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 : "[%012lld] OnInvocationBatch: process-id=%d; thread-id=%d;\n",
283 m : time.ToInternalValue(),
284 m : process_id,
285 m : thread_id);
286 m : for (size_t i = 0; i < num_invocations; ++i) {
287 m : const InvocationInfo& invocation = data->invocations[i];
288 :
289 m : if ((invocation.flags & kCallerIsSymbol) != 0) {
290 m : ::fprintf(file_,
291 m : " caller_sym=0x%X, offs=%d;",
292 m : invocation.caller_symbol_id,
293 m : invocation.caller_offset);
294 m : } else {
295 m : ::fprintf(file_,
296 m : " caller=0x%08X;",
297 m : invocation.caller);
298 m : }
299 :
300 m : if ((invocation.flags & kFunctionIsSymbol) != 0) {
301 m : ::fprintf(file_, " function_sym=0x%X;", invocation.function_symbol_id);
302 m : } else {
303 m : ::fprintf(file_, " function=0x%08X;", invocation.function);
304 m : }
305 :
306 m : ::fprintf(file_,
307 m : " num-calls=%d;\n"
308 m : " cycles-min=%lld; cycles-max=%lld; cycles-sum=%lld\n",
309 m : data->invocations[i].num_calls,
310 m : data->invocations[i].cycles_min,
311 m : data->invocations[i].cycles_max,
312 m : data->invocations[i].cycles_sum);
313 m : }
314 m : }
315 :
316 m : virtual void OnThreadName(base::Time time,
317 m : DWORD process_id,
318 m : DWORD thread_id,
319 m : const base::StringPiece& thread_name) OVERRIDE {
320 m : ::fprintf(file_, "[%012lld] OnThreadName: process-id=%d; thread-id=%d;\n"
321 m : " name=%s\n",
322 m : time.ToInternalValue(), process_id, thread_id,
323 m : thread_name.as_string().c_str());
324 m : }
325 :
326 m : virtual void OnIndexedFrequency(
327 m : base::Time time,
328 m : DWORD process_id,
329 m : DWORD thread_id,
330 m : const TraceIndexedFrequencyData* data) OVERRIDE {
331 m : DCHECK(data != NULL);
332 m : ::fprintf(file_,
333 m : "[%012lld] OnIndexedFrequency: process-id=%d; thread-id=%d;\n"
334 m : " module-base-addr=0x%08X; module-base-size=%d\n"
335 m : " module-checksum=0x%08X; module-time-date-stamp=0x%08X\n"
336 m : " frequency-size=%d; num_columns=%d; num-entries=%d;\n"
337 m : " data-type=%s;\n",
338 m : time.ToInternalValue(),
339 m : process_id,
340 m : thread_id,
341 m : data->module_base_addr,
342 m : data->module_base_size,
343 m : data->module_checksum,
344 m : data->module_time_date_stamp,
345 m : data->frequency_size,
346 m : data->num_columns,
347 m : data->num_entries,
348 m : GetIndexedDataTypeStr(data->data_type));
349 m : }
350 :
351 m : virtual void OnDynamicSymbol(DWORD process_id,
352 m : uint32 symbol_id,
353 m : const base::StringPiece& symbol_name) OVERRIDE {
354 m : ::fprintf(file_, "OnDynamicSymbol: process-id=%d;\n"
355 m : " symbol_id=%d\n"
356 m : " symbol_name=%s\n",
357 m : process_id, symbol_id, symbol_name.as_string().c_str());
358 m : }
359 :
360 m : virtual void OnSampleData(base::Time time,
361 m : DWORD process_id,
362 m : const TraceSampleData* data) OVERRIDE {
363 m : DCHECK(data != NULL);
364 :
365 m : uint64 samples = 0;
366 m : for (uint32 i = 0; i < data->bucket_count; ++i)
367 m : samples += data->buckets[i];
368 :
369 m : ::fprintf(file_,
370 m : "[%012lld] OnSampleData: process-id=%d;\n"
371 m : " module-base-addr=0x%08X;\n"
372 m : " module-size=%d; module-checksum=0x%08X;\n"
373 m : " module-time-date-stamp=0x%08X; bucket-size=%d;\n"
374 m : " bucket-start=0x%08x; bucket-count=%d;\n"
375 m : " sampling-start-time=0x%016llx;\n"
376 m : " sampling-end-time=0x%016llx; sampling-interval=0x%016llx;\n"
377 m : " samples=%lld\n",
378 m : time.ToInternalValue(),
379 m : process_id,
380 m : data->module_base_addr,
381 m : data->module_size,
382 m : data->module_checksum,
383 m : data->module_time_date_stamp,
384 m : data->bucket_size,
385 m : data->bucket_start,
386 m : data->bucket_count,
387 m : data->sampling_start_time,
388 m : data->sampling_end_time,
389 m : data->sampling_interval,
390 m : samples);
391 m : }
392 :
393 : // Issued for detailed function call records.
394 m : virtual void OnFunctionNameTableEntry(
395 m : base::Time time,
396 m : DWORD process_id,
397 m : const TraceFunctionNameTableEntry* data) OVERRIDE {
398 m : DCHECK_NE(static_cast<TraceFunctionNameTableEntry*>(nullptr), data);
399 m : ::fprintf(file_,
400 m : "[%012lld] OnFunctionNameTableEntry: process-id=%d;\n"
401 m : " function-id=%d; name='%.*s'\n",
402 m : time.ToInternalValue(),
403 m : process_id,
404 m : data->function_id,
405 m : data->name_length,
406 m : data->name);
407 m : ProcessIdFunctionIdPair key(process_id, data->function_id);
408 m : std::string value(data->name, data->name_length);
409 m : function_names_.insert(std::make_pair(key, value));
410 m : }
411 :
412 : // Issued for detailed function call records.
413 m : virtual void OnStackTrace(
414 m : base::Time time,
415 m : DWORD process_id,
416 m : const TraceStackTrace* data) OVERRIDE {
417 m : DCHECK_NE(static_cast<TraceStackTrace*>(nullptr), data);
418 m : ::fprintf(file_,
419 m : "[%012lld] OnStackTrace: process-id=%d;\n"
420 m : " stack-trace-id=0x%08X; num_frames=%d\n",
421 m : time.ToInternalValue(),
422 m : process_id,
423 m : data->stack_trace_id,
424 m : data->num_frames);
425 m : }
426 :
427 : // Issued for detailed function call records.
428 m : virtual void OnDetailedFunctionCall(
429 m : base::Time time,
430 m : DWORD process_id,
431 m : DWORD thread_id,
432 m : const TraceDetailedFunctionCall* data) OVERRIDE {
433 m : DCHECK_NE(static_cast<TraceDetailedFunctionCall*>(nullptr), data);
434 m : ::fprintf(file_,
435 m : "[%012lld] OnDetailedFunctionCall: process-id=%d;\n"
436 m : " thread-id=%d; timestamp=0x%016llX;\n"
437 m : " function-id=%d; stack-trace-id=0x%08X\n",
438 m : time.ToInternalValue(),
439 m : process_id,
440 m : thread_id,
441 m : data->timestamp,
442 m : data->function_id,
443 m : data->stack_trace_id);
444 :
445 : // Output the function name if we've seen it.
446 m : auto it = function_names_.find(
447 m : ProcessIdFunctionIdPair(process_id, data->function_id));
448 m : if (it != function_names_.end())
449 m : ::fprintf(file_, " function_name='%s';\n", it->second.c_str());
450 :
451 : // Output the arguments summary info.
452 m : const uint32* argument_lengths = reinterpret_cast<const uint32*>(
453 m : data->argument_data);
454 m : uint32 argument_count = 0;
455 m : if (data->argument_data_size > 0) {
456 m : argument_count = *argument_lengths;
457 m : argument_lengths++;
458 m : }
459 m : ::fprintf(file_, " argument_data_size=%d; argument_count=%d\n",
460 m : data->argument_data_size, argument_count);
461 :
462 m : const uint8* argument_data = reinterpret_cast<const uint8*>(
463 m : argument_lengths + argument_count);
464 m : const uint8* argument_data_end = data->argument_data +
465 m : data->argument_data_size;
466 m : for (size_t i = 0; i < argument_count; ++i) {
467 m : ::fprintf(file_, " argument[%d]:", i);
468 m : for (size_t j = 0; j < argument_lengths[i]; ++j) {
469 m : if (argument_data < argument_data_end) {
470 m : ::fprintf(file_, " %02X", (int)(*argument_data));
471 m : ++argument_data;
472 m : } else {
473 m : ::fprintf(file_, " <insufficient argument data>\n");
474 m : return;
475 m : }
476 m : }
477 m : ::fprintf(file_, ";\n");
478 m : }
479 m : }
480 :
481 m : virtual void OnComment(
482 m : base::Time time,
483 m : DWORD process_id,
484 m : const TraceComment* data) {
485 m : DCHECK_NE(static_cast<TraceComment*>(nullptr), data);
486 m : ::fprintf(file_,
487 m : "[%012lld] OnComment: process-id=%d;\n"
488 m : " comment=\"%.*s\"\n",
489 m : time.ToInternalValue(),
490 m : process_id,
491 m : data->comment_size,
492 m : data->comment);
493 m : }
494 :
495 m : private:
496 m : FILE* file_;
497 m : const char* indentation_;
498 :
499 : // Stores function names per process. Used for symbolizing detailed
500 : // function call data. These are keyed be process ID and function ID.
501 m : typedef std::pair<DWORD, size_t> ProcessIdFunctionIdPair;
502 m : typedef std::map<ProcessIdFunctionIdPair, std::string> FunctionNameMap;
503 m : FunctionNameMap function_names_;
504 :
505 m : DISALLOW_COPY_AND_ASSIGN(TraceFileDumper);
506 m : };
507 :
508 m : bool DumpTraceFiles(FILE* out_file,
509 m : const std::vector<base::FilePath>& file_paths) {
510 m : Parser parser;
511 m : TraceFileDumper dumper(out_file);
512 m : if (!parser.Init(&dumper))
513 m : return false;
514 :
515 m : std::vector<base::FilePath>::const_iterator iter = file_paths.begin();
516 m : for (; iter != file_paths.end(); ++iter) {
517 m : if (!parser.OpenTraceFile(*iter))
518 m : return false;
519 m : }
520 :
521 m : return parser.Consume() && !parser.error_occurred();
522 m : }
523 :
524 m : } // namespace
525 :
526 m : int main(int argc, const char** argv) {
527 m : base::AtExitManager at_exit_manager;
528 m : CommandLine::Init(argc, argv);
529 :
530 m : logging::LoggingSettings settings;
531 m : settings.logging_dest = logging::LOG_TO_SYSTEM_DEBUG_LOG;
532 m : settings.lock_log = logging::DONT_LOCK_LOG_FILE;
533 m : settings.delete_old = logging::APPEND_TO_OLD_LOG_FILE;
534 m : if (!logging::InitLogging(settings))
535 m : return 1;
536 :
537 m : CommandLine* cmd_line = CommandLine::ForCurrentProcess();
538 m : CHECK(cmd_line != NULL);
539 :
540 m : std::vector<base::FilePath> trace_file_paths;
541 m : for (size_t i = 0; i < cmd_line->GetArgs().size(); ++i)
542 m : trace_file_paths.push_back(base::FilePath(cmd_line->GetArgs()[i]));
543 :
544 m : if (trace_file_paths.empty()) {
545 m : LOG(ERROR) << "No trace file paths specified.";
546 :
547 m : ::fprintf(stderr,
548 m : "Usage: %ls [--out=OUTPUT] TRACE_FILE(s)...\n\n",
549 m : cmd_line->GetProgram().value().c_str());
550 m : return 1;
551 m : }
552 :
553 m : base::FilePath out_file_path(cmd_line->GetSwitchValuePath("out"));
554 m : base::ScopedFILE out_file;
555 m : if (!out_file_path.empty()) {
556 m : out_file.reset(base::OpenFile(out_file_path, "w"));
557 m : if (out_file.get() == NULL) {
558 m : LOG(ERROR) << "Failed to open output file: '" << out_file_path.value()
559 m : << "'.";
560 m : return 1;
561 m : }
562 m : }
563 :
564 m : if (!DumpTraceFiles(out_file.get(), trace_file_paths)) {
565 m : LOG(ERROR) << "Failed to dump trace files.";
566 m : return 1;
567 m : }
568 :
569 m : return 0;
570 m : }
|