Record task durations on Renderer Main & Compositor threads.

base/debug/task_annotator.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/debug/task_annotator.h"
 
 #include <array>
 
 #include "base/debug/activity_tracker.h"
 #include "base/debug/alias.h"
+#include "base/metrics/histogram_functions.h"
 #include "base/pending_task.h"
 #include "base/trace_event/trace_event.h"
 #include "base/tracked_objects.h"
 
+namespace {
+
+void RecordCPUTimeUMA(tracked_objects::ThreadData* thread_data,
+                      base::TimeDelta duration) {
+  if (!thread_data)
+    return;
+
+  if (duration.InMillisecondsF() == 0)
+    return;
+
+  if (!thread_data->task_length_recording_enabled_for_uma())

[Sami, 2017/07/26 20:36:38]

Can we swap this before the previous 'if' since this is more likely to early
out?

+    return;
+
+  // TODO - this is slow.

[Sami, 2017/07/26 20:36:38]

TODO(tdresser)

In any case we probably can't land this as is given Bruce's recent findings
about debug string prints during video playback.

[tdresser, 2017/07/27 19:18:05]

Oops, yeah, I meant to call this out as something I was wondering about.

I can imagine a solution in which we use some kind of integer thread type
identifier, and a STATIC_HISTOGRAM_POINTER_GROUP, which would make this much
faster, but most approaches to this would result in some awkward layering
violations.

We could have the "max thread id" get passed to the task annotator at some
point, have a big enum listing possible thread types, and use those here instead
of string manipulation. 

We'd then need to populate a vector where the index indicates the histogram
name, and use a STATIC_HISTOGRAM_POINTER_GROUP.

Pretty messy, but could work.

Thoughts?

[Sami, 2017/08/04 15:46:32]

Yeah, this is pretty tough from a layering perspective. A parallel case that
comes to mind is the tracing thread sorting index:

https://cs.chromium.org/chromium/src/base/trace_event/trace_log.h?l=320&gs=cp...

Maybe we could merge and generalize that with InitializeThreadContext()? We'd
still need to have a registry of ids somewhere for that to work however.

Alternatively we could compute a small hash of the thread name (possibly at
compile time) and use that as the id (and DCHECK that none of the names
collide).

+  base::UmaHistogramCustomCounts(
+      "Scheduling.TaskTime." + thread_data->sanitized_thread_name(),
+      duration.InMicroseconds(), 1, 1000 * 1000, 50);
+}
+
+}  // namespace
+
 namespace base {
 namespace debug {
 
 TaskAnnotator::TaskAnnotator() {
 }
 
 TaskAnnotator::~TaskAnnotator() {
 }
 
 void TaskAnnotator::DidQueueTask(const char* queue_function,
@@ skipping 27 matching lines @@
       std::tuple_size<decltype(pending_task->task_backtrace)>::value + 1;
   std::array<const void*, kStackTaskTraceSnapshotSize> task_backtrace;
   task_backtrace[0] = pending_task->posted_from.program_counter();
   std::copy(pending_task->task_backtrace.begin(),
             pending_task->task_backtrace.end(), task_backtrace.begin() + 1);
   debug::Alias(&task_backtrace);
 
   std::move(pending_task->task).Run();
 
   stopwatch.Stop();
+
+  RecordCPUTimeUMA(stopwatch.GetThreadData(), stopwatch.RunDuration());
+
   tracked_objects::ThreadData::TallyRunOnNamedThreadIfTracking(*pending_task,
                                                                stopwatch);
 }
 
 uint64_t TaskAnnotator::GetTaskTraceID(const PendingTask& task) const {
   return (static_cast<uint64_t>(task.sequence_num) << 32) |
          ((static_cast<uint64_t>(reinterpret_cast<intptr_t>(this)) << 32) >>
           32);
 }
 
 }  // namespace debug
 }  // namespace base