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/logging.h"
22 : #include "base/files/file_path.h"
23 : #include "base/files/file_util.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_t 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(), indentation_, event_type, process_id,
79 m : thread_id, reinterpret_cast<size_t>(data->function));
80 m : }
81 :
82 m : void PrintModuleEvent(const char* event_type,
83 m : base::Time time,
84 m : DWORD process_id,
85 m : DWORD thread_id,
86 m : const TraceModuleData* data) {
87 m : DCHECK(event_type != NULL);
88 m : DCHECK(data != NULL);
89 m : DCHECK(data->module_base_addr != NULL);
90 m : ::fprintf(file_,
91 m : "[%012lld] %s: process-id=%d; thread-id=%d;"
92 m : " module-name='%ls';"
93 m : " module-addr=0x%08X; module-size=%d\n",
94 m : time.ToInternalValue(), event_type, process_id, thread_id,
95 m : data->module_name,
96 m : reinterpret_cast<size_t>(data->module_base_addr),
97 m : data->module_base_size);
98 m : }
99 :
100 m : void PrintOsVersionInfo(base::Time time,
101 m : const OSVERSIONINFOEX& os_version_info) {
102 m : ::fprintf(file_,
103 m : "[%012lld] %sOsVersionInfo: platform_id=%d; product_type=%d; "
104 m : "version=%d.%d; build=%d; service_pack=%d.%d\n",
105 m : time.ToInternalValue(),
106 m : indentation_,
107 m : os_version_info.dwPlatformId,
108 m : os_version_info.wProductType,
109 m : os_version_info.dwMajorVersion,
110 m : os_version_info.dwMinorVersion,
111 m : os_version_info.dwBuildNumber,
112 m : os_version_info.wServicePackMajor,
113 m : os_version_info.wServicePackMinor);
114 m : }
115 :
116 m : void PrintSystemInfo(base::Time time, const SYSTEM_INFO& system_info) {
117 m : ::fprintf(file_,
118 m : "[%012lld] %sSystemInfo: cpu_arch=%d; cpu_count=%d; "
119 m : "cpu_level=%d; cpu_rev=%d\n",
120 m : time.ToInternalValue(),
121 m : indentation_,
122 m : system_info.wProcessorArchitecture,
123 m : system_info.dwNumberOfProcessors,
124 m : system_info.wProcessorLevel,
125 m : system_info.wProcessorRevision);
126 m : }
127 :
128 m : void PrintMemoryStatus(base::Time time, const MEMORYSTATUSEX& memory_status) {
129 m : ::fprintf(file_,
130 m : "[%012lld] %sMemoryStatus: load=%d; total_phys=%lld; "
131 m : "avail_phys=%lld\n",
132 m : time.ToInternalValue(),
133 m : indentation_,
134 m : memory_status.dwMemoryLoad,
135 m : memory_status.ullTotalPhys,
136 m : memory_status.ullAvailPhys);
137 m : }
138 :
139 m : void PrintClockInfo(base::Time time,
140 m : const trace::common::ClockInfo& clock_info) {
141 m : ::fprintf(file_,
142 m : "[%012lld] %sClockInfo: file_time=0x%08X%08X; "
143 m : "ticks_reference=%llu; tsc_reference=%llu; "
144 m : "ticks_info.frequency=%llu; ticks_info.resolution=%llu; "
145 m : "tsc_info.frequency=%llu; tsc_info.resolution=%llu\n",
146 m : time.ToInternalValue(),
147 m : indentation_,
148 m : clock_info.file_time.dwHighDateTime,
149 m : clock_info.file_time.dwLowDateTime,
150 m : clock_info.ticks_reference,
151 m : clock_info.tsc_reference,
152 m : clock_info.ticks_info.frequency,
153 m : clock_info.ticks_info.resolution,
154 m : clock_info.tsc_info.frequency,
155 m : clock_info.tsc_info.resolution);
156 m : }
157 :
158 m : void PrintEnvironmentString(base::Time time,
159 m : const std::wstring& key,
160 m : const std::wstring& value) {
161 m : ::fprintf(file_,
162 m : "[%012lld] %sEnvironment: %ls=%ls\n",
163 m : time.ToInternalValue(),
164 m : indentation_,
165 m : key.c_str(),
166 m : value.c_str());
167 m : }
168 :
169 m : void PrintEnvironmentStrings(base::Time time,
170 m : const TraceEnvironmentStrings& env_strings) {
171 m : for (size_t i = 0; i < env_strings.size(); ++i)
172 m : PrintEnvironmentString(time, env_strings[i].first, env_strings[i].second);
173 m : }
174 :
175 m : virtual void OnProcessStarted(base::Time time,
176 m : DWORD process_id,
177 m : const TraceSystemInfo* data) {
178 m : ::fprintf(file_,
179 m : "[%012lld] OnProcessStarted: process-id=%d\n",
180 m : time.ToInternalValue(),
181 m : process_id);
182 :
183 m : if (data == NULL)
184 m : return;
185 :
186 m : indentation_ = " ";
187 m : PrintOsVersionInfo(time, data->os_version_info);
188 m : PrintSystemInfo(time, data->system_info);
189 m : PrintMemoryStatus(time, data->memory_status);
190 m : PrintClockInfo(time, data->clock_info);
191 m : PrintEnvironmentStrings(time, data->environment_strings);
192 m : indentation_ = "";
193 m : }
194 :
195 m : virtual void OnProcessEnded(base::Time time, DWORD process_id) {
196 m : ::fprintf(file_,
197 m : "[%012lld] OnProcessEnded: process-id=%d\n",
198 m : time.ToInternalValue(),
199 m : process_id);
200 m : }
201 :
202 m : virtual void OnFunctionEntry(base::Time time,
203 m : DWORD process_id,
204 m : DWORD thread_id,
205 m : const TraceEnterExitEventData* data) {
206 m : PrintFunctionEvent("OnFunctionEntry", time, process_id, thread_id, data);
207 m : }
208 :
209 m : virtual void OnFunctionExit(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 OnBatchFunctionEntry(base::Time time,
217 m : DWORD process_id,
218 m : DWORD thread_id,
219 m : const TraceBatchEnterData* data) {
220 m : DCHECK(data != NULL);
221 m : DCHECK_EQ(thread_id, data->thread_id);
222 m : ::fprintf(file_,
223 m : "[%012lld] OnBatchFunctionEntry: " \
224 m : "process-id=%d; thread-id=%d; num-calls=%d\n",
225 m : time.ToInternalValue(),
226 m : process_id,
227 m : thread_id,
228 m : data->num_calls);
229 :
230 : // Explode the batch event into individual function entry events.
231 m : TraceEnterExitEventData new_data = {};
232 m : indentation_ = " ";
233 m : for (size_t i = 0; i < data->num_calls; ++i) {
234 m : new_data.function = data->calls[i].function;
235 m : OnFunctionEntry(time, process_id, thread_id, &new_data);
236 m : }
237 m : indentation_ = "";
238 m : }
239 :
240 m : virtual void OnProcessAttach(base::Time time,
241 m : DWORD process_id,
242 m : DWORD thread_id,
243 m : const TraceModuleData* data) {
244 m : PrintModuleEvent("OnProcessAttach", time, process_id, thread_id, data);
245 m : }
246 :
247 m : virtual void OnProcessDetach(base::Time time,
248 m : DWORD process_id,
249 m : DWORD thread_id,
250 m : const TraceModuleData* data) {
251 m : PrintModuleEvent("OnProcessDetach", time, process_id, thread_id, data);
252 m : }
253 :
254 m : virtual void OnThreadAttach(base::Time time,
255 m : DWORD process_id,
256 m : DWORD thread_id,
257 m : const TraceModuleData* data) {
258 m : PrintModuleEvent("OnThreadAttach", time, process_id, thread_id, data);
259 m : }
260 :
261 m : virtual void OnThreadDetach(base::Time time,
262 m : DWORD process_id,
263 m : DWORD thread_id,
264 m : const TraceModuleData* data) {
265 m : PrintModuleEvent("OnThreadDetach", time, process_id, thread_id, data);
266 m : }
267 :
268 m : virtual void OnInvocationBatch(base::Time time,
269 m : DWORD process_id,
270 m : DWORD thread_id,
271 m : size_t num_invocations,
272 m : const TraceBatchInvocationInfo* data) {
273 m : DCHECK(data != NULL);
274 m : ::fprintf(file_,
275 m : "[%012lld] OnInvocationBatch: process-id=%d; thread-id=%d;\n",
276 m : time.ToInternalValue(),
277 m : process_id,
278 m : thread_id);
279 m : for (size_t i = 0; i < num_invocations; ++i) {
280 m : const InvocationInfo& invocation = data->invocations[i];
281 :
282 m : if ((invocation.flags & kCallerIsSymbol) != 0) {
283 m : ::fprintf(file_,
284 m : " caller_sym=0x%X, offs=%d;",
285 m : invocation.caller_symbol_id,
286 m : invocation.caller_offset);
287 m : } else {
288 m : ::fprintf(file_, " caller=0x%08X;",
289 m : reinterpret_cast<size_t>(invocation.caller));
290 m : }
291 :
292 m : if ((invocation.flags & kFunctionIsSymbol) != 0) {
293 m : ::fprintf(file_, " function_sym=0x%X;", invocation.function_symbol_id);
294 m : } else {
295 m : ::fprintf(file_, " function=0x%08X;",
296 m : reinterpret_cast<size_t>(invocation.function));
297 m : }
298 :
299 m : ::fprintf(file_,
300 m : " num-calls=%d;\n"
301 m : " cycles-min=%lld; cycles-max=%lld; cycles-sum=%lld\n",
302 m : data->invocations[i].num_calls,
303 m : data->invocations[i].cycles_min,
304 m : data->invocations[i].cycles_max,
305 m : data->invocations[i].cycles_sum);
306 m : }
307 m : }
308 :
309 m : virtual void OnThreadName(base::Time time,
310 m : DWORD process_id,
311 m : DWORD thread_id,
312 m : const base::StringPiece& thread_name) override {
313 m : ::fprintf(file_, "[%012lld] OnThreadName: process-id=%d; thread-id=%d;\n"
314 m : " name=%s\n",
315 m : time.ToInternalValue(), process_id, thread_id,
316 m : thread_name.as_string().c_str());
317 m : }
318 :
319 m : virtual void OnIndexedFrequency(
320 m : base::Time time,
321 m : DWORD process_id,
322 m : DWORD thread_id,
323 m : const TraceIndexedFrequencyData* data) override {
324 m : DCHECK(data != NULL);
325 m : ::fprintf(file_,
326 m : "[%012lld] OnIndexedFrequency: process-id=%d; thread-id=%d;\n"
327 m : " module-base-addr=0x%08X; module-base-size=%d\n"
328 m : " module-checksum=0x%08X; module-time-date-stamp=0x%08X\n"
329 m : " frequency-size=%d; num_columns=%d; num-entries=%d;\n"
330 m : " data-type=%s;\n",
331 m : time.ToInternalValue(), process_id, thread_id,
332 m : reinterpret_cast<size_t>(data->module_base_addr),
333 m : data->module_base_size, data->module_checksum,
334 m : data->module_time_date_stamp, data->frequency_size,
335 m : data->num_columns, data->num_entries,
336 m : GetIndexedDataTypeStr(data->data_type));
337 m : }
338 :
339 m : virtual void OnDynamicSymbol(DWORD process_id,
340 m : uint32_t symbol_id,
341 m : const base::StringPiece& symbol_name) override {
342 m : ::fprintf(file_, "OnDynamicSymbol: process-id=%d;\n"
343 m : " symbol_id=%d\n"
344 m : " symbol_name=%s\n",
345 m : process_id, symbol_id, symbol_name.as_string().c_str());
346 m : }
347 :
348 m : virtual void OnSampleData(base::Time time,
349 m : DWORD process_id,
350 m : const TraceSampleData* data) override {
351 m : DCHECK(data != NULL);
352 :
353 m : uint64_t samples = 0;
354 m : for (uint32_t i = 0; i < data->bucket_count; ++i)
355 m : samples += data->buckets[i];
356 :
357 m : ::fprintf(file_,
358 m : "[%012lld] OnSampleData: process-id=%d;\n"
359 m : " module-base-addr=0x%08X;\n"
360 m : " module-size=%d; module-checksum=0x%08X;\n"
361 m : " module-time-date-stamp=0x%08X; bucket-size=%d;\n"
362 m : " bucket-start=0x%08x; bucket-count=%d;\n"
363 m : " sampling-start-time=0x%016llx;\n"
364 m : " sampling-end-time=0x%016llx; sampling-interval=0x%016llx;\n"
365 m : " samples=%lld\n",
366 m : time.ToInternalValue(), process_id,
367 m : reinterpret_cast<size_t>(data->module_base_addr),
368 m : data->module_size, data->module_checksum,
369 m : data->module_time_date_stamp, data->bucket_size,
370 m : reinterpret_cast<size_t>(data->bucket_start), data->bucket_count,
371 m : data->sampling_start_time, data->sampling_end_time,
372 m : data->sampling_interval, samples);
373 m : }
374 :
375 : // Issued for detailed function call records.
376 m : virtual void OnFunctionNameTableEntry(
377 m : base::Time time,
378 m : DWORD process_id,
379 m : const TraceFunctionNameTableEntry* data) override {
380 m : DCHECK_NE(static_cast<TraceFunctionNameTableEntry*>(nullptr), data);
381 m : ::fprintf(file_,
382 m : "[%012lld] OnFunctionNameTableEntry: process-id=%d;\n"
383 m : " function-id=%d; name='%.*s'\n",
384 m : time.ToInternalValue(),
385 m : process_id,
386 m : data->function_id,
387 m : data->name_length,
388 m : data->name);
389 m : ProcessIdFunctionIdPair key(process_id, data->function_id);
390 m : std::string value(data->name, data->name_length);
391 m : function_names_.insert(std::make_pair(key, value));
392 m : }
393 :
394 : // Issued for detailed function call records.
395 m : virtual void OnStackTrace(base::Time time,
396 m : DWORD process_id,
397 m : const TraceStackTrace* data) override {
398 m : DCHECK_NE(static_cast<TraceStackTrace*>(nullptr), data);
399 m : ::fprintf(file_,
400 m : "[%012lld] OnStackTrace: process-id=%d;\n"
401 m : " stack-trace-id=0x%08X; num_frames=%d\n",
402 m : time.ToInternalValue(),
403 m : process_id,
404 m : data->stack_trace_id,
405 m : data->num_frames);
406 m : }
407 :
408 : // Issued for detailed function call records.
409 m : virtual void OnDetailedFunctionCall(
410 m : base::Time time,
411 m : DWORD process_id,
412 m : DWORD thread_id,
413 m : const TraceDetailedFunctionCall* data) override {
414 m : DCHECK_NE(static_cast<TraceDetailedFunctionCall*>(nullptr), data);
415 m : ::fprintf(file_,
416 m : "[%012lld] OnDetailedFunctionCall: process-id=%d;\n"
417 m : " thread-id=%d; timestamp=0x%016llX;\n"
418 m : " function-id=%d; stack-trace-id=0x%08X\n",
419 m : time.ToInternalValue(),
420 m : process_id,
421 m : thread_id,
422 m : data->timestamp,
423 m : data->function_id,
424 m : data->stack_trace_id);
425 :
426 : // Output the function name if we've seen it.
427 m : auto it = function_names_.find(
428 m : ProcessIdFunctionIdPair(process_id, data->function_id));
429 m : if (it != function_names_.end())
430 m : ::fprintf(file_, " function_name='%s';\n", it->second.c_str());
431 :
432 : // Output the arguments summary info.
433 m : const uint32_t* argument_lengths =
434 m : reinterpret_cast<const uint32_t*>(data->argument_data);
435 m : uint32_t argument_count = 0;
436 m : if (data->argument_data_size > 0) {
437 m : argument_count = *argument_lengths;
438 m : argument_lengths++;
439 m : }
440 m : ::fprintf(file_, " argument_data_size=%d; argument_count=%d\n",
441 m : data->argument_data_size, argument_count);
442 :
443 m : const uint8_t* argument_data =
444 m : reinterpret_cast<const uint8_t*>(argument_lengths + argument_count);
445 m : const uint8_t* argument_data_end =
446 m : data->argument_data + data->argument_data_size;
447 m : for (size_t i = 0; i < argument_count; ++i) {
448 m : ::fprintf(file_, " argument[%d]:", i);
449 m : for (size_t j = 0; j < argument_lengths[i]; ++j) {
450 m : if (argument_data < argument_data_end) {
451 m : ::fprintf(file_, " %02X", (int)(*argument_data));
452 m : ++argument_data;
453 m : } else {
454 m : ::fprintf(file_, " <insufficient argument data>\n");
455 m : return;
456 m : }
457 m : }
458 m : ::fprintf(file_, ";\n");
459 m : }
460 m : }
461 :
462 m : virtual void OnComment(
463 m : base::Time time,
464 m : DWORD process_id,
465 m : const TraceComment* data) {
466 m : DCHECK_NE(static_cast<TraceComment*>(nullptr), data);
467 m : ::fprintf(file_,
468 m : "[%012lld] OnComment: process-id=%d;\n"
469 m : " comment=\"%.*s\"\n",
470 m : time.ToInternalValue(),
471 m : process_id,
472 m : data->comment_size,
473 m : data->comment);
474 m : }
475 :
476 m : void OnProcessHeap(base::Time time,
477 m : DWORD process_id,
478 m : const TraceProcessHeap* data) override {
479 m : DCHECK_NE(static_cast<TraceProcessHeap*>(nullptr), data);
480 m : ::fprintf(file_,
481 m : "[%012lld] OnProcessHeap: process-id=%d; process-heap=%08X\n",
482 m : time.ToInternalValue(), process_id, data->process_heap);
483 m : }
484 :
485 m : private:
486 m : FILE* file_;
487 m : const char* indentation_;
488 :
489 : // Stores function names per process. Used for symbolizing detailed
490 : // function call data. These are keyed be process ID and function ID.
491 m : typedef std::pair<DWORD, size_t> ProcessIdFunctionIdPair;
492 m : typedef std::map<ProcessIdFunctionIdPair, std::string> FunctionNameMap;
493 m : FunctionNameMap function_names_;
494 :
495 m : DISALLOW_COPY_AND_ASSIGN(TraceFileDumper);
496 m : };
497 :
498 m : bool DumpTraceFiles(FILE* out_file,
499 m : const std::vector<base::FilePath>& file_paths) {
500 m : Parser parser;
501 m : TraceFileDumper dumper(out_file);
502 m : if (!parser.Init(&dumper))
503 m : return false;
504 :
505 m : std::vector<base::FilePath>::const_iterator iter = file_paths.begin();
506 m : for (; iter != file_paths.end(); ++iter) {
507 m : if (!parser.OpenTraceFile(*iter))
508 m : return false;
509 m : }
510 :
511 m : return parser.Consume() && !parser.error_occurred();
512 m : }
513 :
514 m : } // namespace
515 :
516 m : int main(int argc, const char** argv) {
517 m : base::AtExitManager at_exit_manager;
518 m : base::CommandLine::Init(argc, argv);
519 :
520 m : logging::LoggingSettings settings;
521 m : settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
522 m : settings.lock_log = logging::DONT_LOCK_LOG_FILE;
523 m : settings.delete_old = logging::APPEND_TO_OLD_LOG_FILE;
524 m : if (!logging::InitLogging(settings))
525 m : return 1;
526 :
527 m : base::CommandLine* cmd_line = base::CommandLine::ForCurrentProcess();
528 m : CHECK(cmd_line != NULL);
529 :
530 m : std::vector<base::FilePath> trace_file_paths;
531 m : for (size_t i = 0; i < cmd_line->GetArgs().size(); ++i)
532 m : trace_file_paths.push_back(base::FilePath(cmd_line->GetArgs()[i]));
533 :
534 m : if (trace_file_paths.empty()) {
535 m : LOG(ERROR) << "No trace file paths specified.";
536 :
537 m : ::fprintf(stderr,
538 m : "Usage: %ls [--out=OUTPUT] TRACE_FILE(s)...\n\n",
539 m : cmd_line->GetProgram().value().c_str());
540 m : return 1;
541 m : }
542 :
543 m : base::FilePath out_file_path(cmd_line->GetSwitchValuePath("out"));
544 m : base::ScopedFILE out_file;
545 m : if (!out_file_path.empty()) {
546 m : out_file.reset(base::OpenFile(out_file_path, "w"));
547 m : if (out_file.get() == NULL) {
548 m : LOG(ERROR) << "Failed to open output file: '" << out_file_path.value()
549 m : << "'.";
550 m : return 1;
551 m : }
552 m : }
553 :
554 m : if (!DumpTraceFiles(out_file.get(), trace_file_paths)) {
555 m : LOG(ERROR) << "Failed to dump trace files.";
556 m : return 1;
557 m : }
558 :
559 m : return 0;
560 m : }
|