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

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

Issue 1239593002: Implement a new flow event API that allows binding flow events and regular events. (Closed) Base URL: https://chromium.googlesource.com/chromium/src.git@master
Patch Set: Add support for flow steps. Created 5 years, 5 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
« no previous file with comments | « base/trace_event/trace_event_impl.h ('k') | cc/output/latency_info_swap_promise.cc » ('j') | 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/trace_event/trace_event_impl.h" 5 #include "base/trace_event/trace_event_impl.h"
6 6
7 #include <algorithm> 7 #include <algorithm>
8 #include <cmath> 8 #include <cmath>
9 9
10 #include "base/base_switches.h" 10 #include "base/base_switches.h"
(...skipping 389 matching lines...) Expand 10 before | Expand all | Expand 10 after
400 int thread_id, 400 int thread_id,
401 const char* metadata_name, const char* arg_name, 401 const char* metadata_name, const char* arg_name,
402 const T& value) { 402 const T& value) {
403 if (!trace_event) 403 if (!trace_event)
404 return; 404 return;
405 405
406 int num_args = 1; 406 int num_args = 1;
407 unsigned char arg_type; 407 unsigned char arg_type;
408 unsigned long long arg_value; 408 unsigned long long arg_value;
409 ::trace_event_internal::SetTraceValue(value, &arg_type, &arg_value); 409 ::trace_event_internal::SetTraceValue(value, &arg_type, &arg_value);
410 trace_event->Initialize(thread_id, 410 trace_event->Initialize(
411 TraceTicks(), ThreadTicks(), 411 thread_id, TraceTicks(), ThreadTicks(), TRACE_EVENT_PHASE_METADATA,
412 TRACE_EVENT_PHASE_METADATA, 412 &g_category_group_enabled[g_category_metadata], metadata_name,
413 &g_category_group_enabled[g_category_metadata], 413 ::trace_event_internal::kNoId, trace_event_internal::kNoId, num_args,
414 metadata_name, ::trace_event_internal::kNoEventId, 414 &arg_name, &arg_type, &arg_value, NULL, TRACE_EVENT_FLAG_NONE);
415 num_args, &arg_name, &arg_type, &arg_value, NULL,
416 TRACE_EVENT_FLAG_NONE);
417 } 415 }
418 416
419 class AutoThreadLocalBoolean { 417 class AutoThreadLocalBoolean {
420 public: 418 public:
421 explicit AutoThreadLocalBoolean(ThreadLocalBoolean* thread_local_boolean) 419 explicit AutoThreadLocalBoolean(ThreadLocalBoolean* thread_local_boolean)
422 : thread_local_boolean_(thread_local_boolean) { 420 : thread_local_boolean_(thread_local_boolean) {
423 DCHECK(!thread_local_boolean_->Get()); 421 DCHECK(!thread_local_boolean_->Get());
424 thread_local_boolean_->Set(true); 422 thread_local_boolean_->Set(true);
425 } 423 }
426 ~AutoThreadLocalBoolean() { 424 ~AutoThreadLocalBoolean() {
(...skipping 158 matching lines...) Expand 10 before | Expand all | Expand 10 after
585 } 583 }
586 584
587 void TraceEvent::Initialize( 585 void TraceEvent::Initialize(
588 int thread_id, 586 int thread_id,
589 TraceTicks timestamp, 587 TraceTicks timestamp,
590 ThreadTicks thread_timestamp, 588 ThreadTicks thread_timestamp,
591 char phase, 589 char phase,
592 const unsigned char* category_group_enabled, 590 const unsigned char* category_group_enabled,
593 const char* name, 591 const char* name,
594 unsigned long long id, 592 unsigned long long id,
593 unsigned long long bind_id,
595 int num_args, 594 int num_args,
596 const char** arg_names, 595 const char** arg_names,
597 const unsigned char* arg_types, 596 const unsigned char* arg_types,
598 const unsigned long long* arg_values, 597 const unsigned long long* arg_values,
599 const scoped_refptr<ConvertableToTraceFormat>* convertable_values, 598 const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
600 unsigned int flags) { 599 unsigned int flags) {
601 timestamp_ = timestamp; 600 timestamp_ = timestamp;
602 thread_timestamp_ = thread_timestamp; 601 thread_timestamp_ = thread_timestamp;
603 duration_ = TimeDelta::FromInternalValue(-1); 602 duration_ = TimeDelta::FromInternalValue(-1);
604 id_ = id; 603 id_ = id;
605 category_group_enabled_ = category_group_enabled; 604 category_group_enabled_ = category_group_enabled;
606 name_ = name; 605 name_ = name;
607 thread_id_ = thread_id; 606 thread_id_ = thread_id;
608 phase_ = phase; 607 phase_ = phase;
609 flags_ = flags; 608 flags_ = flags;
609 bind_id_ = bind_id;
610 610
611 // Clamp num_args since it may have been set by a third_party library. 611 // Clamp num_args since it may have been set by a third_party library.
612 num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args; 612 num_args = (num_args > kTraceMaxNumArgs) ? kTraceMaxNumArgs : num_args;
613 int i = 0; 613 int i = 0;
614 for (; i < num_args; ++i) { 614 for (; i < num_args; ++i) {
615 arg_names_[i] = arg_names[i]; 615 arg_names_[i] = arg_names[i];
616 arg_types_[i] = arg_types[i]; 616 arg_types_[i] = arg_types[i];
617 617
618 if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE) 618 if (arg_types[i] == TRACE_VALUE_TYPE_CONVERTABLE)
619 convertable_values_[i] = convertable_values[i]; 619 convertable_values_[i] = convertable_values[i];
(...skipping 221 matching lines...) Expand 10 before | Expand all | Expand 10 after
841 } 841 }
842 842
843 // If id_ is set, print it out as a hex string so we don't loose any 843 // If id_ is set, print it out as a hex string so we don't loose any
844 // bits (it might be a 64-bit pointer). 844 // bits (it might be a 64-bit pointer).
845 if (flags_ & TRACE_EVENT_FLAG_HAS_ID) 845 if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
846 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_)); 846 StringAppendF(out, ",\"id\":\"0x%" PRIx64 "\"", static_cast<uint64>(id_));
847 847
848 if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING) 848 if (flags_ & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING)
849 StringAppendF(out, ",\"bp\":\"e\""); 849 StringAppendF(out, ",\"bp\":\"e\"");
850 850
851 if ((flags_ & TRACE_EVENT_FLAG_FLOW_OUT) ||
852 (flags_ & TRACE_EVENT_FLAG_FLOW_IN))
853 StringAppendF(out, ",\"bind_id\":\"0x%" PRIx64 "\"", static_cast<uint64>(bin d_id_));
854
855 if (flags_ & TRACE_EVENT_FLAG_FLOW_IN)
856 StringAppendF(out, ",\"flow_in\":\"true\"");
857
858 if (flags_ & TRACE_EVENT_FLAG_FLOW_OUT)
859 StringAppendF(out, ",\"flow_out\":\"true\"");
860
851 // Instant events also output their scope. 861 // Instant events also output their scope.
852 if (phase_ == TRACE_EVENT_PHASE_INSTANT) { 862 if (phase_ == TRACE_EVENT_PHASE_INSTANT) {
853 char scope = '?'; 863 char scope = '?';
854 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) { 864 switch (flags_ & TRACE_EVENT_FLAG_SCOPE_MASK) {
855 case TRACE_EVENT_SCOPE_GLOBAL: 865 case TRACE_EVENT_SCOPE_GLOBAL:
856 scope = TRACE_EVENT_SCOPE_NAME_GLOBAL; 866 scope = TRACE_EVENT_SCOPE_NAME_GLOBAL;
857 break; 867 break;
858 868
859 case TRACE_EVENT_SCOPE_PROCESS: 869 case TRACE_EVENT_SCOPE_PROCESS:
860 scope = TRACE_EVENT_SCOPE_NAME_PROCESS; 870 scope = TRACE_EVENT_SCOPE_NAME_PROCESS;
(...skipping 340 matching lines...) Expand 10 before | Expand all | Expand 10 after
1201 CheckThisIsCurrentBuffer(); 1211 CheckThisIsCurrentBuffer();
1202 1212
1203 event_count_++; 1213 event_count_++;
1204 ThreadTicks thread_now = ThreadNow(); 1214 ThreadTicks thread_now = ThreadNow();
1205 TraceTicks now = trace_log_->OffsetNow(); 1215 TraceTicks now = trace_log_->OffsetNow();
1206 TimeDelta overhead = now - event_timestamp; 1216 TimeDelta overhead = now - event_timestamp;
1207 if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) { 1217 if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
1208 TraceEvent* trace_event = AddTraceEvent(NULL); 1218 TraceEvent* trace_event = AddTraceEvent(NULL);
1209 if (trace_event) { 1219 if (trace_event) {
1210 trace_event->Initialize( 1220 trace_event->Initialize(
1211 static_cast<int>(PlatformThread::CurrentId()), 1221 static_cast<int>(PlatformThread::CurrentId()), event_timestamp,
1212 event_timestamp, event_thread_timestamp, 1222 event_thread_timestamp, TRACE_EVENT_PHASE_COMPLETE,
1213 TRACE_EVENT_PHASE_COMPLETE,
1214 &g_category_group_enabled[g_category_trace_event_overhead], 1223 &g_category_group_enabled[g_category_trace_event_overhead],
1215 "overhead", 0, 0, NULL, NULL, NULL, NULL, 0); 1224 "overhead", 0, trace_event_internal::kNoId, 0, NULL, NULL, NULL, NULL, 0);
1216 trace_event->UpdateDuration(now, thread_now); 1225 trace_event->UpdateDuration(now, thread_now);
1217 } 1226 }
1218 } 1227 }
1219 overhead_ += overhead; 1228 overhead_ += overhead;
1220 } 1229 }
1221 1230
1222 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() { 1231 void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
1223 delete this; 1232 delete this;
1224 } 1233 }
1225 1234
(...skipping 777 matching lines...) Expand 10 before | Expand all | Expand 10 after
2003 const char* name, 2012 const char* name,
2004 unsigned long long id, 2013 unsigned long long id,
2005 int num_args, 2014 int num_args,
2006 const char** arg_names, 2015 const char** arg_names,
2007 const unsigned char* arg_types, 2016 const unsigned char* arg_types,
2008 const unsigned long long* arg_values, 2017 const unsigned long long* arg_values,
2009 const scoped_refptr<ConvertableToTraceFormat>* convertable_values, 2018 const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
2010 unsigned int flags) { 2019 unsigned int flags) {
2011 int thread_id = static_cast<int>(base::PlatformThread::CurrentId()); 2020 int thread_id = static_cast<int>(base::PlatformThread::CurrentId());
2012 base::TraceTicks now = base::TraceTicks::Now(); 2021 base::TraceTicks now = base::TraceTicks::Now();
2013 return AddTraceEventWithThreadIdAndTimestamp(phase, category_group_enabled, 2022 return AddTraceEventWithThreadIdAndTimestamp(
2014 name, id, thread_id, now, 2023 phase, category_group_enabled, name, id, thread_id, trace_event_internal:: kNoId,
2015 num_args, arg_names, 2024 now, num_args, arg_names, arg_types, arg_values, convertable_values, flags );
2016 arg_types, arg_values,
2017 convertable_values, flags);
2018 } 2025 }
2019 2026
2020 TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp( 2027 TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
2021 char phase, 2028 char phase,
2022 const unsigned char* category_group_enabled, 2029 const unsigned char* category_group_enabled,
2023 const char* name, 2030 const char* name,
2024 unsigned long long id, 2031 unsigned long long id,
2025 int thread_id, 2032 int thread_id,
2033 unsigned long long bind_id,
2026 const TraceTicks& timestamp, 2034 const TraceTicks& timestamp,
2027 int num_args, 2035 int num_args,
2028 const char** arg_names, 2036 const char** arg_names,
2029 const unsigned char* arg_types, 2037 const unsigned char* arg_types,
2030 const unsigned long long* arg_values, 2038 const unsigned long long* arg_values,
2031 const scoped_refptr<ConvertableToTraceFormat>* convertable_values, 2039 const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
2032 unsigned int flags) { 2040 unsigned int flags) {
2033 TraceEventHandle handle = { 0, 0, 0 }; 2041 TraceEventHandle handle = { 0, 0, 0 };
2034 if (!*category_group_enabled) 2042 if (!*category_group_enabled)
2035 return handle; 2043 return handle;
2036 2044
2037 // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when 2045 // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
2038 // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) -> 2046 // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
2039 // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ... 2047 // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
2040 if (thread_is_in_trace_event_.Get()) 2048 if (thread_is_in_trace_event_.Get())
2041 return handle; 2049 return handle;
2042 2050
2043 AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_); 2051 AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
2044 2052
2045 DCHECK(name); 2053 DCHECK(name);
2046 DCHECK(!timestamp.is_null()); 2054 DCHECK(!timestamp.is_null());
2047 2055
2048 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) 2056 if (flags & TRACE_EVENT_FLAG_MANGLE_ID) {
2049 id = MangleEventId(id); 2057 if ((flags & TRACE_EVENT_FLAG_FLOW_IN) || (flags & TRACE_EVENT_FLAG_FLOW_OUT ))
2058 bind_id = MangleEventId(bind_id);
2059 else
dsinclair 2015/07/20 15:01:32 Do you want the else here? If we have an id we sho
2060 id = MangleEventId(id);
2061 }
2050 2062
2051 TraceTicks offset_event_timestamp = OffsetTimestamp(timestamp); 2063 TraceTicks offset_event_timestamp = OffsetTimestamp(timestamp);
2052 TraceTicks now = flags & TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP ? 2064 TraceTicks now = flags & TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP ?
2053 OffsetNow() : offset_event_timestamp; 2065 OffsetNow() : offset_event_timestamp;
2054 ThreadTicks thread_now = ThreadNow(); 2066 ThreadTicks thread_now = ThreadNow();
2055 2067
2056 // |thread_local_event_buffer_| can be null if the current thread doesn't have 2068 // |thread_local_event_buffer_| can be null if the current thread doesn't have
2057 // a message loop or the message loop is blocked. 2069 // a message loop or the message loop is blocked.
2058 InitializeThreadLocalEventBufferIfSupported(); 2070 InitializeThreadLocalEventBufferIfSupported();
2059 auto thread_local_event_buffer = thread_local_event_buffer_.Get(); 2071 auto thread_local_event_buffer = thread_local_event_buffer_.Get();
(...skipping 54 matching lines...) Expand 10 before | Expand all | Expand 10 after
2114 TraceEvent* trace_event = NULL; 2126 TraceEvent* trace_event = NULL;
2115 if (thread_local_event_buffer) { 2127 if (thread_local_event_buffer) {
2116 trace_event = thread_local_event_buffer->AddTraceEvent(&handle); 2128 trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
2117 } else { 2129 } else {
2118 lock.EnsureAcquired(); 2130 lock.EnsureAcquired();
2119 trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true); 2131 trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
2120 } 2132 }
2121 2133
2122 if (trace_event) { 2134 if (trace_event) {
2123 trace_event->Initialize(thread_id, offset_event_timestamp, thread_now, 2135 trace_event->Initialize(thread_id, offset_event_timestamp, thread_now,
2124 phase, category_group_enabled, name, id, 2136 phase, category_group_enabled, name, id, bind_id,
2125 num_args, arg_names, arg_types, arg_values, 2137 num_args, arg_names, arg_types, arg_values,
2126 convertable_values, flags); 2138 convertable_values, flags);
2127 2139
2128 #if defined(OS_ANDROID) 2140 #if defined(OS_ANDROID)
2129 trace_event->SendToATrace(); 2141 trace_event->SendToATrace();
2130 #endif 2142 #endif
2131 } 2143 }
2132 2144
2133 if (trace_options() & kInternalEchoToConsole) { 2145 if (trace_options() & kInternalEchoToConsole) {
2134 console_message = EventToConsoleMessage( 2146 console_message = EventToConsoleMessage(
(...skipping 145 matching lines...) Expand 10 before | Expand all | Expand 10 after
2280 } 2292 }
2281 2293
2282 if (console_message.size()) 2294 if (console_message.size())
2283 LOG(ERROR) << console_message; 2295 LOG(ERROR) << console_message;
2284 2296
2285 if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) { 2297 if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
2286 EventCallback event_callback = reinterpret_cast<EventCallback>( 2298 EventCallback event_callback = reinterpret_cast<EventCallback>(
2287 subtle::NoBarrier_Load(&event_callback_)); 2299 subtle::NoBarrier_Load(&event_callback_));
2288 if (event_callback) { 2300 if (event_callback) {
2289 event_callback(now, TRACE_EVENT_PHASE_END, category_group_enabled, name, 2301 event_callback(now, TRACE_EVENT_PHASE_END, category_group_enabled, name,
2290 trace_event_internal::kNoEventId, 0, NULL, NULL, NULL, 2302 trace_event_internal::kNoId, 0, NULL, NULL, NULL,
2291 TRACE_EVENT_FLAG_NONE); 2303 TRACE_EVENT_FLAG_NONE);
2292 } 2304 }
2293 } 2305 }
2294 } 2306 }
2295 2307
2296 void TraceLog::SetWatchEvent(const std::string& category_name, 2308 void TraceLog::SetWatchEvent(const std::string& category_name,
2297 const std::string& event_name, 2309 const std::string& event_name,
2298 const WatchEventCallback& callback) { 2310 const WatchEventCallback& callback) {
2299 const unsigned char* category = GetCategoryGroupEnabled( 2311 const unsigned char* category = GetCategoryGroupEnabled(
2300 category_name.c_str()); 2312 category_name.c_str());
(...skipping 204 matching lines...) Expand 10 before | Expand all | Expand 10 after
2505 // The single atom works because for now the category_group can only be "gpu". 2517 // The single atom works because for now the category_group can only be "gpu".
2506 DCHECK_EQ(strcmp(category_group, "gpu"), 0); 2518 DCHECK_EQ(strcmp(category_group, "gpu"), 0);
2507 static TRACE_EVENT_API_ATOMIC_WORD atomic = 0; 2519 static TRACE_EVENT_API_ATOMIC_WORD atomic = 0;
2508 INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES( 2520 INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO_CUSTOM_VARIABLES(
2509 category_group, atomic, category_group_enabled_); 2521 category_group, atomic, category_group_enabled_);
2510 name_ = name; 2522 name_ = name;
2511 if (*category_group_enabled_) { 2523 if (*category_group_enabled_) {
2512 event_handle_ = 2524 event_handle_ =
2513 TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP( 2525 TRACE_EVENT_API_ADD_TRACE_EVENT_WITH_THREAD_ID_AND_TIMESTAMP(
2514 TRACE_EVENT_PHASE_COMPLETE, category_group_enabled_, name, 2526 TRACE_EVENT_PHASE_COMPLETE, category_group_enabled_, name,
2515 trace_event_internal::kNoEventId, 2527 trace_event_internal::kNoId,
2516 static_cast<int>(base::PlatformThread::CurrentId()), 2528 static_cast<int>(base::PlatformThread::CurrentId()),
2529 trace_event_internal::kNoId,
2517 base::TraceTicks::Now(), 0, NULL, NULL, NULL, NULL, 2530 base::TraceTicks::Now(), 0, NULL, NULL, NULL, NULL,
2518 TRACE_EVENT_FLAG_NONE); 2531 TRACE_EVENT_FLAG_NONE);
2519 } 2532 }
2520 } 2533 }
2521 2534
2522 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() { 2535 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
2523 if (*category_group_enabled_) { 2536 if (*category_group_enabled_) {
2524 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, 2537 TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_,
2525 name_, event_handle_); 2538 name_, event_handle_);
2526 } 2539 }
2527 } 2540 }
2528 2541
2529 } // namespace trace_event_internal 2542 } // namespace trace_event_internal
OLDNEW
« no previous file with comments | « base/trace_event/trace_event_impl.h ('k') | cc/output/latency_info_swap_promise.cc » ('j') | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698