OLD | NEW |
1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. | 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. |
2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 | 4 |
5 #include "base/debug/trace_event_impl.h" | 5 #include "base/debug/trace_event_impl.h" |
6 | 6 |
7 #include <algorithm> | 7 #include <algorithm> |
8 | 8 |
9 #include "base/bind.h" | 9 #include "base/bind.h" |
| 10 #include "base/debug/leak_annotations.h" |
10 #include "base/debug/trace_event.h" | 11 #include "base/debug/trace_event.h" |
11 #include "base/file_util.h" | 12 #include "base/file_util.h" |
12 #include "base/format_macros.h" | 13 #include "base/format_macros.h" |
13 #include "base/lazy_instance.h" | 14 #include "base/lazy_instance.h" |
14 #include "base/memory/singleton.h" | 15 #include "base/memory/singleton.h" |
15 #include "base/process_util.h" | 16 #include "base/process_util.h" |
| 17 #include "base/stl_util.h" |
16 #include "base/stringprintf.h" | 18 #include "base/stringprintf.h" |
17 #include "base/string_tokenizer.h" | 19 #include "base/string_tokenizer.h" |
| 20 #include "base/string_util.h" |
| 21 #include "base/sys_info.h" |
| 22 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" |
18 #include "base/threading/platform_thread.h" | 23 #include "base/threading/platform_thread.h" |
19 #include "base/threading/thread_local.h" | 24 #include "base/threading/thread_local.h" |
| 25 #include "base/time.h" |
20 #include "base/utf_string_conversions.h" | 26 #include "base/utf_string_conversions.h" |
21 #include "base/stl_util.h" | |
22 #include "base/sys_info.h" | |
23 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" | |
24 #include "base/time.h" | |
25 | 27 |
26 #if defined(OS_WIN) | 28 #if defined(OS_WIN) |
27 #include "base/debug/trace_event_win.h" | 29 #include "base/debug/trace_event_win.h" |
28 #endif | 30 #endif |
29 | 31 |
30 class DeleteTraceLogForTesting { | 32 class DeleteTraceLogForTesting { |
31 public: | 33 public: |
32 static void Delete() { | 34 static void Delete() { |
33 Singleton<base::debug::TraceLog, | 35 Singleton<base::debug::TraceLog, |
34 StaticMemorySingletonTraits<base::debug::TraceLog> >::OnExit(0); | 36 StaticMemorySingletonTraits<base::debug::TraceLog> >::OnExit(0); |
(...skipping 274 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
309 void TraceResultBuffer::Finish() { | 311 void TraceResultBuffer::Finish() { |
310 output_callback_.Run("]"); | 312 output_callback_.Run("]"); |
311 } | 313 } |
312 | 314 |
313 //////////////////////////////////////////////////////////////////////////////// | 315 //////////////////////////////////////////////////////////////////////////////// |
314 // | 316 // |
315 // TraceLog | 317 // TraceLog |
316 // | 318 // |
317 //////////////////////////////////////////////////////////////////////////////// | 319 //////////////////////////////////////////////////////////////////////////////// |
318 | 320 |
| 321 TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log) |
| 322 : trace_log_(trace_log), |
| 323 notification_(0) { |
| 324 } |
| 325 |
| 326 TraceLog::NotificationHelper::~NotificationHelper() { |
| 327 } |
| 328 |
| 329 void TraceLog::NotificationHelper::AddNotificationWhileLocked( |
| 330 int notification) { |
| 331 if (trace_log_->notification_callback_.is_null()) |
| 332 return; |
| 333 if (notification_ == 0) |
| 334 callback_copy_ = trace_log_->notification_callback_; |
| 335 notification_ |= notification; |
| 336 } |
| 337 |
| 338 void TraceLog::NotificationHelper::SendNotificationIfAny() { |
| 339 if (notification_) |
| 340 callback_copy_.Run(notification_); |
| 341 } |
| 342 |
319 // static | 343 // static |
320 TraceLog* TraceLog::GetInstance() { | 344 TraceLog* TraceLog::GetInstance() { |
321 return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); | 345 return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get(); |
322 } | 346 } |
323 | 347 |
324 TraceLog::TraceLog() | 348 TraceLog::TraceLog() |
325 : enabled_(false) | 349 : enabled_(false), |
326 , dispatching_to_observer_list_(false) { | 350 dispatching_to_observer_list_(false), |
| 351 watch_category_(NULL) { |
327 // Trace is enabled or disabled on one thread while other threads are | 352 // Trace is enabled or disabled on one thread while other threads are |
328 // accessing the enabled flag. We don't care whether edge-case events are | 353 // accessing the enabled flag. We don't care whether edge-case events are |
329 // traced or not, so we allow races on the enabled flag to keep the trace | 354 // traced or not, so we allow races on the enabled flag to keep the trace |
330 // macros fast. | 355 // macros fast. |
331 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots: | 356 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots: |
332 // ANNOTATE_BENIGN_RACE_SIZED(g_category_enabled, sizeof(g_category_enabled), | 357 // ANNOTATE_BENIGN_RACE_SIZED(g_category_enabled, sizeof(g_category_enabled), |
333 // "trace_event category enabled"); | 358 // "trace_event category enabled"); |
334 for (int i = 0; i < TRACE_EVENT_MAX_CATEGORIES; ++i) { | 359 for (int i = 0; i < TRACE_EVENT_MAX_CATEGORIES; ++i) { |
335 ANNOTATE_BENIGN_RACE(&g_category_enabled[i], | 360 ANNOTATE_BENIGN_RACE(&g_category_enabled[i], |
336 "trace_event category enabled"); | 361 "trace_event category enabled"); |
(...skipping 62 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
399 for (int i = 0; i < g_category_index; i++) { | 424 for (int i = 0; i < g_category_index; i++) { |
400 if (strcmp(g_categories[i], name) == 0) | 425 if (strcmp(g_categories[i], name) == 0) |
401 return &g_category_enabled[i]; | 426 return &g_category_enabled[i]; |
402 } | 427 } |
403 | 428 |
404 // Create a new category | 429 // Create a new category |
405 DCHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) << | 430 DCHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) << |
406 "must increase TRACE_EVENT_MAX_CATEGORIES"; | 431 "must increase TRACE_EVENT_MAX_CATEGORIES"; |
407 if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) { | 432 if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) { |
408 int new_index = g_category_index++; | 433 int new_index = g_category_index++; |
409 g_categories[new_index] = name; | 434 // Don't hold on to the name pointer, so that we can create categories with |
| 435 // strings not known at compile time (this is required by SetWatchEvent). |
| 436 const char* new_name = base::strdup(name); |
| 437 ANNOTATE_LEAKING_OBJECT_PTR(new_name); |
| 438 g_categories[new_index] = new_name; |
410 DCHECK(!g_category_enabled[new_index]); | 439 DCHECK(!g_category_enabled[new_index]); |
411 if (enabled_) { | 440 if (enabled_) { |
412 // Note that if both included and excluded_categories are empty, the else | 441 // Note that if both included and excluded_categories are empty, the else |
413 // clause below excludes nothing, thereby enabling this category. | 442 // clause below excludes nothing, thereby enabling this category. |
414 if (!included_categories_.empty()) | 443 if (!included_categories_.empty()) |
415 EnableMatchingCategory(new_index, included_categories_, 1); | 444 EnableMatchingCategory(new_index, included_categories_, 1); |
416 else | 445 else |
417 EnableMatchingCategory(new_index, excluded_categories_, 0); | 446 EnableMatchingCategory(new_index, excluded_categories_, 0); |
418 } else { | 447 } else { |
419 g_category_enabled[new_index] = 0; | 448 g_category_enabled[new_index] = 0; |
(...skipping 64 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
484 std::vector<std::string>* included_out, | 513 std::vector<std::string>* included_out, |
485 std::vector<std::string>* excluded_out) { | 514 std::vector<std::string>* excluded_out) { |
486 AutoLock lock(lock_); | 515 AutoLock lock(lock_); |
487 if (enabled_) { | 516 if (enabled_) { |
488 *included_out = included_categories_; | 517 *included_out = included_categories_; |
489 *excluded_out = excluded_categories_; | 518 *excluded_out = excluded_categories_; |
490 } | 519 } |
491 } | 520 } |
492 | 521 |
493 void TraceLog::SetDisabled() { | 522 void TraceLog::SetDisabled() { |
494 { | 523 AutoLock lock(lock_); |
495 AutoLock lock(lock_); | 524 if (!enabled_) |
496 if (!enabled_) | 525 return; |
497 return; | |
498 | 526 |
499 if (dispatching_to_observer_list_) { | 527 if (dispatching_to_observer_list_) { |
500 DLOG(ERROR) | 528 DLOG(ERROR) |
501 << "Cannot manipulate TraceLog::Enabled state from an observer."; | 529 << "Cannot manipulate TraceLog::Enabled state from an observer."; |
502 return; | 530 return; |
503 } | 531 } |
504 | 532 |
505 dispatching_to_observer_list_ = true; | 533 dispatching_to_observer_list_ = true; |
506 FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_, | 534 FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_, |
507 OnTraceLogWillDisable()); | 535 OnTraceLogWillDisable()); |
508 dispatching_to_observer_list_ = false; | 536 dispatching_to_observer_list_ = false; |
509 | 537 |
510 enabled_ = false; | 538 enabled_ = false; |
511 included_categories_.clear(); | 539 included_categories_.clear(); |
512 excluded_categories_.clear(); | 540 excluded_categories_.clear(); |
513 for (int i = 0; i < g_category_index; i++) | 541 watch_category_ = NULL; |
514 g_category_enabled[i] = 0; | 542 watch_event_name_ = ""; |
515 AddThreadNameMetadataEvents(); | 543 for (int i = 0; i < g_category_index; i++) |
516 AddClockSyncMetadataEvents(); | 544 g_category_enabled[i] = 0; |
517 } // release lock | 545 AddThreadNameMetadataEvents(); |
518 Flush(); | 546 AddClockSyncMetadataEvents(); |
519 } | 547 } |
520 | 548 |
521 void TraceLog::SetEnabled(bool enabled) { | 549 void TraceLog::SetEnabled(bool enabled) { |
522 if (enabled) | 550 if (enabled) |
523 SetEnabled(std::vector<std::string>(), std::vector<std::string>()); | 551 SetEnabled(std::vector<std::string>(), std::vector<std::string>()); |
524 else | 552 else |
525 SetDisabled(); | 553 SetDisabled(); |
526 } | 554 } |
527 | 555 |
528 void TraceLog::AddEnabledStateObserver(EnabledStateChangedObserver* listener) { | 556 void TraceLog::AddEnabledStateObserver(EnabledStateChangedObserver* listener) { |
529 enabled_state_observer_list_.AddObserver(listener); | 557 enabled_state_observer_list_.AddObserver(listener); |
530 } | 558 } |
531 | 559 |
532 void TraceLog::RemoveEnabledStateObserver( | 560 void TraceLog::RemoveEnabledStateObserver( |
533 EnabledStateChangedObserver* listener) { | 561 EnabledStateChangedObserver* listener) { |
534 enabled_state_observer_list_.RemoveObserver(listener); | 562 enabled_state_observer_list_.RemoveObserver(listener); |
535 } | 563 } |
536 | 564 |
537 float TraceLog::GetBufferPercentFull() const { | 565 float TraceLog::GetBufferPercentFull() const { |
538 return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize); | 566 return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize); |
539 } | 567 } |
540 | 568 |
541 void TraceLog::SetOutputCallback(const TraceLog::OutputCallback& cb) { | 569 void TraceLog::SetNotificationCallback( |
| 570 const TraceLog::NotificationCallback& cb) { |
542 AutoLock lock(lock_); | 571 AutoLock lock(lock_); |
543 output_callback_ = cb; | 572 notification_callback_ = cb; |
544 } | 573 } |
545 | 574 |
546 void TraceLog::SetBufferFullCallback(const TraceLog::BufferFullCallback& cb) { | 575 void TraceLog::Flush(const TraceLog::OutputCallback& cb) { |
547 AutoLock lock(lock_); | |
548 buffer_full_callback_ = cb; | |
549 } | |
550 | |
551 void TraceLog::Flush() { | |
552 std::vector<TraceEvent> previous_logged_events; | 576 std::vector<TraceEvent> previous_logged_events; |
553 OutputCallback output_callback_copy; | |
554 { | 577 { |
555 AutoLock lock(lock_); | 578 AutoLock lock(lock_); |
556 previous_logged_events.swap(logged_events_); | 579 previous_logged_events.swap(logged_events_); |
557 output_callback_copy = output_callback_; | |
558 } // release lock | 580 } // release lock |
559 | 581 |
560 if (output_callback_copy.is_null()) | |
561 return; | |
562 | |
563 for (size_t i = 0; | 582 for (size_t i = 0; |
564 i < previous_logged_events.size(); | 583 i < previous_logged_events.size(); |
565 i += kTraceEventBatchSize) { | 584 i += kTraceEventBatchSize) { |
566 scoped_refptr<RefCountedString> json_events_str_ptr = | 585 scoped_refptr<RefCountedString> json_events_str_ptr = |
567 new RefCountedString(); | 586 new RefCountedString(); |
568 TraceEvent::AppendEventsAsJSON(previous_logged_events, | 587 TraceEvent::AppendEventsAsJSON(previous_logged_events, |
569 i, | 588 i, |
570 kTraceEventBatchSize, | 589 kTraceEventBatchSize, |
571 &(json_events_str_ptr->data())); | 590 &(json_events_str_ptr->data())); |
572 output_callback_copy.Run(json_events_str_ptr); | 591 cb.Run(json_events_str_ptr); |
573 } | 592 } |
574 } | 593 } |
575 | 594 |
576 int TraceLog::AddTraceEvent(char phase, | 595 int TraceLog::AddTraceEvent(char phase, |
577 const unsigned char* category_enabled, | 596 const unsigned char* category_enabled, |
578 const char* name, | 597 const char* name, |
579 unsigned long long id, | 598 unsigned long long id, |
580 int num_args, | 599 int num_args, |
581 const char** arg_names, | 600 const char** arg_names, |
582 const unsigned char* arg_types, | 601 const unsigned char* arg_types, |
583 const unsigned long long* arg_values, | 602 const unsigned long long* arg_values, |
584 int threshold_begin_id, | 603 int threshold_begin_id, |
585 long long threshold, | 604 long long threshold, |
586 unsigned char flags) { | 605 unsigned char flags) { |
587 DCHECK(name); | 606 DCHECK(name); |
588 TimeTicks now = TimeTicks::NowFromSystemTraceTime(); | 607 TimeTicks now = TimeTicks::NowFromSystemTraceTime(); |
589 BufferFullCallback buffer_full_callback_copy; | 608 NotificationHelper notifier(this); |
590 int ret_begin_id = -1; | 609 int ret_begin_id = -1; |
591 { | 610 { |
592 AutoLock lock(lock_); | 611 AutoLock lock(lock_); |
593 if (!*category_enabled) | 612 if (!*category_enabled) |
594 return -1; | 613 return -1; |
595 if (logged_events_.size() >= kTraceEventBufferSize) | 614 if (logged_events_.size() >= kTraceEventBufferSize) |
596 return -1; | 615 return -1; |
597 | 616 |
598 int thread_id = static_cast<int>(PlatformThread::CurrentId()); | 617 int thread_id = static_cast<int>(PlatformThread::CurrentId()); |
599 | 618 |
(...skipping 45 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
645 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) | 664 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) |
646 id ^= process_id_hash_; | 665 id ^= process_id_hash_; |
647 | 666 |
648 ret_begin_id = static_cast<int>(logged_events_.size()); | 667 ret_begin_id = static_cast<int>(logged_events_.size()); |
649 logged_events_.push_back( | 668 logged_events_.push_back( |
650 TraceEvent(thread_id, | 669 TraceEvent(thread_id, |
651 now, phase, category_enabled, name, id, | 670 now, phase, category_enabled, name, id, |
652 num_args, arg_names, arg_types, arg_values, | 671 num_args, arg_names, arg_types, arg_values, |
653 flags)); | 672 flags)); |
654 | 673 |
655 if (logged_events_.size() == kTraceEventBufferSize) { | 674 if (logged_events_.size() == kTraceEventBufferSize) |
656 buffer_full_callback_copy = buffer_full_callback_; | 675 notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL); |
657 } | 676 |
| 677 if (watch_category_ == category_enabled && watch_event_name_ == name) |
| 678 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); |
658 } // release lock | 679 } // release lock |
659 | 680 |
660 if (!buffer_full_callback_copy.is_null()) | 681 notifier.SendNotificationIfAny(); |
661 buffer_full_callback_copy.Run(); | |
662 | 682 |
663 return ret_begin_id; | 683 return ret_begin_id; |
664 } | 684 } |
665 | 685 |
666 void TraceLog::AddTraceEventEtw(char phase, | 686 void TraceLog::AddTraceEventEtw(char phase, |
667 const char* name, | 687 const char* name, |
668 const void* id, | 688 const void* id, |
669 const char* extra) { | 689 const char* extra) { |
670 #if defined(OS_WIN) | 690 #if defined(OS_WIN) |
671 TraceEventETWProvider::Trace(name, phase, id, extra); | 691 TraceEventETWProvider::Trace(name, phase, id, extra); |
672 #endif | 692 #endif |
673 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, | 693 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, |
674 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); | 694 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); |
675 } | 695 } |
676 | 696 |
677 void TraceLog::AddTraceEventEtw(char phase, | 697 void TraceLog::AddTraceEventEtw(char phase, |
678 const char* name, | 698 const char* name, |
679 const void* id, | 699 const void* id, |
680 const std::string& extra) | 700 const std::string& extra) |
681 { | 701 { |
682 #if defined(OS_WIN) | 702 #if defined(OS_WIN) |
683 TraceEventETWProvider::Trace(name, phase, id, extra); | 703 TraceEventETWProvider::Trace(name, phase, id, extra); |
684 #endif | 704 #endif |
685 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, | 705 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, |
686 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); | 706 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); |
687 } | 707 } |
688 | 708 |
| 709 void TraceLog::SetWatchEvent(const std::string& category_name, |
| 710 const std::string& event_name) { |
| 711 const unsigned char* category = GetCategoryEnabled(category_name.c_str()); |
| 712 int notify_count = 0; |
| 713 { |
| 714 AutoLock lock(lock_); |
| 715 watch_category_ = category; |
| 716 watch_event_name_ = event_name; |
| 717 |
| 718 // First, search existing events for watch event because we want to catch it |
| 719 // even if it has already occurred. |
| 720 for (size_t i = 0u; i < logged_events_.size(); ++i) { |
| 721 if (category == logged_events_[i].category_enabled() && |
| 722 strcmp(event_name.c_str(), logged_events_[i].name()) == 0) { |
| 723 ++notify_count; |
| 724 } |
| 725 } |
| 726 } // release lock |
| 727 |
| 728 // Send notification for each event found. |
| 729 for (int i = 0; i < notify_count; ++i) { |
| 730 NotificationHelper notifier(this); |
| 731 lock_.Acquire(); |
| 732 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); |
| 733 lock_.Release(); |
| 734 notifier.SendNotificationIfAny(); |
| 735 } |
| 736 } |
| 737 |
| 738 void TraceLog::CancelWatchEvent() { |
| 739 AutoLock lock(lock_); |
| 740 watch_category_ = NULL; |
| 741 watch_event_name_ = ""; |
| 742 } |
| 743 |
689 void TraceLog::AddClockSyncMetadataEvents() { | 744 void TraceLog::AddClockSyncMetadataEvents() { |
690 #if defined(OS_ANDROID) | 745 #if defined(OS_ANDROID) |
691 // Since Android does not support sched_setaffinity, we cannot establish clock | 746 // Since Android does not support sched_setaffinity, we cannot establish clock |
692 // sync unless the scheduler clock is set to global. If the trace_clock file | 747 // sync unless the scheduler clock is set to global. If the trace_clock file |
693 // can't be read, we will assume the kernel doesn't support tracing and do | 748 // can't be read, we will assume the kernel doesn't support tracing and do |
694 // nothing. | 749 // nothing. |
695 std::string clock_mode; | 750 std::string clock_mode; |
696 if (!file_util::ReadFileToString( | 751 if (!file_util::ReadFileToString( |
697 FilePath("/sys/kernel/debug/tracing/trace_clock"), | 752 FilePath("/sys/kernel/debug/tracing/trace_clock"), |
698 &clock_mode)) | 753 &clock_mode)) |
(...skipping 61 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
760 // Create a FNV hash from the process ID for XORing. | 815 // Create a FNV hash from the process ID for XORing. |
761 // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details. | 816 // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details. |
762 unsigned long long offset_basis = 14695981039346656037ull; | 817 unsigned long long offset_basis = 14695981039346656037ull; |
763 unsigned long long fnv_prime = 1099511628211ull; | 818 unsigned long long fnv_prime = 1099511628211ull; |
764 unsigned long long pid = static_cast<unsigned long long>(process_id_); | 819 unsigned long long pid = static_cast<unsigned long long>(process_id_); |
765 process_id_hash_ = (offset_basis ^ pid) * fnv_prime; | 820 process_id_hash_ = (offset_basis ^ pid) * fnv_prime; |
766 } | 821 } |
767 | 822 |
768 } // namespace debug | 823 } // namespace debug |
769 } // namespace base | 824 } // namespace base |
OLD | NEW |