Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(1181)

Side by Side Diff: base/debug/trace_event_impl.cc

Issue 22962004: Thread-local trace-event buffers (Closed) Base URL: https://chromium.googlesource.com/chromium/src.git@master
Patch Set: Created 7 years, 4 months ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
« base/debug/trace_event_impl.h ('K') | « base/debug/trace_event_impl.h ('k') | no next file » | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
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
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
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
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(&notifier);
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
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
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
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
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
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
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, &notifier);
1236 1383 } else {
1237 event_callback_copy = event_callback_; 1384 AutoLock lock(lock_);
1238 if (logged_events_->IsFull()) 1385 AddEventToMainBufferWhileLocked(trace_event, &notifier);
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
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
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
OLDNEW
« base/debug/trace_event_impl.h ('K') | « base/debug/trace_event_impl.h ('k') | no next file » | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698