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 : // Base class for common trace parsing infrastructure.
16 : #include "syzygy/trace/parse/parse_engine.h"
17 :
18 : #include <windows.h> // NOLINT
19 : #include <wmistr.h> // NOLINT
20 : #include <evntrace.h>
21 :
22 : #include "base/logging.h"
23 : #include "sawbuck/common/buffer_parser.h"
24 : #include "sawbuck/common/com_utils.h"
25 : #include "syzygy/trace/parse/parser.h"
26 :
27 : namespace trace {
28 : namespace parser {
29 :
30 : ParseEngine::ParseEngine(const char* name, bool fail_on_module_conflict)
31 : : event_handler_(NULL),
32 : error_occurred_(false),
33 E : fail_on_module_conflict_(fail_on_module_conflict) {
34 E : DCHECK(name != NULL);
35 E : DCHECK(name[0] != '\0');
36 E : name_ = name;
37 E : }
38 :
39 E : ParseEngine::~ParseEngine() {
40 E : }
41 :
42 E : const char* ParseEngine::name() const {
43 E : return name_.c_str();
44 E : }
45 :
46 E : bool ParseEngine::error_occurred() const {
47 E : return error_occurred_;
48 E : }
49 :
50 E : void ParseEngine::set_error_occurred(bool value) {
51 E : error_occurred_ = value;
52 E : }
53 :
54 E : void ParseEngine::set_event_handler(ParseEventHandler* event_handler) {
55 E : DCHECK(event_handler_ == NULL);
56 E : DCHECK(event_handler != NULL);
57 E : event_handler_ = event_handler;
58 E : }
59 :
60 : const ModuleInformation* ParseEngine::GetModuleInformation(
61 E : uint32 process_id, AbsoluteAddress64 addr) const {
62 E : ProcessMap::const_iterator processes_it = processes_.find(process_id);
63 E : if (processes_it == processes_.end())
64 E : return NULL;
65 :
66 E : const ModuleSpace& module_space = processes_it->second;
67 E : ModuleSpace::Range range(addr, 1);
68 : ModuleSpace::RangeMapConstIter module_it =
69 E : module_space.FindFirstIntersection(range);
70 E : if (module_it == module_space.end())
71 E : return NULL;
72 :
73 E : return &module_it->second;
74 E : }
75 :
76 : bool ParseEngine::AddModuleInformation(DWORD process_id,
77 E : const ModuleInformation& module_info) {
78 : // Avoid doing needless work.
79 E : if (module_info.module_size == 0)
80 i : return true;
81 :
82 : // This happens in Windows XP ETW traces for some reason. They contain
83 : // conflicting information, so we ignore them.
84 E : if (module_info.image_file_name.empty())
85 i : return true;
86 :
87 E : ModuleSpace& module_space = processes_[process_id];
88 E : AbsoluteAddress64 addr(module_info.base_address);
89 E : ModuleSpace::Range range(addr, module_info.module_size);
90 :
91 E : AnnotatedModuleInformation new_module_info(module_info);
92 :
93 E : ModuleSpace::RangeMapIter iter;
94 E : if (module_space.FindOrInsert(range, new_module_info, &iter)) {
95 E : return true;
96 : }
97 :
98 : // Perhaps this is a case of conflicting paths for the same module. We often
99 : // get paths reported to us in \Device\HarddiskVolumeN\... notation, and
100 : // othertimes in C:\... notation. In this case we're happy if everything
101 : // matches except the path. For a little bit of extra sanity checking we
102 : // also check the basename of the paths.
103 : if (module_info.base_address == iter->second.base_address &&
104 : module_info.image_checksum == iter->second.image_checksum &&
105 : module_info.module_size == iter->second.module_size &&
106 E : module_info.time_date_stamp == iter->second.time_date_stamp) {
107 i : base::FilePath path1(module_info.image_file_name);
108 i : base::FilePath path2(iter->second.image_file_name);
109 i : if (path1.BaseName() == path2.BaseName()) {
110 i : return true;
111 : }
112 i : }
113 :
114 : // Perhaps this is a case of process id reuse. In that case, we should have
115 : // previously seen a module unload event and marked the module information
116 : // as dirty.
117 E : while (iter->second.is_dirty) {
118 E : module_space.Remove(iter->first);
119 E : if (module_space.FindOrInsert(range, new_module_info, &iter)) {
120 E : return true;
121 : }
122 i : }
123 :
124 E : LOG(ERROR) << "Conflicting module info for pid=" << process_id << ": "
125 : << module_info.image_file_name
126 : << " (base=0x" << module_info.base_address
127 : << ", size=" << module_info.module_size << ") and "
128 : << iter->second.image_file_name
129 : << " (base=0x" << iter->second.base_address
130 : << ", size=" << iter->second.module_size << ").";
131 :
132 E : return fail_on_module_conflict_ ? false : true;
133 E : }
134 :
135 : bool ParseEngine::RemoveModuleInformation(
136 E : DWORD process_id, const ModuleInformation& module_info) {
137 : // Avoid doing needless work.
138 E : if (module_info.module_size == 0)
139 i : return true;
140 :
141 : // This happens in Windows XP traces for some reason. They contain conflicing
142 : // information, so we ignore them.
143 E : if (module_info.image_file_name.empty())
144 i : return true;
145 :
146 E : ModuleSpace& module_space = processes_[process_id];
147 E : AbsoluteAddress64 addr(module_info.base_address);
148 E : ModuleSpace::Range range(addr, module_info.module_size);
149 E : ModuleSpace::RangeMapIter it = module_space.FindFirstIntersection(range);
150 E : if (it == module_space.end()) {
151 : // We occasionally see this, as certain modules fire off multiple Unload
152 : // events, so we don't log an error. I'm looking at you, logman.exe.
153 E : return true;
154 : }
155 E : if (it->first != range) {
156 i : LOG(ERROR) << "Trying to remove module with mismatching range: "
157 : << module_info.image_file_name
158 : << " (base=0x" << module_info.base_address
159 : << ", size=" << module_info.module_size << ").";
160 i : if (fail_on_module_conflict_)
161 i : return false;
162 : }
163 :
164 : // We only remove modules from a given process if a conflicting module is
165 : // loaded after the module has been marked as dirty. This is because (1) we
166 : // don't guarantee temporal order of all events in a process, so you
167 : // might parse a function event after seeing the module get unloaded
168 : // if the buffers are flushed in that order; and (2) because process ids may
169 : // be reused (but not concurrently) so we do want to drop stale module info
170 : // when the process has been replaced.
171 :
172 E : it->second.is_dirty = true;
173 :
174 E : return true;
175 E : }
176 :
177 E : bool ParseEngine::RemoveProcessInformation(DWORD process_id) {
178 E : ProcessMap::iterator proc_iter = processes_.find(process_id);
179 E : if (proc_iter == processes_.end()) {
180 i : LOG(ERROR) << "Unknown process id: " << process_id << ".";
181 i : return false;
182 : }
183 :
184 E : ModuleSpace& process_info = proc_iter->second;
185 :
186 E : ModuleSpace::iterator module_iter = process_info.begin();
187 E : for (; module_iter != process_info.end(); ++module_iter) {
188 E : module_iter->second.is_dirty = true;
189 E : }
190 :
191 E : return true;
192 E : }
193 :
194 E : bool ParseEngine::DispatchEvent(EVENT_TRACE* event) {
195 E : DCHECK(event != NULL);
196 E : DCHECK(event_handler_ != NULL);
197 E : DCHECK(error_occurred_ == false);
198 :
199 E : if (kCallTraceEventClass != event->Header.Guid)
200 E : return false;
201 :
202 E : bool success = false;
203 E : TraceEventType type = static_cast<TraceEventType>(event->Header.Class.Type);
204 :
205 E : switch (type) {
206 : case TRACE_ENTER_EVENT:
207 : case TRACE_EXIT_EVENT:
208 E : success = DispatchEntryExitEvent(event, type);
209 E : break;
210 :
211 : case TRACE_BATCH_ENTER:
212 E : success = DispatchBatchEnterEvent(event);
213 E : break;
214 :
215 : case TRACE_PROCESS_ATTACH_EVENT:
216 : case TRACE_PROCESS_DETACH_EVENT:
217 : case TRACE_THREAD_ATTACH_EVENT:
218 : case TRACE_THREAD_DETACH_EVENT:
219 E : success = DispatchModuleEvent(event, type);
220 E : break;
221 :
222 : case TRACE_PROCESS_ENDED:
223 E : success = DispatchProcessEndedEvent(event);
224 E : break;
225 :
226 : case TRACE_MODULE_EVENT:
227 i : LOG(ERROR) << "Parsing for TRACE_MODULE_EVENT not yet implemented.";
228 i : break;
229 :
230 : case TRACE_BATCH_INVOCATION:
231 E : success = DispatchBatchInvocationEvent(event);
232 E : break;
233 :
234 : case TRACE_THREAD_NAME:
235 E : success = DispatchThreadNameEvent(event);
236 E : break;
237 :
238 : case TRACE_INDEXED_FREQUENCY:
239 E : success = DispatchIndexedFrequencyEvent(event);
240 E : break;
241 :
242 : case TRACE_DYNAMIC_SYMBOL:
243 E : success = DispatchDynamicSymbolEvent(event);
244 E : break;
245 :
246 : case TRACE_SAMPLE_DATA:
247 E : success = DispatchSampleDataEvent(event);
248 E : break;
249 :
250 : default:
251 E : LOG(ERROR) << "Unknown event type encountered.";
252 : break;
253 : }
254 :
255 E : if (!success) {
256 E : error_occurred_ = true;
257 : }
258 :
259 E : return true;
260 E : }
261 :
262 : bool ParseEngine::DispatchEntryExitEvent(EVENT_TRACE* event,
263 E : TraceEventType type) {
264 E : DCHECK(event != NULL);
265 E : DCHECK(type == TRACE_ENTER_EVENT || type == TRACE_EXIT_EVENT);
266 E : DCHECK(event_handler_ != NULL);
267 E : DCHECK(error_occurred_ == false);
268 :
269 E : BinaryBufferReader reader(event->MofData, event->MofLength);
270 E : const TraceEnterExitEventData* data = NULL;
271 :
272 E : if (!reader.Read(sizeof(TraceEnterExitEventData), &data)) {
273 E : LOG(ERROR) << "Short entry exit event.";
274 E : return false;
275 : }
276 :
277 : base::Time time(base::Time::FromFileTime(
278 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
279 E : DWORD process_id = event->Header.ProcessId;
280 E : DWORD thread_id = event->Header.ThreadId;
281 :
282 E : switch (type) {
283 : case TRACE_ENTER_EVENT:
284 E : event_handler_->OnFunctionEntry(time, process_id, thread_id, data);
285 E : break;
286 :
287 : case TRACE_EXIT_EVENT:
288 E : event_handler_->OnFunctionExit(time, process_id, thread_id, data);
289 E : break;
290 :
291 : default:
292 i : NOTREACHED() << "Impossible event type.";
293 i : return false;
294 : }
295 :
296 E : return true;
297 E : }
298 :
299 E : bool ParseEngine::DispatchBatchEnterEvent(EVENT_TRACE* event) {
300 E : DCHECK(event != NULL);
301 E : DCHECK(event_handler_ != NULL);
302 E : DCHECK(error_occurred_ == false);
303 :
304 E : BinaryBufferReader reader(event->MofData, event->MofLength);
305 E : const TraceBatchEnterData* data = NULL;
306 E : size_t offset_to_calls = FIELD_OFFSET(TraceBatchEnterData, calls);
307 E : if (!reader.Read(offset_to_calls, &data)) {
308 E : LOG(ERROR) << "Short or empty batch event.";
309 E : return false;
310 : }
311 :
312 E : size_t bytes_needed = data->num_calls * sizeof(data->calls[0]);
313 E : if (!reader.Consume(bytes_needed)) {
314 E : LOG(ERROR) << "Short batch event data. Expected " << data->num_calls
315 : << " entries (" << (offset_to_calls + bytes_needed)
316 : << " bytes) but batch record was only " << event->MofLength
317 : << " bytes.";
318 E : return false;
319 : }
320 :
321 : // Trim the batch entries if the last one is NULL, indicating that the
322 : // reporting thread was interrupted mid-write.
323 : if (data->num_calls != 0 &&
324 E : data->calls[data->num_calls - 1].function == NULL) {
325 : // Yuck! Cast away constness because the BinaryBufferReader only likes
326 : // to deal with const output pointers.
327 E : const_cast<TraceBatchEnterData*>(data)->num_calls -= 1;
328 : }
329 : DCHECK(data->num_calls == 0 ||
330 E : data->calls[data->num_calls - 1].function != NULL);
331 :
332 : base::Time time(base::Time::FromFileTime(
333 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
334 E : DWORD process_id = event->Header.ProcessId;
335 E : DWORD thread_id = data->thread_id;
336 E : event_handler_->OnBatchFunctionEntry(time, process_id, thread_id, data);
337 E : return true;
338 E : }
339 :
340 E : bool ParseEngine::DispatchProcessEndedEvent(EVENT_TRACE* event) {
341 E : DCHECK(event != NULL);
342 E : DCHECK(event_handler_ != NULL);
343 E : DCHECK(error_occurred_ == false);
344 :
345 : base::Time time(base::Time::FromFileTime(
346 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
347 :
348 E : event_handler_->OnProcessEnded(time, event->Header.ProcessId);
349 E : if (!RemoveProcessInformation(event->Header.ProcessId))
350 i : return false;
351 :
352 E : return true;
353 E : }
354 :
355 E : bool ParseEngine::DispatchBatchInvocationEvent(EVENT_TRACE* event) {
356 E : DCHECK(event != NULL);
357 E : DCHECK(event_handler_ != NULL);
358 E : DCHECK(error_occurred_ == false);
359 :
360 E : BinaryBufferReader reader(event->MofData, event->MofLength);
361 E : if (event->MofLength % sizeof(InvocationInfo) != 0) {
362 i : LOG(ERROR) << "Invocation batch length off.";
363 i : return false;
364 : }
365 :
366 E : const TraceBatchInvocationInfo* data = NULL;
367 E : if (!reader.Read(event->MofLength, &data)) {
368 i : LOG(ERROR) << "Short or empty batch event.";
369 i : return false;
370 : }
371 :
372 : // TODO(rogerm): Ensure this is robust in the presence of incomplete write.
373 E : size_t num_invocations = event->MofLength / sizeof(InvocationInfo);
374 : base::Time time(base::Time::FromFileTime(
375 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
376 E : DWORD process_id = event->Header.ProcessId;
377 E : DWORD thread_id = event->Header.ThreadId;
378 : event_handler_->OnInvocationBatch(time,
379 : process_id,
380 : thread_id,
381 : num_invocations,
382 E : data);
383 :
384 E : return true;
385 E : }
386 :
387 E : bool ParseEngine::DispatchThreadNameEvent(EVENT_TRACE* event) {
388 E : DCHECK(event != NULL);
389 E : DCHECK(event_handler_ != NULL);
390 E : DCHECK(error_occurred_ == false);
391 :
392 E : BinaryBufferReader reader(event->MofData, event->MofLength);
393 E : const char* thread_name = NULL;
394 E : size_t thread_name_len = 0;
395 E : if (!reader.ReadString(&thread_name, &thread_name_len)) {
396 i : LOG(ERROR) << "Unable to read string.";
397 i : return false;
398 : }
399 :
400 : base::Time time(base::Time::FromFileTime(
401 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
402 E : DWORD process_id = event->Header.ProcessId;
403 E : DWORD thread_id = event->Header.ThreadId;
404 : event_handler_->OnThreadName(time,
405 : process_id,
406 : thread_id,
407 E : base::StringPiece(thread_name, thread_name_len));
408 :
409 E : return true;
410 E : }
411 :
412 E : bool ParseEngine::DispatchIndexedFrequencyEvent(EVENT_TRACE* event) {
413 E : DCHECK(event != NULL);
414 E : DCHECK(event_handler_ != NULL);
415 E : DCHECK(error_occurred_ == false);
416 :
417 E : if (event->MofLength < sizeof(TraceIndexedFrequencyData)) {
418 E : LOG(ERROR) << "Data too small for TraceIndexedFrequency struct.";
419 E : return false;
420 : }
421 :
422 E : BinaryBufferReader reader(event->MofData, event->MofLength);
423 E : const TraceIndexedFrequencyData* data = NULL;
424 E : if (!reader.Read(&data)) {
425 i : LOG(ERROR) << "Short or empty coverage data event.";
426 i : return false;
427 : }
428 E : DCHECK(data != NULL);
429 :
430 : // Calculate the expected size of the entire payload, headers included.
431 : size_t expected_length = data->frequency_size * data->num_entries +
432 E : sizeof(TraceIndexedFrequencyData) - 1;
433 E : if (event->MofLength < expected_length) {
434 E : LOG(ERROR) << "Payload smaller than size implied by "
435 : << "TraceIndexedFrequencyData header.";
436 E : return false;
437 : }
438 :
439 : base::Time time(base::Time::FromFileTime(
440 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
441 E : DWORD process_id = event->Header.ProcessId;
442 E : DWORD thread_id = event->Header.ThreadId;
443 E : event_handler_->OnIndexedFrequency(time, process_id, thread_id, data);
444 :
445 E : return true;
446 E : }
447 :
448 E : bool ParseEngine::DispatchDynamicSymbolEvent(EVENT_TRACE* event) {
449 E : DCHECK(event != NULL);
450 E : DCHECK(event_handler_ != NULL);
451 E : DCHECK(error_occurred_ == false);
452 :
453 E : BinaryBufferReader reader(event->MofData, event->MofLength);
454 E : const TraceDynamicSymbol* symbol = NULL;
455 E : const char* symbol_name = NULL;
456 E : size_t symbol_name_len = 0;
457 : if (!reader.Read(FIELD_OFFSET(TraceDynamicSymbol, symbol_name), &symbol) ||
458 E : !reader.ReadString(&symbol_name, &symbol_name_len)) {
459 E : LOG(ERROR) << "Short or empty coverage data event.";
460 E : return false;
461 : }
462 :
463 E : DWORD process_id = event->Header.ProcessId;
464 : event_handler_->OnDynamicSymbol(
465 : process_id, symbol->symbol_id,
466 E : base::StringPiece(symbol_name, symbol_name_len));
467 :
468 E : return true;
469 E : }
470 :
471 E : bool ParseEngine::DispatchSampleDataEvent(EVENT_TRACE* event) {
472 E : DCHECK(event != NULL);
473 E : DCHECK(event_handler_ != NULL);
474 E : DCHECK(error_occurred_ == false);
475 :
476 E : BinaryBufferReader reader(event->MofData, event->MofLength);
477 E : const TraceSampleData* data = NULL;
478 E : if (!reader.Read(&data)) {
479 i : LOG(ERROR) << "Short or empty TraceSampleData event.";
480 i : return false;
481 : }
482 E : DCHECK(data != NULL);
483 :
484 : // Calculate the expected size of the entire payload, headers included.
485 : size_t expected_length = FIELD_OFFSET(TraceSampleData, buckets) +
486 E : sizeof(data->buckets[0]) * data->bucket_count;
487 E : if (event->MofLength < expected_length) {
488 E : LOG(ERROR) << "Payload smaller than size implied by TraceSampleData "
489 : << "header.";
490 E : return false;
491 : }
492 :
493 : base::Time time(base::Time::FromFileTime(
494 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
495 E : DWORD process_id = event->Header.ProcessId;
496 E : event_handler_->OnSampleData(time, process_id, data);
497 :
498 E : return true;
499 E : }
500 :
501 : namespace {
502 :
503 : ModuleInformation ModuleTraceDataToModuleInformation(
504 E : const TraceModuleData& module_data) {
505 E : ModuleInformation module_info = {};
506 : module_info.base_address =
507 E : reinterpret_cast<uint32>(module_data.module_base_addr);
508 E : module_info.module_size = module_data.module_base_size;
509 E : module_info.image_file_name = module_data.module_name;
510 E : module_info.image_checksum = module_data.module_checksum;
511 E : module_info.time_date_stamp = module_data.module_time_date_stamp;
512 E : return module_info;
513 E : }
514 :
515 : } // namespace
516 :
517 : bool ParseEngine::DispatchModuleEvent(EVENT_TRACE* event,
518 E : TraceEventType type) {
519 E : DCHECK(event != NULL);
520 : DCHECK(type == TRACE_PROCESS_ATTACH_EVENT ||
521 : type == TRACE_PROCESS_DETACH_EVENT ||
522 : type == TRACE_THREAD_ATTACH_EVENT ||
523 E : type == TRACE_THREAD_DETACH_EVENT);
524 E : DCHECK(event_handler_ != NULL);
525 E : DCHECK(error_occurred_ == false);
526 :
527 E : BinaryBufferReader reader(event->MofData, event->MofLength);
528 E : const TraceModuleData* data = NULL;
529 E : if (!reader.Read(&data)) {
530 E : LOG(ERROR) << "Short or empty module event.";
531 E : return false;
532 : }
533 :
534 E : if (data->module_base_addr == NULL) {
535 E : LOG(INFO) << "Encountered incompletely written module event record.";
536 E : return true;
537 : }
538 :
539 : base::Time time(base::Time::FromFileTime(
540 E : reinterpret_cast<FILETIME&>(event->Header.TimeStamp)));
541 E : DWORD process_id = event->Header.ProcessId;
542 E : DWORD thread_id = event->Header.ThreadId;
543 :
544 E : switch (type) {
545 : case TRACE_PROCESS_ATTACH_EVENT:
546 : AddModuleInformation(process_id,
547 E : ModuleTraceDataToModuleInformation(*data));
548 E : event_handler_->OnProcessAttach(time, process_id, thread_id, data);
549 E : break;
550 :
551 : case TRACE_PROCESS_DETACH_EVENT:
552 E : event_handler_->OnProcessDetach(time, process_id, thread_id, data);
553 : RemoveModuleInformation(process_id,
554 E : ModuleTraceDataToModuleInformation(*data));
555 E : break;
556 :
557 : case TRACE_THREAD_ATTACH_EVENT:
558 E : event_handler_->OnThreadAttach(time, process_id, thread_id, data);
559 E : break;
560 :
561 : case TRACE_THREAD_DETACH_EVENT:
562 E : event_handler_->OnThreadDetach(time, process_id, thread_id, data);
563 E : break;
564 :
565 : default:
566 i : LOG(ERROR) << "Unexpected module event type " << type << ".";
567 i : return false;
568 : }
569 :
570 E : return true;
571 E : }
572 :
573 : } // namespace parser
574 : } // namespace trace
|