1 : // Copyright 2014 Google Inc. All Rights Reserved.
2 : //
3 : // Licensed under the Apache License, Version 2.0 (the "License");
4 : // you may not use this file except in compliance with the License.
5 : // You may obtain a copy of the License at
6 : //
7 : // http://www.apache.org/licenses/LICENSE-2.0
8 : //
9 : // Unless required by applicable law or agreed to in writing, software
10 : // distributed under the License is distributed on an "AS IS" BASIS,
11 : // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 : // See the License for the specific language governing permissions and
13 : // limitations under the License.
14 :
15 : #include "syzygy/testing/metrics.h"
16 :
17 : #include <limits>
18 : #include "base/command_line.h"
19 : #include "base/environment.h"
20 : #include "base/path_service.h"
21 : #include "base/files/file_path.h"
22 : #include "base/files/file_util.h"
23 : #include "base/strings/stringprintf.h"
24 : #include "base/strings/utf_string_conversions.h"
25 : #include "base/synchronization/lock.h"
26 : #include "base/time/time.h"
27 : #include "base/win/scoped_handle.h"
28 : #include "syzygy/version/syzygy_version.h"
29 :
30 : namespace testing {
31 :
32 : namespace {
33 :
34 : // The metrics will be written to a log file with the following extension,
35 : // directly alongside the executable that is emitting metrics. By convention
36 : // all test executables are in the root of the configuration output directory.
37 : static const wchar_t kMetricsFileName[] = L"metrics.csv";
38 :
39 : // The maximum allowable size of the metrics file. This prevents local
40 : // developers metric files from growing monotonically and getting out of
41 : // control. This needs to be amply large for the set of metrics that will be
42 : // emitted in a single run of unittests.
43 : static const size_t kMetricsFileMaxSize = 1 * 1024 * 1024;
44 :
45 : // The environment variable where the metrics are configured.
46 : static const char kMetricsEnvVar[] = "SYZYGY_UNITTEST_METRICS";
47 :
48 : // Switches for controlling metrics.
49 : static const char kEmitToLog[] = "emit-to-log";
50 : static const char kEmitToWaterfall[] = "emit-to-waterfall";
51 :
52 : // The current build configuration.
53 : static const char kBuildConfig[] =
54 : #ifdef _COVERAGE_BUILD
55 : "Coverage";
56 : #else
57 : #ifdef NDEBUG
58 : #ifdef OFFICIAL_BUILD
59 : "Official";
60 : #else
61 : "Release";
62 : #endif // OFFICIAL_BUILD
63 : #else
64 : "Debug";
65 : #endif // NDEBUG
66 : #endif // _COVERAGE_BUILD
67 :
68 : // A global lock used by metrics.
69 E : base::Lock metrics_lock;
70 :
71 : // Global metrics configuration. This is initialized from the environment.
72 : struct MetricsConfiguration {
73 : bool emit_to_log;
74 : bool emit_to_waterfall;
75 : } metrics_config = { false, false };
76 :
77 : // Parses metrics configuration from the environment.
78 E : void ParseMetricsConfiguration() {
79 E : base::Environment* env = base::Environment::Create();
80 E : DCHECK_NE(static_cast<base::Environment*>(nullptr), env);
81 :
82 : // If there's no environment variable then there's nothing to parse.
83 E : std::string s;
84 E : if (!env->GetVar(kMetricsEnvVar, &s))
85 E : return;
86 :
87 : // Build a command line object that we can use for parsing. Prefix the
88 : // environment variable with a dummy executable name.
89 i : std::wstring cmd_line(L"foo.exe ");
90 i : cmd_line.append(base::UTF8ToWide(s));
91 i : base::CommandLine cmd = base::CommandLine::FromString(cmd_line);
92 i : metrics_config.emit_to_log = cmd.HasSwitch(kEmitToLog);
93 i : metrics_config.emit_to_waterfall = cmd.HasSwitch(kEmitToWaterfall);
94 E : }
95 :
96 : // Generates the path to the metrics log.
97 i : base::FilePath GetMetricsLogPath() {
98 i : base::FilePath exe_dir;
99 i : PathService::Get(base::DIR_EXE, &exe_dir);
100 i : return exe_dir.Append(kMetricsFileName);
101 i : }
102 :
103 : // Opens a file for exclusive writing. This tries in a loop but can fail
104 : // permanently. Returns an empty handle on failure.
105 : bool OpenForExclusiveWrite(const base::FilePath& path,
106 i : base::win::ScopedHandle* handle) {
107 i : DCHECK_NE(static_cast<base::win::ScopedHandle*>(nullptr), handle);
108 i : DWORD wait = 1; // In milliseconds.
109 i : for (size_t retries = 0; retries <= 10; ++retries) {
110 : handle->Set(::CreateFile(
111 : path.value().c_str(),
112 : FILE_APPEND_DATA,
113 : 0, // Exclusive access.
114 : nullptr, // No security attributes.
115 : OPEN_ALWAYS, // Create existing file, or create a new one.
116 : FILE_ATTRIBUTE_NORMAL,
117 i : nullptr));
118 i : if (handle->IsValid())
119 i : return true;
120 i : ::Sleep(wait);
121 i : wait++;
122 i : }
123 i : return false;
124 i : }
125 :
126 : // Deletes the specified file if its size exceeds the given
127 : // threshold. Returns true on success, false otherwise.
128 i : bool DeleteFileIfTooLarge(const base::FilePath& path, size_t max_size) {
129 : // Get the file size in a retry loop.
130 i : int64 file_size = 0;
131 i : DWORD wait = 1;
132 i : bool got_size = false;
133 i : for (size_t retries = 0; retries <= 10; ++retries) {
134 i : if (!base::PathExists(path))
135 i : return true;
136 i : if (base::GetFileSize(path, &file_size)) {
137 i : got_size = true;
138 i : break;
139 : }
140 i : ::Sleep(wait);
141 i : wait++;
142 i : }
143 :
144 i : if (!got_size) {
145 i : LOG(ERROR) << "Unable to determine metric file size: " << path.value();
146 i : return false;
147 : }
148 :
149 : // If the file doesn't need to be deleted then return.
150 i : if (file_size <= static_cast<int64>(max_size))
151 i : return true;
152 :
153 : // Try to delete the file in a retry loop.
154 i : wait = 1;
155 i : for (size_t retries = 0; retries <= 10; ++retries) {
156 i : if (base::DeleteFile(path, false)) {
157 i : LOG(INFO) << "Delete large metric file: " << path.value();
158 i : return true;
159 : }
160 i : ::Sleep(wait);
161 i : wait++;
162 i : }
163 :
164 i : LOG(ERROR) << "Unable to delete large metric file: " << path.value();
165 i : return false;
166 i : }
167 :
168 : // Emits a single line of data to the log file. Logs an error if this fails,
169 : // succeeds silently.
170 i : void EmitLineToMetricsFile(const base::StringPiece& line) {
171 i : base::FilePath path = GetMetricsLogPath();
172 i : if (!DeleteFileIfTooLarge(path, kMetricsFileMaxSize))
173 i : return;
174 :
175 i : base::win::ScopedHandle handle;
176 i : if (!OpenForExclusiveWrite(path, &handle)) {
177 i : LOG(ERROR) << "Failed to acquire handle to metrics log.";
178 i : return;
179 : }
180 i : DCHECK(handle.IsValid());
181 i : DWORD bytes_written = 0;
182 : if (!::WriteFile(handle.Get(),
183 : line.data(),
184 : line.size(),
185 : &bytes_written,
186 : nullptr) ||
187 i : bytes_written != line.size()) {
188 i : LOG(ERROR) << "Failed to write line to metrics log.";
189 : }
190 i : }
191 :
192 : struct ScopedInfoLogLevel {
193 E : ScopedInfoLogLevel() : level(0) {
194 E : level = logging::GetMinLogLevel();
195 E : logging::SetMinLogLevel(logging::LOG_INFO);
196 E : }
197 E : ~ScopedInfoLogLevel() {
198 E : logging::SetMinLogLevel(level);
199 E : }
200 : int level;
201 : };
202 :
203 : // Emits a metric that will appear on the waterfall console.
204 : void EmitMetricToWaterfall(const base::StringPiece& name,
205 i : const std::string& value) {
206 i : ScopedInfoLogLevel scoped_info_log_level;
207 i : LOG(INFO) << "Emitting metric to waterfall\n\n"
208 : << "@@@STEP_TEXT@" << name << " = " << value << "@@@\n";
209 i : }
210 :
211 : // Emit a metric in a simple human readable format.
212 : void EmitMetricToLogging(const base::StringPiece& name,
213 E : const std::string& value) {
214 E : ScopedInfoLogLevel scoped_info_log_level;
215 E : LOG(INFO) << "PERF: " << name << "=" << value;
216 E : }
217 :
218 E : void EmitMetric(const base::StringPiece& name, const std::string& value) {
219 E : base::AutoLock auto_lock(metrics_lock);
220 :
221 : // Ensure the metric configuration is parsed from the environment.
222 E : ParseMetricsConfiguration();
223 :
224 : // Build the CSV record.
225 E : base::Time time = base::Time::Now();
226 E : const version::SyzygyVersion& version = version::kSyzygyVersion;
227 : std::string record = base::StringPrintf(
228 : "%lld, " // Time (in microseconds since epoch)
229 : "%d.%d.%d.%d, " // Version
230 : "%s, " // GitHash
231 : "%s, " // Config
232 : "%s, " // MetricName
233 : "%s\n", // MetricValue
234 : time.ToInternalValue(),
235 : version.major(), version.minor(), version.build(), version.patch(),
236 : version.last_change().c_str(),
237 : kBuildConfig,
238 : name.data(),
239 E : value.data());
240 :
241 : // Emit the record to the log.
242 E : if (metrics_config.emit_to_log)
243 i : EmitLineToMetricsFile(record);
244 :
245 : // And also emit it to the log or waterfall.
246 E : if (metrics_config.emit_to_waterfall) {
247 i : EmitMetricToWaterfall(name, value);
248 i : } else {
249 E : EmitMetricToLogging(name, value);
250 : }
251 E : }
252 :
253 : } // namespace
254 :
255 : void EmitMetric(const base::StringPiece& name, int64 value) {
256 : std::string s = base::StringPrintf("%lld", value);
257 : EmitMetric(name, s);
258 : }
259 :
260 E : void EmitMetric(const base::StringPiece& name, uint64 value) {
261 E : std::string s = base::StringPrintf("%llu", value);
262 E : EmitMetric(name, s);
263 E : }
264 :
265 : void EmitMetric(const base::StringPiece& name, double value) {
266 : // Convert the metric value to a string.
267 : std::string s = base::StringPrintf(
268 : "%.*e", std::numeric_limits<double>::digits10, value);
269 : EmitMetric(name, s);
270 : }
271 :
272 : } // namespace testing
|