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/base_switches.h" | 9 #include "base/base_switches.h" |
10 #include "base/bind.h" | 10 #include "base/bind.h" |
11 #include "base/command_line.h" | 11 #include "base/command_line.h" |
12 #include "base/debug/leak_annotations.h" | 12 #include "base/debug/leak_annotations.h" |
13 #include "base/debug/trace_event.h" | 13 #include "base/debug/trace_event.h" |
14 #include "base/format_macros.h" | 14 #include "base/format_macros.h" |
15 #include "base/lazy_instance.h" | 15 #include "base/lazy_instance.h" |
16 #include "base/memory/singleton.h" | 16 #include "base/memory/singleton.h" |
17 #include "base/message_loop/message_loop.h" | |
17 #include "base/process/process_metrics.h" | 18 #include "base/process/process_metrics.h" |
18 #include "base/stl_util.h" | 19 #include "base/stl_util.h" |
19 #include "base/strings/string_split.h" | 20 #include "base/strings/string_split.h" |
20 #include "base/strings/string_tokenizer.h" | 21 #include "base/strings/string_tokenizer.h" |
21 #include "base/strings/string_util.h" | 22 #include "base/strings/string_util.h" |
22 #include "base/strings/stringprintf.h" | 23 #include "base/strings/stringprintf.h" |
23 #include "base/strings/utf_string_conversions.h" | 24 #include "base/strings/utf_string_conversions.h" |
24 #include "base/synchronization/cancellation_flag.h" | 25 #include "base/synchronization/cancellation_flag.h" |
25 #include "base/synchronization/waitable_event.h" | 26 #include "base/synchronization/waitable_event.h" |
26 #include "base/sys_info.h" | 27 #include "base/sys_info.h" |
27 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" | 28 #include "base/third_party/dynamic_annotations/dynamic_annotations.h" |
28 #include "base/threading/platform_thread.h" | 29 #include "base/threading/platform_thread.h" |
29 #include "base/threading/thread_id_name_manager.h" | 30 #include "base/threading/thread_id_name_manager.h" |
30 #include "base/threading/thread_local.h" | |
31 #include "base/time/time.h" | 31 #include "base/time/time.h" |
32 | 32 |
33 #if defined(OS_WIN) | 33 #if defined(OS_WIN) |
34 #include "base/debug/trace_event_win.h" | 34 #include "base/debug/trace_event_win.h" |
35 #endif | 35 #endif |
36 | 36 |
37 class DeleteTraceLogForTesting { | 37 class DeleteTraceLogForTesting { |
38 public: | 38 public: |
39 static void Delete() { | 39 static void Delete() { |
40 Singleton<base::debug::TraceLog, | 40 Singleton<base::debug::TraceLog, |
41 LeakySingletonTraits<base::debug::TraceLog> >::OnExit(0); | 41 LeakySingletonTraits<base::debug::TraceLog> >::OnExit(0); |
42 } | 42 } |
43 }; | 43 }; |
44 | 44 |
45 // The thread buckets for the sampling profiler. | 45 // The thread buckets for the sampling profiler. |
46 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3]; | 46 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3]; |
47 | 47 |
48 namespace base { | 48 namespace base { |
49 namespace debug { | 49 namespace debug { |
50 | 50 |
51 namespace { | |
52 | |
51 // Controls the number of trace events we will buffer in-memory | 53 // Controls the number of trace events we will buffer in-memory |
52 // before throwing them away. | 54 // before throwing them away. |
53 const size_t kTraceEventBufferSize = 500000; | 55 const size_t kTraceEventBufferSize = 500000; |
56 const size_t kTraceEventThreadLocalBufferSize = 1024; | |
54 const size_t kTraceEventBatchSize = 1000; | 57 const size_t kTraceEventBatchSize = 1000; |
55 const size_t kTraceEventInitialBufferSize = 1024; | 58 const size_t kTraceEventInitialBufferSize = 1024; |
56 | 59 |
57 #define MAX_CATEGORY_GROUPS 100 | 60 #define MAX_CATEGORY_GROUPS 100 |
58 | 61 |
59 namespace { | |
60 | |
61 // Parallel arrays g_category_groups and g_category_group_enabled are separate | 62 // Parallel arrays g_category_groups and g_category_group_enabled are separate |
62 // so that a pointer to a member of g_category_group_enabled can be easily | 63 // so that a pointer to a member of g_category_group_enabled can be easily |
63 // converted to an index into g_category_groups. This allows macros to deal | 64 // converted to an index into g_category_groups. This allows macros to deal |
64 // only with char enabled pointers from g_category_group_enabled, and we can | 65 // only with char enabled pointers from g_category_group_enabled, and we can |
65 // convert internally to determine the category name from the char enabled | 66 // convert internally to determine the category name from the char enabled |
66 // pointer. | 67 // pointer. |
67 const char* g_category_groups[MAX_CATEGORY_GROUPS] = { | 68 const char* g_category_groups[MAX_CATEGORY_GROUPS] = { |
68 "tracing already shutdown", | 69 "tracing already shutdown", |
69 "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS", | 70 "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS", |
70 "__metadata", | 71 "__metadata", |
(...skipping 17 matching lines...) Expand all Loading... | |
88 const char kRecordContinuously[] = "record-continuously"; | 89 const char kRecordContinuously[] = "record-continuously"; |
89 const char kEnableSampling[] = "enable-sampling"; | 90 const char kEnableSampling[] = "enable-sampling"; |
90 | 91 |
91 size_t NextIndex(size_t index) { | 92 size_t NextIndex(size_t index) { |
92 index++; | 93 index++; |
93 if (index >= kTraceEventBufferSize) | 94 if (index >= kTraceEventBufferSize) |
94 index = 0; | 95 index = 0; |
95 return index; | 96 return index; |
96 } | 97 } |
97 | 98 |
98 } // namespace | |
99 | |
100 class TraceBufferRingBuffer : public TraceBuffer { | 99 class TraceBufferRingBuffer : public TraceBuffer { |
101 public: | 100 public: |
102 TraceBufferRingBuffer() | 101 TraceBufferRingBuffer() |
103 : unused_event_index_(0), | 102 : unused_event_index_(0), |
104 oldest_event_index_(0) { | 103 oldest_event_index_(0) { |
105 logged_events_.reserve(kTraceEventInitialBufferSize); | 104 logged_events_.reserve(kTraceEventInitialBufferSize); |
106 } | 105 } |
107 | 106 |
108 virtual ~TraceBufferRingBuffer() {} | 107 virtual ~TraceBufferRingBuffer() {} |
109 | 108 |
(...skipping 140 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
250 } | 249 } |
251 | 250 |
252 virtual size_t Size() const OVERRIDE { return 0; } | 251 virtual size_t Size() const OVERRIDE { return 0; } |
253 | 252 |
254 virtual const TraceEvent& GetEventAt(size_t index) const OVERRIDE { | 253 virtual const TraceEvent& GetEventAt(size_t index) const OVERRIDE { |
255 NOTREACHED(); | 254 NOTREACHED(); |
256 return *static_cast<TraceEvent*>(NULL); | 255 return *static_cast<TraceEvent*>(NULL); |
257 } | 256 } |
258 }; | 257 }; |
259 | 258 |
259 } // namespace | |
260 | |
260 //////////////////////////////////////////////////////////////////////////////// | 261 //////////////////////////////////////////////////////////////////////////////// |
261 // | 262 // |
262 // TraceEvent | 263 // TraceEvent |
263 // | 264 // |
264 //////////////////////////////////////////////////////////////////////////////// | 265 //////////////////////////////////////////////////////////////////////////////// |
265 | 266 |
266 namespace { | 267 namespace { |
267 | 268 |
268 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; } | 269 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; } |
269 | 270 |
(...skipping 464 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
734 | 735 |
735 TraceBucketData::~TraceBucketData() { | 736 TraceBucketData::~TraceBucketData() { |
736 } | 737 } |
737 | 738 |
738 //////////////////////////////////////////////////////////////////////////////// | 739 //////////////////////////////////////////////////////////////////////////////// |
739 // | 740 // |
740 // TraceLog | 741 // TraceLog |
741 // | 742 // |
742 //////////////////////////////////////////////////////////////////////////////// | 743 //////////////////////////////////////////////////////////////////////////////// |
743 | 744 |
745 class TraceLog::ThreadLocalEventBuffer | |
746 : public MessageLoop::DestructionObserver { | |
747 public: | |
748 ThreadLocalEventBuffer(TraceLog* trace_log); | |
749 virtual ~ThreadLocalEventBuffer(); | |
750 | |
751 bool AddEvent(const TraceEvent& event, NotificationHelper* notifier); | |
752 | |
753 private: | |
754 // MessageLoop::DestructionObserver | |
755 virtual void WillDestroyCurrentMessageLoop() OVERRIDE; | |
756 | |
757 bool FlushWhileLocked(NotificationHelper* notifier); | |
758 | |
759 void CheckThread() { | |
760 DCHECK(trace_log_->thread_local_event_buffer_.Get() == this); | |
761 } | |
762 | |
763 TraceLog* trace_log_; | |
764 std::vector<TraceEvent> logged_events_; | |
765 }; | |
dsinclair
2013/08/13 21:04:42
DISABLE_COPY_AND_ASSIGN?
Xianzhu
2013/08/14 21:28:33
Done.
| |
766 | |
767 TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log) | |
768 : trace_log_(trace_log) { | |
769 logged_events_.reserve(kTraceEventThreadLocalBufferSize); | |
770 | |
771 MessageLoop* message_loop = MessageLoop::current(); | |
772 DCHECK(message_loop); | |
773 message_loop->AddDestructionObserver(this); | |
774 | |
775 AutoLock lock(trace_log->lock_); | |
776 trace_log->thread_message_loops_.insert(message_loop); | |
777 } | |
778 | |
779 TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() { | |
780 CheckThread(); | |
781 NotificationHelper notifier(trace_log_); | |
782 { | |
783 AutoLock lock(trace_log_->lock_); | |
784 FlushWhileLocked(¬ifier); | |
785 trace_log_->thread_message_loops_.erase(MessageLoop::current()); | |
786 if (trace_log_->flush_message_loop_) { | |
787 trace_log_->flush_message_loop_->PostTask( | |
788 FROM_HERE, | |
789 Bind(&TraceLog::FlushNextThreadOrFinish, Unretained(trace_log_))); | |
790 } | |
791 } | |
792 notifier.SendNotificationIfAny(); | |
793 trace_log_->thread_local_event_buffer_.Set(NULL); | |
794 } | |
795 | |
796 bool TraceLog::ThreadLocalEventBuffer::AddEvent(const TraceEvent& event, | |
797 NotificationHelper* notifier) { | |
798 CheckThread(); | |
799 logged_events_.push_back(event); | |
800 if (logged_events_.size() >= kTraceEventThreadLocalBufferSize) { | |
801 AutoLock lock(trace_log_->lock_); | |
802 return FlushWhileLocked(notifier); | |
803 } | |
804 return true; | |
805 } | |
806 | |
807 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() { | |
808 delete this; | |
809 } | |
810 | |
811 bool TraceLog::ThreadLocalEventBuffer::FlushWhileLocked( | |
812 NotificationHelper* notifier) { | |
813 bool success = true; | |
814 for (size_t i = 0; i < logged_events_.size(); ++i) { | |
815 success = trace_log_->AddEventToMainBufferWhileLocked(logged_events_[i], | |
816 notifier); | |
817 if (!success) | |
818 break; | |
819 } | |
820 logged_events_.resize(0); | |
821 return success; | |
822 } | |
823 | |
744 TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log) | 824 TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log) |
745 : trace_log_(trace_log), | 825 : trace_log_(trace_log), |
746 notification_(0) { | 826 notification_(0) { |
747 } | 827 } |
748 | 828 |
749 TraceLog::NotificationHelper::~NotificationHelper() { | 829 TraceLog::NotificationHelper::~NotificationHelper() { |
750 } | 830 } |
751 | 831 |
752 void TraceLog::NotificationHelper::AddNotificationWhileLocked( | 832 void TraceLog::NotificationHelper::AddNotificationWhileLocked( |
753 int notification) { | 833 int notification) { |
834 trace_log_->lock_.AssertAcquired(); | |
754 if (trace_log_->notification_callback_.is_null()) | 835 if (trace_log_->notification_callback_.is_null()) |
755 return; | 836 return; |
756 if (notification_ == 0) | 837 if (notification_ == 0) |
757 callback_copy_ = trace_log_->notification_callback_; | 838 callback_copy_ = trace_log_->notification_callback_; |
758 notification_ |= notification; | 839 notification_ |= notification; |
759 } | 840 } |
760 | 841 |
761 void TraceLog::NotificationHelper::SendNotificationIfAny() { | 842 void TraceLog::NotificationHelper::SendNotificationIfAny() { |
762 if (notification_) | 843 if (notification_) |
763 callback_copy_.Run(notification_); | 844 callback_copy_.Run(notification_); |
(...skipping 23 matching lines...) Expand all Loading... | |
787 } else { | 868 } else { |
788 NOTREACHED(); // Unknown option provided. | 869 NOTREACHED(); // Unknown option provided. |
789 } | 870 } |
790 } | 871 } |
791 if (!(ret & RECORD_UNTIL_FULL) && !(ret & RECORD_CONTINUOUSLY)) | 872 if (!(ret & RECORD_UNTIL_FULL) && !(ret & RECORD_CONTINUOUSLY)) |
792 ret |= RECORD_UNTIL_FULL; // Default when no options are specified. | 873 ret |= RECORD_UNTIL_FULL; // Default when no options are specified. |
793 | 874 |
794 return static_cast<Options>(ret); | 875 return static_cast<Options>(ret); |
795 } | 876 } |
796 | 877 |
878 namespace { | |
879 | |
880 struct EchoToConsoleContext { | |
881 hash_map<int, std::stack<TimeTicks> > thread_event_start_times; | |
882 hash_map<std::string, int> thread_colors; | |
883 }; | |
884 | |
885 } // namespace | |
886 | |
797 TraceLog::TraceLog() | 887 TraceLog::TraceLog() |
798 : enable_count_(0), | 888 : enable_count_(0), |
799 num_traces_recorded_(0), | 889 num_traces_recorded_(0), |
800 event_callback_(NULL), | 890 buffer_is_full_(0), |
891 event_callback_(0), | |
801 dispatching_to_observer_list_(false), | 892 dispatching_to_observer_list_(false), |
802 process_sort_index_(0), | 893 process_sort_index_(0), |
803 watch_category_(NULL), | 894 echo_to_console_context_(0), |
895 process_id_hash_(0), | |
896 process_id_(0), | |
897 watch_category_(0), | |
804 trace_options_(RECORD_UNTIL_FULL), | 898 trace_options_(RECORD_UNTIL_FULL), |
805 sampling_thread_handle_(0), | 899 sampling_thread_handle_(0), |
806 category_filter_(CategoryFilter::kDefaultCategoryFilterString) { | 900 category_filter_(CategoryFilter::kDefaultCategoryFilterString), |
901 flush_message_loop_(NULL) { | |
807 // Trace is enabled or disabled on one thread while other threads are | 902 // Trace is enabled or disabled on one thread while other threads are |
808 // accessing the enabled flag. We don't care whether edge-case events are | 903 // accessing the enabled flag. We don't care whether edge-case events are |
809 // traced or not, so we allow races on the enabled flag to keep the trace | 904 // traced or not, so we allow races on the enabled flag to keep the trace |
810 // macros fast. | 905 // macros fast. |
811 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots: | 906 // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots: |
812 // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled, | 907 // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled, |
813 // sizeof(g_category_group_enabled), | 908 // sizeof(g_category_group_enabled), |
814 // "trace_event category enabled"); | 909 // "trace_event category enabled"); |
815 for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) { | 910 for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) { |
816 ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i], | 911 ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i], |
(...skipping 15 matching lines...) Expand all Loading... | |
832 category_string = "*"; | 927 category_string = "*"; |
833 | 928 |
834 SetEnabled(CategoryFilter(category_string), ECHO_TO_CONSOLE); | 929 SetEnabled(CategoryFilter(category_string), ECHO_TO_CONSOLE); |
835 } | 930 } |
836 #endif | 931 #endif |
837 | 932 |
838 logged_events_.reset(GetTraceBuffer()); | 933 logged_events_.reset(GetTraceBuffer()); |
839 } | 934 } |
840 | 935 |
841 TraceLog::~TraceLog() { | 936 TraceLog::~TraceLog() { |
937 delete reinterpret_cast<EchoToConsoleContext*>(echo_to_console_context_); | |
842 } | 938 } |
843 | 939 |
844 const unsigned char* TraceLog::GetCategoryGroupEnabled( | 940 const unsigned char* TraceLog::GetCategoryGroupEnabled( |
845 const char* category_group) { | 941 const char* category_group) { |
846 TraceLog* tracelog = GetInstance(); | 942 TraceLog* tracelog = GetInstance(); |
847 if (!tracelog) { | 943 if (!tracelog) { |
848 DCHECK(!g_category_group_enabled[g_category_already_shutdown]); | 944 DCHECK(!g_category_group_enabled[g_category_already_shutdown]); |
849 return &g_category_group_enabled[g_category_already_shutdown]; | 945 return &g_category_group_enabled[g_category_already_shutdown]; |
850 } | 946 } |
851 return tracelog->GetCategoryGroupEnabledInternal(category_group); | 947 return tracelog->GetCategoryGroupEnabledInternal(category_group); |
(...skipping 102 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
954 << "set of options."; | 1050 << "set of options."; |
955 } | 1051 } |
956 | 1052 |
957 category_filter_.Merge(category_filter); | 1053 category_filter_.Merge(category_filter); |
958 UpdateCategoryGroupEnabledFlags(); | 1054 UpdateCategoryGroupEnabledFlags(); |
959 return; | 1055 return; |
960 } | 1056 } |
961 | 1057 |
962 if (options != trace_options_) { | 1058 if (options != trace_options_) { |
963 trace_options_ = options; | 1059 trace_options_ = options; |
1060 EnableEchoToConsole(options & ECHO_TO_CONSOLE); | |
964 logged_events_.reset(GetTraceBuffer()); | 1061 logged_events_.reset(GetTraceBuffer()); |
1062 subtle::NoBarrier_Store(&buffer_is_full_, 0); | |
965 } | 1063 } |
966 | 1064 |
967 if (dispatching_to_observer_list_) { | 1065 if (dispatching_to_observer_list_) { |
968 DLOG(ERROR) << | 1066 DLOG(ERROR) << |
969 "Cannot manipulate TraceLog::Enabled state from an observer."; | 1067 "Cannot manipulate TraceLog::Enabled state from an observer."; |
970 return; | 1068 return; |
971 } | 1069 } |
972 | 1070 |
973 num_traces_recorded_++; | 1071 num_traces_recorded_++; |
974 | 1072 |
(...skipping 57 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
1032 // Stop the sampling thread. | 1130 // Stop the sampling thread. |
1033 sampling_thread_->Stop(); | 1131 sampling_thread_->Stop(); |
1034 lock_.Release(); | 1132 lock_.Release(); |
1035 PlatformThread::Join(sampling_thread_handle_); | 1133 PlatformThread::Join(sampling_thread_handle_); |
1036 lock_.Acquire(); | 1134 lock_.Acquire(); |
1037 sampling_thread_handle_ = PlatformThreadHandle(); | 1135 sampling_thread_handle_ = PlatformThreadHandle(); |
1038 sampling_thread_.reset(); | 1136 sampling_thread_.reset(); |
1039 } | 1137 } |
1040 | 1138 |
1041 category_filter_.Clear(); | 1139 category_filter_.Clear(); |
1042 watch_category_ = NULL; | 1140 subtle::NoBarrier_Store(&watch_category_, 0); |
1043 watch_event_name_ = ""; | 1141 watch_event_name_ = ""; |
1044 UpdateCategoryGroupEnabledFlags(); | 1142 UpdateCategoryGroupEnabledFlags(); |
1045 AddMetadataEvents(); | 1143 AddMetadataEvents(); |
1046 | 1144 |
1047 dispatching_to_observer_list_ = true; | 1145 dispatching_to_observer_list_ = true; |
1048 observer_list = enabled_state_observer_list_; | 1146 observer_list = enabled_state_observer_list_; |
1049 } | 1147 } |
1050 | 1148 |
1051 // Dispatch to observers outside the lock in case the observer triggers a | 1149 // Dispatch to observers outside the lock in case the observer triggers a |
1052 // trace event. | 1150 // trace event. |
(...skipping 45 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
1098 } | 1196 } |
1099 | 1197 |
1100 TraceBuffer* TraceLog::GetTraceBuffer() { | 1198 TraceBuffer* TraceLog::GetTraceBuffer() { |
1101 if (trace_options_ & RECORD_CONTINUOUSLY) | 1199 if (trace_options_ & RECORD_CONTINUOUSLY) |
1102 return new TraceBufferRingBuffer(); | 1200 return new TraceBufferRingBuffer(); |
1103 else if (trace_options_ & ECHO_TO_CONSOLE) | 1201 else if (trace_options_ & ECHO_TO_CONSOLE) |
1104 return new TraceBufferDiscardsEvents(); | 1202 return new TraceBufferDiscardsEvents(); |
1105 return new TraceBufferVector(); | 1203 return new TraceBufferVector(); |
1106 } | 1204 } |
1107 | 1205 |
1206 bool TraceLog::AddEventToMainBufferWhileLocked(const TraceEvent& trace_event, | |
1207 NotificationHelper* notifier) { | |
1208 lock_.AssertAcquired(); | |
1209 logged_events_->AddEvent(trace_event); | |
1210 if (logged_events_->IsFull()) { | |
1211 subtle::NoBarrier_Store(&buffer_is_full_, | |
1212 static_cast<subtle::AtomicWord>(1)); | |
1213 notifier->AddNotificationWhileLocked(TRACE_BUFFER_FULL); | |
1214 return false; | |
1215 } | |
1216 return true; | |
1217 } | |
1218 | |
1108 void TraceLog::SetEventCallback(EventCallback cb) { | 1219 void TraceLog::SetEventCallback(EventCallback cb) { |
1109 AutoLock lock(lock_); | 1220 subtle::NoBarrier_Store(&event_callback_, |
1110 event_callback_ = cb; | 1221 reinterpret_cast<subtle::AtomicWord>(cb)); |
1111 }; | 1222 }; |
1112 | 1223 |
1113 void TraceLog::Flush(const TraceLog::OutputCallback& cb) { | 1224 void TraceLog::Flush(const TraceLog::OutputCallback& cb) { |
1114 // Ignore memory allocations from here down. | 1225 // Ignore memory allocations from here down. |
1115 INTERNAL_TRACE_MEMORY(TRACE_DISABLED_BY_DEFAULT("memory"), | 1226 INTERNAL_TRACE_MEMORY(TRACE_DISABLED_BY_DEFAULT("memory"), |
1116 TRACE_MEMORY_IGNORE); | 1227 TRACE_MEMORY_IGNORE); |
1228 { | |
1229 AutoLock lock(lock_); | |
1230 DCHECK(!flush_message_loop_); | |
1231 flush_message_loop_ = MessageLoop::current(); | |
1232 DCHECK(flush_message_loop_); | |
1233 flush_output_callback_ = cb; | |
1234 } | |
1235 FlushNextThreadOrFinish(); | |
1236 } | |
1237 | |
1238 void TraceLog::FlushNextThreadOrFinish() { | |
1117 scoped_ptr<TraceBuffer> previous_logged_events; | 1239 scoped_ptr<TraceBuffer> previous_logged_events; |
1118 { | 1240 { |
1119 AutoLock lock(lock_); | 1241 AutoLock lock(lock_); |
1242 hash_set<MessageLoop*>::const_iterator next_message_loop = | |
1243 thread_message_loops_.begin(); | |
1244 if (next_message_loop != thread_message_loops_.end()) { | |
1245 (*next_message_loop)->PostTask( | |
1246 FROM_HERE, | |
1247 Bind(&TraceLog::DestroyThreadLocalEventBuffer, Unretained(this))); | |
1248 return; | |
1249 } | |
1250 | |
1120 previous_logged_events.swap(logged_events_); | 1251 previous_logged_events.swap(logged_events_); |
1121 logged_events_.reset(GetTraceBuffer()); | 1252 logged_events_.reset(GetTraceBuffer()); |
1253 subtle::NoBarrier_Store(&buffer_is_full_, 0); | |
1122 } // release lock | 1254 } // release lock |
1123 | 1255 |
1256 flush_message_loop_ = NULL; | |
1257 | |
1124 while (previous_logged_events->HasMoreEvents()) { | 1258 while (previous_logged_events->HasMoreEvents()) { |
1125 scoped_refptr<RefCountedString> json_events_str_ptr = | 1259 scoped_refptr<RefCountedString> json_events_str_ptr = |
1126 new RefCountedString(); | 1260 new RefCountedString(); |
1127 | 1261 |
1128 for (size_t i = 0; i < kTraceEventBatchSize; ++i) { | 1262 for (size_t i = 0; i < kTraceEventBatchSize; ++i) { |
1129 if (i > 0) | 1263 if (i > 0) |
1130 *(&(json_events_str_ptr->data())) += ","; | 1264 *(&(json_events_str_ptr->data())) += ","; |
1131 | 1265 |
1132 previous_logged_events->NextEvent().AppendAsJSON( | 1266 previous_logged_events->NextEvent().AppendAsJSON( |
1133 &(json_events_str_ptr->data())); | 1267 &(json_events_str_ptr->data())); |
1134 | 1268 |
1135 if (!previous_logged_events->HasMoreEvents()) | 1269 if (!previous_logged_events->HasMoreEvents()) |
1136 break; | 1270 break; |
1137 } | 1271 } |
1138 | 1272 |
1139 cb.Run(json_events_str_ptr); | 1273 flush_output_callback_.Run(json_events_str_ptr); |
1140 } | 1274 } |
1141 } | 1275 } |
1142 | 1276 |
1277 void TraceLog::DestroyThreadLocalEventBuffer() { | |
1278 delete thread_local_event_buffer_.Get(); | |
1279 thread_local_event_buffer_.Set(NULL); | |
1280 } | |
1281 | |
1143 void TraceLog::AddTraceEvent( | 1282 void TraceLog::AddTraceEvent( |
1144 char phase, | 1283 char phase, |
1145 const unsigned char* category_group_enabled, | 1284 const unsigned char* category_group_enabled, |
1146 const char* name, | 1285 const char* name, |
1147 unsigned long long id, | 1286 unsigned long long id, |
1148 int num_args, | 1287 int num_args, |
1149 const char** arg_names, | 1288 const char** arg_names, |
1150 const unsigned char* arg_types, | 1289 const unsigned char* arg_types, |
1151 const unsigned long long* arg_values, | 1290 const unsigned long long* arg_values, |
1152 scoped_ptr<ConvertableToTraceFormat> convertable_values[], | 1291 scoped_ptr<ConvertableToTraceFormat> convertable_values[], |
(...skipping 18 matching lines...) Expand all Loading... | |
1171 const unsigned char* arg_types, | 1310 const unsigned char* arg_types, |
1172 const unsigned long long* arg_values, | 1311 const unsigned long long* arg_values, |
1173 scoped_ptr<ConvertableToTraceFormat> convertable_values[], | 1312 scoped_ptr<ConvertableToTraceFormat> convertable_values[], |
1174 unsigned char flags) { | 1313 unsigned char flags) { |
1175 DCHECK(name); | 1314 DCHECK(name); |
1176 | 1315 |
1177 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) | 1316 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) |
1178 id ^= process_id_hash_; | 1317 id ^= process_id_hash_; |
1179 | 1318 |
1180 #if defined(OS_ANDROID) | 1319 #if defined(OS_ANDROID) |
1181 SendToATrace(phase, GetCategoryGroupName(category_group_enabled), name, id, | 1320 SendToATrace(phase, category_group_enabled, name, id, |
1182 num_args, arg_names, arg_types, arg_values, convertable_values, | 1321 num_args, arg_names, arg_types, arg_values, convertable_values, |
1183 flags); | 1322 flags); |
1184 #endif | 1323 #endif |
1185 | 1324 |
1186 if (!IsCategoryGroupEnabled(category_group_enabled)) | 1325 if (!IsCategoryGroupEnabled(category_group_enabled)) |
1187 return; | 1326 return; |
1188 | 1327 |
1189 TimeTicks now = timestamp - time_offset_; | 1328 TimeTicks now = timestamp - time_offset_; |
1190 EventCallback event_callback_copy; | |
1191 | 1329 |
1192 NotificationHelper notifier(this); | 1330 NotificationHelper notifier(this); |
1193 | 1331 |
1194 // Check and update the current thread name only if the event is for the | 1332 ThreadLocalEventBuffer* thread_local_event_buffer = NULL; |
1195 // current thread to avoid locks in most cases. | 1333 |
1196 if (thread_id == static_cast<int>(PlatformThread::CurrentId())) { | 1334 if (thread_id == static_cast<int>(PlatformThread::CurrentId())) { |
1335 if (MessageLoop::current()) { | |
1336 thread_local_event_buffer = thread_local_event_buffer_.Get(); | |
1337 if (!thread_local_event_buffer) { | |
1338 thread_local_event_buffer = new ThreadLocalEventBuffer(this); | |
1339 thread_local_event_buffer_.Set(thread_local_event_buffer); | |
1340 } | |
1341 } | |
1342 | |
1343 // Check and update the current thread name only if the event is for the | |
1344 // current thread to avoid locks in most cases. | |
1197 const char* new_name = ThreadIdNameManager::GetInstance()-> | 1345 const char* new_name = ThreadIdNameManager::GetInstance()-> |
1198 GetName(thread_id); | 1346 GetName(thread_id); |
1199 // Check if the thread name has been set or changed since the previous | 1347 // Check if the thread name has been set or changed since the previous |
1200 // call (if any), but don't bother if the new name is empty. Note this will | 1348 // call (if any), but don't bother if the new name is empty. Note this will |
1201 // not detect a thread name change within the same char* buffer address: we | 1349 // not detect a thread name change within the same char* buffer address: we |
1202 // favor common case performance over corner case correctness. | 1350 // favor common case performance over corner case correctness. |
1203 if (new_name != g_current_thread_name.Get().Get() && | 1351 if (new_name != g_current_thread_name.Get().Get() && |
1204 new_name && *new_name) { | 1352 new_name && *new_name) { |
1205 g_current_thread_name.Get().Set(new_name); | 1353 g_current_thread_name.Get().Set(new_name); |
1206 | |
1207 AutoLock lock(lock_); | |
1208 hash_map<int, std::string>::iterator existing_name = | 1354 hash_map<int, std::string>::iterator existing_name = |
1209 thread_names_.find(thread_id); | 1355 thread_names_.find(thread_id); |
1210 if (existing_name == thread_names_.end()) { | 1356 if (existing_name == thread_names_.end()) { |
1211 // This is a new thread id, and a new name. | 1357 // This is a new thread id, and a new name. |
1212 thread_names_[thread_id] = new_name; | 1358 thread_names_[thread_id] = new_name; |
1213 } else { | 1359 } else { |
1214 // This is a thread id that we've seen before, but potentially with a | 1360 // This is a thread id that we've seen before, but potentially with a |
1215 // new name. | 1361 // new name. |
1216 std::vector<StringPiece> existing_names; | 1362 std::vector<StringPiece> existing_names; |
1217 Tokenize(existing_name->second, ",", &existing_names); | 1363 Tokenize(existing_name->second, ",", &existing_names); |
1218 bool found = std::find(existing_names.begin(), | 1364 bool found = std::find(existing_names.begin(), |
1219 existing_names.end(), | 1365 existing_names.end(), |
1220 new_name) != existing_names.end(); | 1366 new_name) != existing_names.end(); |
1221 if (!found) { | 1367 if (!found) { |
1222 existing_name->second.push_back(','); | 1368 existing_name->second.push_back(','); |
1223 existing_name->second.append(new_name); | 1369 existing_name->second.append(new_name); |
1224 } | 1370 } |
1225 } | 1371 } |
1226 } | 1372 } |
1227 } | 1373 } |
1228 | 1374 |
1229 TraceEvent trace_event(thread_id, | 1375 if (!subtle::NoBarrier_Load(&buffer_is_full_)) { |
1230 now, phase, category_group_enabled, name, id, | 1376 TraceEvent trace_event(thread_id, |
1231 num_args, arg_names, arg_types, arg_values, | 1377 now, phase, category_group_enabled, name, id, |
1232 convertable_values, flags); | 1378 num_args, arg_names, arg_types, arg_values, |
1379 convertable_values, flags); | |
1233 | 1380 |
1234 do { | 1381 if (thread_local_event_buffer) { |
1235 AutoLock lock(lock_); | 1382 thread_local_event_buffer->AddEvent(trace_event, ¬ifier); |
1236 | 1383 } else { |
1237 event_callback_copy = event_callback_; | 1384 AutoLock lock(lock_); |
1238 if (logged_events_->IsFull()) | 1385 AddEventToMainBufferWhileLocked(trace_event, ¬ifier); |
1239 break; | |
1240 | |
1241 logged_events_->AddEvent(trace_event); | |
1242 | |
1243 if (trace_options_ & ECHO_TO_CONSOLE) { | |
1244 TimeDelta duration; | |
1245 if (phase == TRACE_EVENT_PHASE_END) { | |
1246 duration = timestamp - thread_event_start_times_[thread_id].top(); | |
1247 thread_event_start_times_[thread_id].pop(); | |
1248 } | |
1249 | |
1250 std::string thread_name = thread_names_[thread_id]; | |
1251 if (thread_colors_.find(thread_name) == thread_colors_.end()) | |
1252 thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1; | |
1253 | |
1254 std::ostringstream log; | |
1255 log << base::StringPrintf("%s: \x1b[0;3%dm", | |
1256 thread_name.c_str(), | |
1257 thread_colors_[thread_name]); | |
1258 | |
1259 size_t depth = 0; | |
1260 if (thread_event_start_times_.find(thread_id) != | |
1261 thread_event_start_times_.end()) | |
1262 depth = thread_event_start_times_[thread_id].size(); | |
1263 | |
1264 for (size_t i = 0; i < depth; ++i) | |
1265 log << "| "; | |
1266 | |
1267 trace_event.AppendPrettyPrinted(&log); | |
1268 if (phase == TRACE_EVENT_PHASE_END) | |
1269 log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF()); | |
1270 | |
1271 LOG(ERROR) << log.str() << "\x1b[0;m"; | |
1272 | |
1273 if (phase == TRACE_EVENT_PHASE_BEGIN) | |
1274 thread_event_start_times_[thread_id].push(timestamp); | |
1275 } | 1386 } |
1276 | 1387 |
1277 if (logged_events_->IsFull()) | 1388 EchoEventToConsoleIfEnabled(trace_event); |
1278 notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL); | 1389 } |
1279 | 1390 |
1280 if (watch_category_ == category_group_enabled && watch_event_name_ == name) | 1391 if (reinterpret_cast<const unsigned char*>(subtle::NoBarrier_Load( |
1392 &watch_category_)) == category_group_enabled) { | |
1393 AutoLock lock(lock_); | |
1394 if (watch_event_name_ == name) | |
1281 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); | 1395 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); |
1282 } while (0); // release lock | 1396 } |
1283 | 1397 |
1284 notifier.SendNotificationIfAny(); | 1398 notifier.SendNotificationIfAny(); |
1285 if (event_callback_copy != NULL) { | 1399 EventCallback event_callback = reinterpret_cast<EventCallback>( |
1286 event_callback_copy(phase, category_group_enabled, name, id, | 1400 subtle::NoBarrier_Load(&event_callback_)); |
1287 num_args, arg_names, arg_types, arg_values, | 1401 if (event_callback) { |
1288 flags); | 1402 event_callback(phase, category_group_enabled, name, id, |
1403 num_args, arg_names, arg_types, arg_values, | |
1404 flags); | |
1289 } | 1405 } |
1290 } | 1406 } |
1291 | 1407 |
1408 void TraceLog::EnableEchoToConsole(bool enable) { | |
1409 if (enable) { | |
1410 EchoToConsoleContext* new_context = new EchoToConsoleContext(); | |
1411 if (subtle::NoBarrier_CompareAndSwap( | |
1412 &echo_to_console_context_, 0, | |
1413 reinterpret_cast<subtle::AtomicWord>(new_context))) { | |
1414 // There is existing context, the new_context is not used. | |
1415 delete new_context; | |
1416 } | |
1417 } else { | |
1418 delete reinterpret_cast<EchoToConsoleContext*>( | |
1419 subtle::NoBarrier_AtomicExchange(&echo_to_console_context_, 0)); | |
1420 } | |
1421 } | |
1422 | |
1423 void TraceLog::EchoEventToConsoleIfEnabled(const TraceEvent& event) { | |
dsinclair
2013/08/13 21:04:42
Could this, mostly, be moved to it's own CL? Then,
Xianzhu
2013/08/14 21:28:33
Done.
| |
1424 EchoToConsoleContext* context = reinterpret_cast<EchoToConsoleContext*>( | |
1425 subtle::NoBarrier_Load(&echo_to_console_context_)); | |
1426 if (!context) // ECHO_TO_CONSOLE not enabled. | |
1427 return; | |
1428 | |
1429 AutoLock lock(lock_); | |
1430 | |
1431 int thread_id = event.thread_id(); | |
1432 TimeDelta duration; | |
1433 if (event.phase() == TRACE_EVENT_PHASE_END) { | |
1434 duration = event.timestamp() - | |
1435 context->thread_event_start_times[thread_id].top(); | |
1436 context->thread_event_start_times[thread_id].pop(); | |
1437 } | |
1438 | |
1439 std::string thread_name = thread_names_[thread_id]; | |
1440 if (context->thread_colors.find(thread_name) == | |
1441 context->thread_colors.end()) | |
1442 context->thread_colors[thread_name] = | |
1443 (context->thread_colors.size() % 6) + 1; | |
1444 | |
1445 std::ostringstream log; | |
1446 log << base::StringPrintf("%s: \x1b[0;3%dm", | |
1447 thread_name.c_str(), | |
1448 context->thread_colors[thread_name]); | |
1449 | |
1450 size_t depth = 0; | |
1451 if (context->thread_event_start_times.find(thread_id) != | |
1452 context->thread_event_start_times.end()) | |
1453 depth = context->thread_event_start_times[thread_id].size(); | |
1454 | |
1455 for (size_t i = 0; i < depth; ++i) | |
1456 log << "| "; | |
1457 | |
1458 event.AppendPrettyPrinted(&log); | |
1459 if (event.phase() == TRACE_EVENT_PHASE_END) | |
1460 log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF()); | |
1461 | |
1462 LOG(ERROR) << log.str() << "\x1b[0;m"; | |
1463 | |
1464 if (event.phase() == TRACE_EVENT_PHASE_BEGIN) | |
1465 context->thread_event_start_times[thread_id].push(event.timestamp()); | |
1466 } | |
1467 | |
1292 void TraceLog::AddTraceEventEtw(char phase, | 1468 void TraceLog::AddTraceEventEtw(char phase, |
1293 const char* name, | 1469 const char* name, |
1294 const void* id, | 1470 const void* id, |
1295 const char* extra) { | 1471 const char* extra) { |
1296 #if defined(OS_WIN) | 1472 #if defined(OS_WIN) |
1297 TraceEventETWProvider::Trace(name, phase, id, extra); | 1473 TraceEventETWProvider::Trace(name, phase, id, extra); |
1298 #endif | 1474 #endif |
1299 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, | 1475 INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name, |
1300 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); | 1476 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); |
1301 } | 1477 } |
(...skipping 10 matching lines...) Expand all Loading... | |
1312 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); | 1488 TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra); |
1313 } | 1489 } |
1314 | 1490 |
1315 void TraceLog::SetWatchEvent(const std::string& category_name, | 1491 void TraceLog::SetWatchEvent(const std::string& category_name, |
1316 const std::string& event_name) { | 1492 const std::string& event_name) { |
1317 const unsigned char* category = GetCategoryGroupEnabled( | 1493 const unsigned char* category = GetCategoryGroupEnabled( |
1318 category_name.c_str()); | 1494 category_name.c_str()); |
1319 size_t notify_count = 0; | 1495 size_t notify_count = 0; |
1320 { | 1496 { |
1321 AutoLock lock(lock_); | 1497 AutoLock lock(lock_); |
1322 watch_category_ = category; | 1498 subtle::NoBarrier_Store(&watch_category_, |
1499 reinterpret_cast<subtle::AtomicWord>(category)); | |
1323 watch_event_name_ = event_name; | 1500 watch_event_name_ = event_name; |
1324 | 1501 |
1325 // First, search existing events for watch event because we want to catch | 1502 // First, search existing events for watch event because we want to catch |
1326 // it even if it has already occurred. | 1503 // it even if it has already occurred. |
1327 notify_count = logged_events_->CountEnabledByName(category, event_name); | 1504 notify_count = logged_events_->CountEnabledByName(category, event_name); |
1328 } // release lock | 1505 } // release lock |
1329 | 1506 |
1330 // Send notification for each event found. | 1507 // Send notification for each event found. |
1331 for (size_t i = 0; i < notify_count; ++i) { | 1508 for (size_t i = 0; i < notify_count; ++i) { |
1332 NotificationHelper notifier(this); | 1509 NotificationHelper notifier(this); |
1333 lock_.Acquire(); | 1510 lock_.Acquire(); |
1334 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); | 1511 notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION); |
1335 lock_.Release(); | 1512 lock_.Release(); |
1336 notifier.SendNotificationIfAny(); | 1513 notifier.SendNotificationIfAny(); |
1337 } | 1514 } |
1338 } | 1515 } |
1339 | 1516 |
1340 void TraceLog::CancelWatchEvent() { | 1517 void TraceLog::CancelWatchEvent() { |
1341 AutoLock lock(lock_); | 1518 AutoLock lock(lock_); |
1342 watch_category_ = NULL; | 1519 subtle::NoBarrier_Store(&watch_category_, 0); |
1343 watch_event_name_ = ""; | 1520 watch_event_name_ = ""; |
1344 } | 1521 } |
1345 | 1522 |
1346 namespace { | 1523 namespace { |
1347 | 1524 |
1348 template <typename T> | 1525 template <typename T> |
1349 void AddMetadataEventToBuffer( | 1526 void AddMetadataEventToBuffer( |
1350 TraceBuffer* logged_events, | 1527 TraceBuffer* logged_events, |
1351 int thread_id, | 1528 int thread_id, |
1352 const char* metadata_name, const char* arg_name, | 1529 const char* metadata_name, const char* arg_name, |
(...skipping 330 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
1683 0, // num_args | 1860 0, // num_args |
1684 NULL, // arg_names | 1861 NULL, // arg_names |
1685 NULL, // arg_types | 1862 NULL, // arg_types |
1686 NULL, // arg_values | 1863 NULL, // arg_values |
1687 NULL, // convertable values | 1864 NULL, // convertable values |
1688 TRACE_EVENT_FLAG_NONE); // flags | 1865 TRACE_EVENT_FLAG_NONE); // flags |
1689 } | 1866 } |
1690 } | 1867 } |
1691 | 1868 |
1692 } // namespace trace_event_internal | 1869 } // namespace trace_event_internal |
OLD | NEW |