1 : // Copyright 2012 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 <windows.h> // NOLINT
16 : #include <stdio.h>
17 : #include <vector>
18 :
19 : #include "base/at_exit.h"
20 : #include "base/command_line.h"
21 : #include "base/file_util.h"
22 : #include "base/logging.h"
23 : #include "base/files/file_path.h"
24 : #include "base/threading/simple_thread.h"
25 : #include "base/win/event_trace_consumer.h"
26 : #include "base/win/event_trace_controller.h"
27 : #include "base/win/scoped_handle.h"
28 : #include "base/win/windows_version.h"
29 : #include "syzygy/common/indexed_frequency_data.h"
30 : #include "syzygy/trace/parse/parser.h"
31 : #include "syzygy/trace/service/service.h"
32 :
33 m : namespace {
34 :
35 m : using trace::parser::Parser;
36 m : using trace::parser::ParseEventHandler;
37 m : using trace::parser::ModuleInformation;
38 :
39 m : const char* GetIndexedDataTypeStr(uint8 data_type) {
40 m : const char* ret = NULL;
41 m : switch (data_type) {
42 m : case common::IndexedFrequencyData::BASIC_BLOCK_ENTRY:
43 m : ret = "basic-block entry counts";
44 m : break;
45 m : case common::IndexedFrequencyData::COVERAGE:
46 m : ret = "coverage entry counts";
47 m : break;
48 m : case common::IndexedFrequencyData::BRANCH:
49 m : ret = "branch entry counts";
50 m : break;
51 m : case common::IndexedFrequencyData::JUMP_TABLE:
52 m : ret = "jump-table case counts";
53 m : break;
54 m : default:
55 m : NOTREACHED();
56 m : break;
57 m : }
58 m : return ret;
59 m : }
60 :
61 m : class TraceFileDumper : public ParseEventHandler {
62 m : public:
63 m : explicit TraceFileDumper(FILE* file)
64 m : : file_(file ? file : stdout),
65 m : indentation_("") {
66 m : }
67 :
68 m : void PrintFunctionEvent(const char* event_type,
69 m : base::Time time,
70 m : DWORD process_id,
71 m : DWORD thread_id,
72 m : const TraceEnterExitEventData* data) {
73 m : DCHECK(event_type != NULL);
74 m : DCHECK(data != NULL);
75 m : DCHECK(data->function != NULL);
76 m : ::fprintf(file_,
77 m : "[%012lld] %s%s: process-id=%d; thread-id=%d; address=0x%08X\n",
78 m : time.ToInternalValue(),
79 m : indentation_,
80 m : event_type,
81 m : process_id,
82 m : thread_id,
83 m : data->function);
84 m : }
85 :
86 m : void PrintModuleEvent(const char* event_type,
87 m : base::Time time,
88 m : DWORD process_id,
89 m : DWORD thread_id,
90 m : const TraceModuleData* data) {
91 m : DCHECK(event_type != NULL);
92 m : DCHECK(data != NULL);
93 m : DCHECK(data->module_base_addr != NULL);
94 m : ::fprintf(file_,
95 m : "[%012lld] %s: process-id=%d; thread-id=%d;"
96 m : " module-name='%ls';"
97 m : " module-addr=0x%08X; module-size=%d\n",
98 m : time.ToInternalValue(),
99 m : event_type,
100 m : process_id,
101 m : thread_id,
102 m : data->module_name,
103 m : data->module_base_addr,
104 m : data->module_base_size);
105 m : }
106 :
107 m : void PrintOsVersionInfo(base::Time time,
108 m : const OSVERSIONINFOEX& os_version_info) {
109 m : ::fprintf(file_,
110 m : "[%012lld] %sOsVersionInfo: platform_id=%d; product_type=%d; "
111 m : "version=%d.%d; build=%d; service_pack=%d.%d\n",
112 m : time.ToInternalValue(),
113 m : indentation_,
114 m : os_version_info.dwPlatformId,
115 m : os_version_info.wProductType,
116 m : os_version_info.dwMajorVersion,
117 m : os_version_info.dwMinorVersion,
118 m : os_version_info.dwBuildNumber,
119 m : os_version_info.wServicePackMajor,
120 m : os_version_info.wServicePackMinor);
121 m : }
122 :
123 m : void PrintSystemInfo(base::Time time, const SYSTEM_INFO& system_info) {
124 m : ::fprintf(file_,
125 m : "[%012lld] %sSystemInfo: cpu_arch=%d; cpu_count=%d; "
126 m : "cpu_level=%d; cpu_rev=%d\n",
127 m : time.ToInternalValue(),
128 m : indentation_,
129 m : system_info.wProcessorArchitecture,
130 m : system_info.dwNumberOfProcessors,
131 m : system_info.wProcessorLevel,
132 m : system_info.wProcessorRevision);
133 m : }
134 :
135 m : void PrintMemoryStatus(base::Time time, const MEMORYSTATUSEX& memory_status) {
136 m : ::fprintf(file_,
137 m : "[%012lld] %sMemoryStatus: load=%d; total_phys=%lld; "
138 m : "avail_phys=%lld\n",
139 m : time.ToInternalValue(),
140 m : indentation_,
141 m : memory_status.dwMemoryLoad,
142 m : memory_status.ullTotalPhys,
143 m : memory_status.ullAvailPhys);
144 m : }
145 :
146 m : void PrintClockInfo(base::Time time,
147 m : const trace::common::ClockInfo& clock_info) {
148 m : ::fprintf(file_,
149 m : "[%012lld] %sClockInfo: file_time=0x%08X%08X; "
150 m : "ticks_reference=%llu; tsc_reference=%llu; "
151 m : "ticks_info.frequency=%llu; ticks_info.resolution=%llu; "
152 m : "tsc_info.frequency=%llu; tsc_info.resolution=%llu\n",
153 m : time.ToInternalValue(),
154 m : indentation_,
155 m : clock_info.file_time.dwHighDateTime,
156 m : clock_info.file_time.dwLowDateTime,
157 m : clock_info.ticks_reference,
158 m : clock_info.tsc_reference,
159 m : clock_info.ticks_info.frequency,
160 m : clock_info.ticks_info.resolution,
161 m : clock_info.tsc_info.frequency,
162 m : clock_info.tsc_info.resolution);
163 m : }
164 :
165 m : void PrintEnvironmentString(base::Time time,
166 m : const std::wstring& key,
167 m : const std::wstring& value) {
168 m : ::fprintf(file_,
169 m : "[%012lld] %sEnvironment: %ls=%ls\n",
170 m : time.ToInternalValue(),
171 m : indentation_,
172 m : key.c_str(),
173 m : value.c_str());
174 m : }
175 :
176 m : void PrintEnvironmentStrings(base::Time time,
177 m : const TraceEnvironmentStrings& env_strings) {
178 m : for (size_t i = 0; i < env_strings.size(); ++i)
179 m : PrintEnvironmentString(time, env_strings[i].first, env_strings[i].second);
180 m : }
181 :
182 m : virtual void OnProcessStarted(base::Time time,
183 m : DWORD process_id,
184 m : const TraceSystemInfo* data) {
185 m : ::fprintf(file_,
186 m : "[%012lld] OnProcessStarted: process-id=%d\n",
187 m : time.ToInternalValue(),
188 m : process_id);
189 :
190 m : if (data == NULL)
191 m : return;
192 :
193 m : indentation_ = " ";
194 m : PrintOsVersionInfo(time, data->os_version_info);
195 m : PrintSystemInfo(time, data->system_info);
196 m : PrintMemoryStatus(time, data->memory_status);
197 m : PrintClockInfo(time, data->clock_info);
198 m : PrintEnvironmentStrings(time, data->environment_strings);
199 m : indentation_ = "";
200 m : }
201 :
202 m : virtual void OnProcessEnded(base::Time time, DWORD process_id) {
203 m : ::fprintf(file_,
204 m : "[%012lld] OnProcessEnded: process-id=%d\n",
205 m : time.ToInternalValue(),
206 m : process_id);
207 m : }
208 :
209 m : virtual void OnFunctionEntry(base::Time time,
210 m : DWORD process_id,
211 m : DWORD thread_id,
212 m : const TraceEnterExitEventData* data) {
213 m : PrintFunctionEvent("OnFunctionEntry", time, process_id, thread_id, data);
214 m : }
215 :
216 m : virtual void OnFunctionExit(base::Time time,
217 m : DWORD process_id,
218 m : DWORD thread_id,
219 m : const TraceEnterExitEventData* data) {
220 m : PrintFunctionEvent("OnFunctionEntry", time, process_id, thread_id, data);
221 m : }
222 :
223 m : virtual void OnBatchFunctionEntry(base::Time time,
224 m : DWORD process_id,
225 m : DWORD thread_id,
226 m : const TraceBatchEnterData* data) {
227 m : DCHECK(data != NULL);
228 m : DCHECK_EQ(thread_id, data->thread_id);
229 m : ::fprintf(file_,
230 m : "[%012lld] OnBatchFunctionEntry: " \
231 m : "process-id=%d; thread-id=%d; num-calls=%d\n",
232 m : time.ToInternalValue(),
233 m : process_id,
234 m : thread_id,
235 m : data->num_calls);
236 :
237 : // Explode the batch event into individual function entry events.
238 m : TraceEnterExitEventData new_data = {};
239 m : indentation_ = " ";
240 m : for (size_t i = 0; i < data->num_calls; ++i) {
241 m : new_data.function = data->calls[i].function;
242 m : OnFunctionEntry(time, process_id, thread_id, &new_data);
243 m : }
244 m : indentation_ = "";
245 m : }
246 :
247 m : virtual void OnProcessAttach(base::Time time,
248 m : DWORD process_id,
249 m : DWORD thread_id,
250 m : const TraceModuleData* data) {
251 m : PrintModuleEvent("OnProcessAttach", time, process_id, thread_id, data);
252 m : }
253 :
254 m : virtual void OnProcessDetach(base::Time time,
255 m : DWORD process_id,
256 m : DWORD thread_id,
257 m : const TraceModuleData* data) {
258 m : PrintModuleEvent("OnProcessDetach", time, process_id, thread_id, data);
259 m : }
260 :
261 m : virtual void OnThreadAttach(base::Time time,
262 m : DWORD process_id,
263 m : DWORD thread_id,
264 m : const TraceModuleData* data) {
265 m : PrintModuleEvent("OnThreadAttach", time, process_id, thread_id, data);
266 m : }
267 :
268 m : virtual void OnThreadDetach(base::Time time,
269 m : DWORD process_id,
270 m : DWORD thread_id,
271 m : const TraceModuleData* data) {
272 m : PrintModuleEvent("OnThreadDetach", time, process_id, thread_id, data);
273 m : }
274 :
275 m : virtual void OnInvocationBatch(base::Time time,
276 m : DWORD process_id,
277 m : DWORD thread_id,
278 m : size_t num_invocations,
279 m : const TraceBatchInvocationInfo* data) {
280 m : DCHECK(data != NULL);
281 m : ::fprintf(file_,
282 m : "OnInvocationBatch: process-id=%d; thread-id=%d;\n",
283 m : process_id,
284 m : thread_id);
285 m : for (size_t i = 0; i < num_invocations; ++i) {
286 m : const InvocationInfo& invocation = data->invocations[i];
287 :
288 m : if ((invocation.flags & kCallerIsSymbol) != 0) {
289 m : ::fprintf(file_,
290 m : " caller_sym=0x%X, offs=%d;",
291 m : invocation.caller_symbol_id,
292 m : invocation.caller_offset);
293 m : } else {
294 m : ::fprintf(file_,
295 m : " caller=0x%08X;",
296 m : invocation.caller);
297 m : }
298 :
299 m : if ((invocation.flags & kFunctionIsSymbol) != 0) {
300 m : ::fprintf(file_, " function_sym=0x%X;", invocation.function_symbol_id);
301 m : } else {
302 m : ::fprintf(file_, " function=0x%08X;", invocation.function);
303 m : }
304 :
305 m : ::fprintf(file_,
306 m : " num-calls=%d;\n"
307 m : " cycles-min=%lld; cycles-max=%lld; cycles-sum=%lld\n",
308 m : data->invocations[i].num_calls,
309 m : data->invocations[i].cycles_min,
310 m : data->invocations[i].cycles_max,
311 m : data->invocations[i].cycles_sum);
312 m : }
313 m : }
314 :
315 m : virtual void OnThreadName(base::Time time,
316 m : DWORD process_id,
317 m : DWORD thread_id,
318 m : const base::StringPiece& thread_name) OVERRIDE {
319 m : ::fprintf(file_, "OnThreadName: process-id=%d; thread-id=%d;\n"
320 m : " name=%s\n",
321 m : process_id, thread_id, thread_name.as_string().c_str());
322 m : }
323 :
324 m : virtual void OnIndexedFrequency(
325 m : base::Time time,
326 m : DWORD process_id,
327 m : DWORD thread_id,
328 m : const TraceIndexedFrequencyData* data) OVERRIDE {
329 m : DCHECK(data != NULL);
330 m : ::fprintf(file_,
331 m : "OnIndexedFrequency: process-id=%d; thread-id=%d;\n"
332 m : " module-base-addr=0x%08X; module-base-size=%d\n"
333 m : " module-checksum=0x%08X; module-time-date-stamp=0x%08X\n"
334 m : " frequency-size=%d; num_columns=%d; num-entries=%d;\n"
335 m : " data-type=%s;\n",
336 m : process_id,
337 m : thread_id,
338 m : data->module_base_addr,
339 m : data->module_base_size,
340 m : data->module_checksum,
341 m : data->module_time_date_stamp,
342 m : data->frequency_size,
343 m : data->num_columns,
344 m : data->num_entries,
345 m : GetIndexedDataTypeStr(data->data_type));
346 m : }
347 :
348 m : virtual void OnDynamicSymbol(DWORD process_id,
349 m : uint32 symbol_id,
350 m : const base::StringPiece& symbol_name) OVERRIDE {
351 m : ::fprintf(file_, "OnDynamicSymbol: process-id=%d;\n"
352 m : " symbol_id=%d\n"
353 m : " symbol_name=%s\n",
354 m : process_id, symbol_id, symbol_name.as_string().c_str());
355 m : }
356 :
357 m : virtual void OnSampleData(base::Time Time,
358 m : DWORD process_id,
359 m : const TraceSampleData* data) OVERRIDE {
360 m : DCHECK(data != NULL);
361 :
362 m : uint64 samples = 0;
363 m : for (uint32 i = 0; i < data->bucket_count; ++i)
364 m : samples += data->buckets[i];
365 :
366 m : ::fprintf(file_,
367 m : "OnSampleData: process-id=%d; module-base-addr=0x%08X;\n"
368 m : " module-size=%d; module-checksum=0x%08X;\n"
369 m : " module-time-date-stamp=0x%08X; bucket-size=%d;\n"
370 m : " bucket-start=0x%08x; bucket-count=%d;\n"
371 m : " sampling-start-time=0x%016llx;\n"
372 m : " sampling-end-time=0x%016llx; sampling-interval=0x%016llx;\n"
373 m : " samples=%lld\n",
374 m : process_id,
375 m : data->module_base_addr,
376 m : data->module_size,
377 m : data->module_checksum,
378 m : data->module_time_date_stamp,
379 m : data->bucket_size,
380 m : data->bucket_start,
381 m : data->bucket_count,
382 m : data->sampling_start_time,
383 m : data->sampling_end_time,
384 m : data->sampling_interval,
385 m : samples);
386 m : }
387 :
388 m : private:
389 m : FILE* file_;
390 m : const char* indentation_;
391 :
392 m : DISALLOW_COPY_AND_ASSIGN(TraceFileDumper);
393 m : };
394 :
395 m : bool DumpTraceFiles(FILE* out_file,
396 m : const std::vector<base::FilePath>& file_paths) {
397 m : Parser parser;
398 m : TraceFileDumper dumper(out_file);
399 m : if (!parser.Init(&dumper))
400 m : return false;
401 :
402 m : std::vector<base::FilePath>::const_iterator iter = file_paths.begin();
403 m : for (; iter != file_paths.end(); ++iter) {
404 m : if (!parser.OpenTraceFile(*iter))
405 m : return false;
406 m : }
407 :
408 m : return parser.Consume() && !parser.error_occurred();
409 m : }
410 :
411 m : } // namespace
412 :
413 m : int main(int argc, const char** argv) {
414 m : base::AtExitManager at_exit_manager;
415 m : CommandLine::Init(argc, argv);
416 :
417 m : if (!logging::InitLogging(
418 m : L"",
419 m : logging::LOG_ONLY_TO_SYSTEM_DEBUG_LOG,
420 m : logging::DONT_LOCK_LOG_FILE,
421 m : logging::APPEND_TO_OLD_LOG_FILE,
422 m : logging::ENABLE_DCHECK_FOR_NON_OFFICIAL_RELEASE_BUILDS)) {
423 m : return 1;
424 m : }
425 :
426 m : CommandLine* cmd_line = CommandLine::ForCurrentProcess();
427 m : CHECK(cmd_line != NULL);
428 :
429 m : std::vector<base::FilePath> trace_file_paths;
430 m : for (size_t i = 0; i < cmd_line->GetArgs().size(); ++i)
431 m : trace_file_paths.push_back(base::FilePath(cmd_line->GetArgs()[i]));
432 :
433 m : if (trace_file_paths.empty()) {
434 m : LOG(ERROR) << "No trace file paths specified.";
435 :
436 m : ::fprintf(stderr,
437 m : "Usage: %ls [--out=OUTPUT] TRACE_FILE(s)...\n\n",
438 m : cmd_line->GetProgram().value().c_str());
439 m : return 1;
440 m : }
441 :
442 m : base::FilePath out_file_path(cmd_line->GetSwitchValuePath("out"));
443 m : file_util::ScopedFILE out_file;
444 m : if (!out_file_path.empty()) {
445 m : out_file.reset(file_util::OpenFile(out_file_path, "w"));
446 m : if (out_file.get() == NULL) {
447 m : LOG(ERROR) << "Failed to open output file: '" << out_file_path.value()
448 m : << "'.";
449 m : return 1;
450 m : }
451 m : }
452 :
453 m : if (!DumpTraceFiles(out_file.get(), trace_file_paths)) {
454 m : LOG(ERROR) << "Failed to dump trace files.";
455 m : return 1;
456 m : }
457 :
458 m : return 0;
459 m : }
|