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/leak_annotations.h" |
11 #include "base/debug/trace_event.h" | 11 #include "base/debug/trace_event.h" |
12 #include "base/format_macros.h" | 12 #include "base/format_macros.h" |
13 #include "base/lazy_instance.h" | 13 #include "base/lazy_instance.h" |
14 #include "base/memory/singleton.h" | 14 #include "base/memory/singleton.h" |
15 #include "base/process_util.h" | 15 #include "base/process_util.h" |
16 #include "base/stl_util.h" | 16 #include "base/stl_util.h" |
17 #include "base/stringprintf.h" | 17 #include "base/stringprintf.h" |
18 #include "base/string_tokenizer.h" | 18 #include "base/string_tokenizer.h" |
19 #include "base/string_util.h" | 19 #include "base/string_util.h" |
20 #include "base/sys_info.h" | 20 #include "base/sys_info.h" |
21 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" | 21 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" |
22 #include "base/threading/platform_thread.h" | 22 #include "base/threading/platform_thread.h" |
| 23 #include "base/threading/thread_id_name_manager.h" |
23 #include "base/threading/thread_local.h" | 24 #include "base/threading/thread_local.h" |
24 #include "base/time.h" | 25 #include "base/time.h" |
25 #include "base/utf_string_conversions.h" | 26 #include "base/utf_string_conversions.h" |
26 | 27 |
27 #if defined(OS_WIN) | 28 #if defined(OS_WIN) |
28 #include "base/debug/trace_event_win.h" | 29 #include "base/debug/trace_event_win.h" |
29 #endif | 30 #endif |
30 | 31 |
31 class DeleteTraceLogForTesting { | 32 class DeleteTraceLogForTesting { |
32 public: | 33 public: |
(...skipping 569 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
602 scoped_refptr<RefCountedString> json_events_str_ptr = | 603 scoped_refptr<RefCountedString> json_events_str_ptr = |
603 new RefCountedString(); | 604 new RefCountedString(); |
604 TraceEvent::AppendEventsAsJSON(previous_logged_events, | 605 TraceEvent::AppendEventsAsJSON(previous_logged_events, |
605 i, | 606 i, |
606 kTraceEventBatchSize, | 607 kTraceEventBatchSize, |
607 &(json_events_str_ptr->data())); | 608 &(json_events_str_ptr->data())); |
608 cb.Run(json_events_str_ptr); | 609 cb.Run(json_events_str_ptr); |
609 } | 610 } |
610 } | 611 } |
611 | 612 |
| 613 int TraceLog::AddTraceEventExplicit(char phase, |
| 614 const unsigned char* category_enabled, |
| 615 const char* name, |
| 616 int thread_id, |
| 617 int64 timestamp, |
| 618 unsigned long long id, |
| 619 int num_args, |
| 620 const char** arg_names, |
| 621 const unsigned char* arg_types, |
| 622 const unsigned long long* arg_values, |
| 623 int threshold_begin_id, |
| 624 long long threshold, |
| 625 unsigned char flags) { |
| 626 DCHECK(name); |
| 627 TimeTicks now = TimeTicks::FromInternalValue(timestamp); |
| 628 NotificationHelper notifier(this); |
| 629 |
| 630 int ret_begin_id = AddTraceEventInternal(notifier, now, phase, |
| 631 category_enabled, name, thread_id, |
| 632 id, num_args, arg_names, arg_types, |
| 633 arg_values, threshold_begin_id, |
| 634 threshold, flags); |
| 635 |
| 636 notifier.SendNotificationIfAny(); |
| 637 |
| 638 return ret_begin_id; |
| 639 } |
| 640 |
612 int TraceLog::AddTraceEvent(char phase, | 641 int TraceLog::AddTraceEvent(char phase, |
613 const unsigned char* category_enabled, | 642 const unsigned char* category_enabled, |
614 const char* name, | 643 const char* name, |
615 unsigned long long id, | 644 unsigned long long id, |
616 int num_args, | 645 int num_args, |
617 const char** arg_names, | 646 const char** arg_names, |
618 const unsigned char* arg_types, | 647 const unsigned char* arg_types, |
619 const unsigned long long* arg_values, | 648 const unsigned long long* arg_values, |
620 int threshold_begin_id, | 649 int threshold_begin_id, |
621 long long threshold, | 650 long long threshold, |
622 unsigned char flags) { | 651 unsigned char flags) { |
623 DCHECK(name); | 652 DCHECK(name); |
624 | 653 |
625 #if defined(OS_ANDROID) | 654 #if defined(OS_ANDROID) |
626 SendToATrace(phase, GetCategoryName(category_enabled), name, | 655 SendToATrace(phase, GetCategoryName(category_enabled), name, |
627 num_args, arg_names, arg_types, arg_values); | 656 num_args, arg_names, arg_types, arg_values); |
628 #endif | 657 #endif |
629 | 658 |
630 TimeTicks now = TimeTicks::NowFromSystemTraceTime(); | 659 TimeTicks now = TimeTicks::NowFromSystemTraceTime(); |
631 NotificationHelper notifier(this); | 660 NotificationHelper notifier(this); |
632 int ret_begin_id = -1; | |
633 { | |
634 AutoLock lock(lock_); | |
635 if (*category_enabled != CATEGORY_ENABLED) | |
636 return -1; | |
637 if (logged_events_.size() >= kTraceEventBufferSize) | |
638 return -1; | |
639 | 661 |
640 int thread_id = static_cast<int>(PlatformThread::CurrentId()); | 662 int thread_id = static_cast<int>(PlatformThread::CurrentId()); |
641 | 663 int ret_begin_id = AddTraceEventInternal(notifier, now, phase, |
642 const char* new_name = PlatformThread::GetName(); | 664 category_enabled, name, thread_id, |
643 // Check if the thread name has been set or changed since the previous | 665 id, num_args, arg_names, arg_types, |
644 // call (if any), but don't bother if the new name is empty. Note this will | 666 arg_values, threshold_begin_id, |
645 // not detect a thread name change within the same char* buffer address: we | 667 threshold, flags); |
646 // favor common case performance over corner case correctness. | |
647 if (new_name != g_current_thread_name.Get().Get() && | |
648 new_name && *new_name) { | |
649 g_current_thread_name.Get().Set(new_name); | |
650 base::hash_map<int, std::string>::iterator existing_name = | |
651 thread_names_.find(thread_id); | |
652 if (existing_name == thread_names_.end()) { | |
653 // This is a new thread id, and a new name. | |
654 thread_names_[thread_id] = new_name; | |
655 } else { | |
656 // This is a thread id that we've seen before, but potentially with a | |
657 // new name. | |
658 std::vector<base::StringPiece> existing_names; | |
659 Tokenize(existing_name->second, ",", &existing_names); | |
660 bool found = std::find(existing_names.begin(), | |
661 existing_names.end(), | |
662 new_name) != existing_names.end(); | |
663 if (!found) { | |
664 existing_name->second.push_back(','); | |
665 existing_name->second.append(new_name); | |
666 } | |
667 } | |
668 } | |
669 | |
670 if (threshold_begin_id > -1) { | |
671 DCHECK(phase == TRACE_EVENT_PHASE_END); | |
672 size_t begin_i = static_cast<size_t>(threshold_begin_id); | |
673 // Return now if there has been a flush since the begin event was posted. | |
674 if (begin_i >= logged_events_.size()) | |
675 return -1; | |
676 // Determine whether to drop the begin/end pair. | |
677 TimeDelta elapsed = now - logged_events_[begin_i].timestamp(); | |
678 if (elapsed < TimeDelta::FromMicroseconds(threshold)) { | |
679 // Remove begin event and do not add end event. | |
680 // This will be expensive if there have been other events in the | |
681 // mean time (should be rare). | |
682 logged_events_.erase(logged_events_.begin() + begin_i); | |
683 return -1; | |
684 } | |
685 } | |
686 | |
687 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) | |
688 id ^= process_id_hash_; | |
689 | |
690 ret_begin_id = static_cast<int>(logged_events_.size()); | |
691 logged_events_.push_back( | |
692 TraceEvent(thread_id, | |
693 now, phase, category_enabled, name, id, | |
694 num_args, arg_names, arg_types, arg_values, | |
695 flags)); | |
696 | |
697 if (logged_events_.size() == kTraceEventBufferSize) | |
698 notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL); | |
699 | |
700 if (watch_category_ == category_enabled && watch_event_name_ == name) | |
701 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); | |
702 } // release lock | |
703 | 668 |
704 notifier.SendNotificationIfAny(); | 669 notifier.SendNotificationIfAny(); |
705 | 670 |
706 return ret_begin_id; | 671 return ret_begin_id; |
707 } | 672 } |
| 673 |
| 674 int TraceLog::AddTraceEventInternal(NotificationHelper& notifier, |
| 675 TimeTicks timestamp, |
| 676 char phase, |
| 677 const unsigned char* category_enabled, |
| 678 const char* name, |
| 679 int thread_id, |
| 680 unsigned long long id, |
| 681 int num_args, |
| 682 const char** arg_names, |
| 683 const unsigned char* arg_types, |
| 684 const unsigned long long* arg_values, |
| 685 int threshold_begin_id, |
| 686 long long threshold, |
| 687 unsigned char flags) { |
| 688 AutoLock lock(lock_); |
| 689 if (*category_enabled != CATEGORY_ENABLED) |
| 690 return -1; |
| 691 if (logged_events_.size() >= kTraceEventBufferSize) |
| 692 return -1; |
| 693 |
| 694 const char* new_name = ThreadIdNameManager::GetInstance()-> |
| 695 GetNameForId(thread_id); |
| 696 |
| 697 // Check if the thread name has been set or changed since the previous |
| 698 // call (if any), but don't bother if the new name is empty. Note this will |
| 699 // not detect a thread name change within the same char* buffer address: we |
| 700 // favor common case performance over corner case correctness. |
| 701 if (new_name != g_current_thread_name.Get().Get() && new_name && *new_name) { |
| 702 g_current_thread_name.Get().Set(new_name); |
| 703 base::hash_map<int, std::string>::iterator existing_name = |
| 704 thread_names_.find(thread_id); |
| 705 if (existing_name == thread_names_.end()) { |
| 706 // This is a new thread id, and a new name. |
| 707 thread_names_[thread_id] = new_name; |
| 708 } else { |
| 709 // This is a thread id that we've seen before, but potentially with a |
| 710 // new name. |
| 711 std::vector<base::StringPiece> existing_names; |
| 712 Tokenize(existing_name->second, ",", &existing_names); |
| 713 bool found = std::find(existing_names.begin(), |
| 714 existing_names.end(), |
| 715 new_name) != existing_names.end(); |
| 716 if (!found) { |
| 717 existing_name->second.push_back(','); |
| 718 existing_name->second.append(new_name); |
| 719 } |
| 720 } |
| 721 } |
| 722 |
| 723 if (threshold_begin_id > -1) { |
| 724 DCHECK(phase == TRACE_EVENT_PHASE_END); |
| 725 size_t begin_i = static_cast<size_t>(threshold_begin_id); |
| 726 // Return now if there has been a flush since the begin event was posted. |
| 727 if (begin_i >= logged_events_.size()) |
| 728 return -1; |
| 729 // Determine whether to drop the begin/end pair. |
| 730 TimeDelta elapsed = timestamp - logged_events_[begin_i].timestamp(); |
| 731 if (elapsed < TimeDelta::FromMicroseconds(threshold)) { |
| 732 // Remove begin event and do not add end event. |
| 733 // This will be expensive if there have been other events in the |
| 734 // mean time (should be rare). |
| 735 logged_events_.erase(logged_events_.begin() + begin_i); |
| 736 return -1; |
| 737 } |
| 738 } |
| 739 |
| 740 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) |
| 741 id ^= process_id_hash_; |
| 742 |
| 743 int ret_begin_id = static_cast<int>(logged_events_.size()); |
| 744 logged_events_.push_back( |
| 745 TraceEvent(thread_id, |
| 746 timestamp, phase, category_enabled, name, id, |
| 747 num_args, arg_names, arg_types, arg_values, |
| 748 flags)); |
| 749 |
| 750 if (logged_events_.size() == kTraceEventBufferSize) |
| 751 notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL); |
| 752 |
| 753 if (watch_category_ == category_enabled && watch_event_name_ == name) |
| 754 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); |
| 755 |
| 756 return ret_begin_id; |
| 757 } |
708 | 758 |
709 void TraceLog::AddTraceEventEtw(char phase, | 759 void TraceLog::AddTraceEventEtw(char phase, |
710 const char* name, | 760 const char* name, |
711 const void* id, | 761 const void* id, |
712 const char* extra) { | 762 const char* extra) { |
713 #if defined(OS_WIN) | 763 #if defined(OS_WIN) |
714 TraceEventETWProvider::Trace(name, phase, id, extra); | 764 TraceEventETWProvider::Trace(name, phase, id, extra); |
715 #endif | 765 #endif |
716 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, | 766 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, |
717 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); | 767 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); |
(...skipping 81 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
799 // Create a FNV hash from the process ID for XORing. | 849 // Create a FNV hash from the process ID for XORing. |
800 // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details. | 850 // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details. |
801 unsigned long long offset_basis = 14695981039346656037ull; | 851 unsigned long long offset_basis = 14695981039346656037ull; |
802 unsigned long long fnv_prime = 1099511628211ull; | 852 unsigned long long fnv_prime = 1099511628211ull; |
803 unsigned long long pid = static_cast<unsigned long long>(process_id_); | 853 unsigned long long pid = static_cast<unsigned long long>(process_id_); |
804 process_id_hash_ = (offset_basis ^ pid) * fnv_prime; | 854 process_id_hash_ = (offset_basis ^ pid) * fnv_prime; |
805 } | 855 } |
806 | 856 |
807 } // namespace debug | 857 } // namespace debug |
808 } // namespace base | 858 } // namespace base |
OLD | NEW |