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