OLD | NEW |
1 // Copyright 2011 Google Inc. | 1 // Copyright 2011 Google Inc. |
2 // | 2 // |
3 // Licensed under the Apache License, Version 2.0 (the "License"); | 3 // Licensed under the Apache License, Version 2.0 (the "License"); |
4 // you may not use this file except in compliance with 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 | 5 // You may obtain a copy of the License at |
6 // | 6 // |
7 // http://www.apache.org/licenses/LICENSE-2.0 | 7 // http://www.apache.org/licenses/LICENSE-2.0 |
8 // | 8 // |
9 // Unless required by applicable law or agreed to in writing, software | 9 // Unless required by applicable law or agreed to in writing, software |
10 // distributed under the License is distributed on an "AS IS" BASIS, | 10 // distributed under the License is distributed on an "AS IS" BASIS, |
(...skipping 125 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
136 trace_paths_(trace_paths), | 136 trace_paths_(trace_paths), |
137 flags_(flags), | 137 flags_(flags), |
138 code_block_entry_events_(0), | 138 code_block_entry_events_(0), |
139 consumer_errored_(false), | 139 consumer_errored_(false), |
140 order_generator_(NULL), | 140 order_generator_(NULL), |
141 image_(NULL) { | 141 image_(NULL) { |
142 DCHECK(consumer_ == NULL); | 142 DCHECK(consumer_ == NULL); |
143 if (consumer_ == NULL) { | 143 if (consumer_ == NULL) { |
144 consumer_ = this; | 144 consumer_ = this; |
145 kernel_log_parser_.set_module_event_sink(this); | 145 kernel_log_parser_.set_module_event_sink(this); |
| 146 kernel_log_parser_.set_process_event_sink(this); |
146 call_trace_parser_.set_call_trace_event_sink(this); | 147 call_trace_parser_.set_call_trace_event_sink(this); |
147 } | 148 } |
148 } | 149 } |
149 | 150 |
150 Reorderer::~Reorderer() { | 151 Reorderer::~Reorderer() { |
151 consumer_ = NULL; | 152 consumer_ = NULL; |
152 } | 153 } |
153 | 154 |
154 bool Reorderer::Reorder(OrderGenerator* order_generator, Order* order) { | 155 bool Reorderer::Reorder(OrderGenerator* order_generator, Order* order) { |
155 DCHECK(order_generator != NULL); | 156 DCHECK(order_generator != NULL); |
(...skipping 163 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
319 OnModuleLoad(process_id, time, module_info); | 320 OnModuleLoad(process_id, time, module_info); |
320 } | 321 } |
321 | 322 |
322 void Reorderer::OnModuleUnload(DWORD process_id, | 323 void Reorderer::OnModuleUnload(DWORD process_id, |
323 const base::Time& time, | 324 const base::Time& time, |
324 const ModuleInformation& module_info) { | 325 const ModuleInformation& module_info) { |
325 // Avoid doing needless work. | 326 // Avoid doing needless work. |
326 if (consumer_errored_ || module_info.module_size == 0) | 327 if (consumer_errored_ || module_info.module_size == 0) |
327 return; | 328 return; |
328 | 329 |
| 330 // This happens in Windows XP traces for some reason. They contain conflicing |
| 331 // information, so we ignore them. |
| 332 if (module_info.image_file_name.empty()) |
| 333 return; |
| 334 |
329 if (last_event_time_ > time) { | 335 if (last_event_time_ > time) { |
330 LOG(ERROR) << "Messages out of temporal order."; | 336 LOG(ERROR) << "Messages out of temporal order."; |
331 consumer_errored_ = true; | 337 consumer_errored_ = true; |
332 return; | 338 return; |
333 } | 339 } |
334 | 340 |
335 ModuleSpace& module_space = processes_[process_id]; | 341 ModuleSpace& module_space = processes_[process_id]; |
336 AbsoluteAddress64 addr(module_info.base_address); | 342 AbsoluteAddress64 addr(module_info.base_address); |
337 ModuleSpace::Range range(addr, module_info.module_size); | 343 ModuleSpace::Range range(addr, module_info.module_size); |
338 ModuleSpace::RangeMapIter it = | 344 ModuleSpace::RangeMapIter it = |
(...skipping 14 matching lines...) Expand all Loading... |
353 last_event_time_ = time; | 359 last_event_time_ = time; |
354 } | 360 } |
355 | 361 |
356 void Reorderer::OnModuleLoad(DWORD process_id, | 362 void Reorderer::OnModuleLoad(DWORD process_id, |
357 const base::Time& time, | 363 const base::Time& time, |
358 const ModuleInformation& module_info) { | 364 const ModuleInformation& module_info) { |
359 // Avoid doing needless work. | 365 // Avoid doing needless work. |
360 if (consumer_errored_ || module_info.module_size == 0) | 366 if (consumer_errored_ || module_info.module_size == 0) |
361 return; | 367 return; |
362 | 368 |
| 369 // This happens in Windows XP traces for some reason. They contain conflicing |
| 370 // information, so we ignore them. |
| 371 if (module_info.image_file_name.empty()) |
| 372 return; |
| 373 |
363 if (last_event_time_ > time) { | 374 if (last_event_time_ > time) { |
364 LOG(ERROR) << "Messages out of temporal order."; | 375 LOG(ERROR) << "Messages out of temporal order."; |
365 consumer_errored_ = true; | 376 consumer_errored_ = true; |
366 return; | 377 return; |
367 } | 378 } |
368 | 379 |
369 ModuleSpace& module_space = processes_[process_id]; | 380 ModuleSpace& module_space = processes_[process_id]; |
370 AbsoluteAddress64 addr(module_info.base_address); | 381 AbsoluteAddress64 addr(module_info.base_address); |
371 ModuleSpace::Range range(addr, module_info.module_size); | 382 ModuleSpace::Range range(addr, module_info.module_size); |
372 if (!module_space.Insert(range, module_info)) { | 383 if (!module_space.Insert(range, module_info)) { |
373 ModuleSpace::RangeMapIter it = module_space.FindFirstIntersection(range); | 384 ModuleSpace::RangeMapIter it = module_space.FindFirstIntersection(range); |
374 DCHECK(it != module_space.end()); | 385 DCHECK(it != module_space.end()); |
375 LOG(ERROR) << "Trying to insert conflicting module: " | 386 // We actually see this behaviour on Windows XP gathered traces. Since this |
376 << module_info.image_file_name; | 387 // is one of the platforms we target, we simply print out a warning for |
377 consumer_errored_ = true; | 388 // now. |
378 return; | 389 LOG(WARNING) << "Trying to insert conflicting module: " |
| 390 << module_info.image_file_name; |
379 } | 391 } |
380 | 392 |
381 last_event_time_ = time; | 393 last_event_time_ = time; |
382 } | 394 } |
383 | 395 |
| 396 // KernelProcessEvents implementation. |
| 397 void Reorderer::OnProcessIsRunning(const base::Time& time, |
| 398 const ProcessInfo& process_info) { |
| 399 // We don't care about these events. |
| 400 } |
| 401 |
| 402 void Reorderer::OnProcessStarted(const base::Time& time, |
| 403 const ProcessInfo& process_info) { |
| 404 // We don't care about these events. |
| 405 } |
| 406 |
| 407 void Reorderer::OnProcessEnded(const base::Time& time, |
| 408 const ProcessInfo& process_info, |
| 409 ULONG exit_status) { |
| 410 uint32 process_id = process_info.process_id; |
| 411 ProcessSet::iterator process_it = matching_process_ids_.find(process_id); |
| 412 if (process_it == matching_process_ids_.end()) |
| 413 return; |
| 414 |
| 415 matching_process_ids_.erase(process_it); |
| 416 |
| 417 UniqueTime entry_time(time); |
| 418 if (!order_generator_->OnProcessEnded(*this, process_id, entry_time)) { |
| 419 consumer_errored_ = true; |
| 420 return; |
| 421 } |
| 422 |
| 423 return; |
| 424 } |
| 425 |
384 // CallTraceEvents implementation. | 426 // CallTraceEvents implementation. |
385 void Reorderer::OnTraceEntry(base::Time time, | 427 void Reorderer::OnTraceEntry(base::Time time, |
386 DWORD process_id, | 428 DWORD process_id, |
387 DWORD thread_id, | 429 DWORD thread_id, |
388 const TraceEnterExitEventData* data) { | 430 const TraceEnterExitEventData* data) { |
389 // We currently don't care about TraceEntry events. | 431 // We currently don't care about TraceEntry events. |
390 } | 432 } |
391 | 433 |
392 void Reorderer::OnTraceExit(base::Time time, | 434 void Reorderer::OnTraceExit(base::Time time, |
393 DWORD process_id, | 435 DWORD process_id, |
(...skipping 22 matching lines...) Expand all Loading... |
416 !MatchesInstrumentedModuleSignature(*module_info)) | 458 !MatchesInstrumentedModuleSignature(*module_info)) |
417 continue; | 459 continue; |
418 | 460 |
419 // Get the block that this function call refers to. We can only instrument | 461 // Get the block that this function call refers to. We can only instrument |
420 // 32-bit DLLs, so we're sure that the following address conversion is safe. | 462 // 32-bit DLLs, so we're sure that the following address conversion is safe. |
421 RelativeAddress rva( | 463 RelativeAddress rva( |
422 static_cast<uint32>(function_address - module_info->base_address)); | 464 static_cast<uint32>(function_address - module_info->base_address)); |
423 const BlockGraph::Block* block = | 465 const BlockGraph::Block* block = |
424 image_->address_space.GetBlockByAddress(rva); | 466 image_->address_space.GetBlockByAddress(rva); |
425 if (block == NULL) { | 467 if (block == NULL) { |
426 LOG(ERROR) << "Unable to map relative address " | 468 LOG(ERROR) << "Unable to map " << rva << " to a block."; |
427 << base::StringPrintf("0x%08d", rva.value()) | |
428 << " to a block."; | |
429 consumer_errored_ = true; | 469 consumer_errored_ = true; |
430 return; | 470 return; |
431 } | 471 } |
432 if (block->type() != BlockGraph::CODE_BLOCK) { | 472 if (block->type() != BlockGraph::CODE_BLOCK) { |
433 LOG(ERROR) << "Address " << base::StringPrintf("0x%08d", rva.value()) | 473 LOG(ERROR) << rva << " maps to a non-code block."; |
434 << " maps to a non-code block."; | |
435 consumer_errored_ = true; | 474 consumer_errored_ = true; |
436 return; | 475 return; |
437 } | 476 } |
438 | 477 |
439 // Get the actual time of the call. We ignore ticks_ago for now, as the | 478 // Get the actual time of the call. We ignore ticks_ago for now, as the |
440 // low-resolution and rounding can cause inaccurate relative timings. We | 479 // low-resolution and rounding can cause inaccurate relative timings. We |
441 // simply rely on the buffer ordering (via UniqueTime's internal counter) | 480 // simply rely on the buffer ordering (via UniqueTime's internal counter) |
442 // to maintain relative ordering. For future reference, ticks_ago are in | 481 // to maintain relative ordering. For future reference, ticks_ago are in |
443 // milliseconds, according to MSDN. | 482 // milliseconds, according to MSDN. |
444 UniqueTime entry_time(time); | 483 UniqueTime entry_time(time); |
445 | 484 |
| 485 // If this is the first call of interest by a given process, send an |
| 486 // OnProcessStarted event. |
| 487 if (matching_process_ids_.insert(process_id).second) { |
| 488 if (!order_generator_->OnProcessStarted(*this, process_id, entry_time)) { |
| 489 consumer_errored_ = true; |
| 490 return; |
| 491 } |
| 492 } |
| 493 |
446 ++code_block_entry_events_; | 494 ++code_block_entry_events_; |
447 if (!order_generator_->OnCodeBlockEntry(*this, block, rva, process_id, | 495 if (!order_generator_->OnCodeBlockEntry(*this, block, rva, process_id, |
448 thread_id, entry_time)) { | 496 thread_id, entry_time)) { |
449 consumer_errored_ = true; | 497 consumer_errored_ = true; |
450 return; | 498 return; |
451 } | 499 } |
452 } | 500 } |
453 } | 501 } |
454 | 502 |
455 void Reorderer::OnEvent(PEVENT_TRACE event) { | 503 void Reorderer::OnEvent(PEVENT_TRACE event) { |
(...skipping 305 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
761 if (id_ < rhs.id_) | 809 if (id_ < rhs.id_) |
762 return -1; | 810 return -1; |
763 if (id_ > rhs.id_) | 811 if (id_ > rhs.id_) |
764 return 1; | 812 return 1; |
765 return 0; | 813 return 0; |
766 } | 814 } |
767 | 815 |
768 size_t Reorderer::UniqueTime::next_id_ = 0; | 816 size_t Reorderer::UniqueTime::next_id_ = 0; |
769 | 817 |
770 } // namespace reorder | 818 } // namespace reorder |
OLD | NEW |