Add queued_time_ms trace for events in message loop
These trace can be useful for examining the status of message loop
queues when debugging some performance issues.
BUG=none
Review URL: https://chromiumcodereview.appspot.com/18083015
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@210880 0039d316-1c4b-4281-b951-d872f2087c98
CrOS-Libchrome-Original-Commit: e1a38d600ac88e2b70a50f1a95416ccfcb2de858
diff --git a/base/message_loop/message_loop.cc b/base/message_loop/message_loop.cc
index 9e33a42..96192a7 100644
--- a/base/message_loop/message_loop.cc
+++ b/base/message_loop/message_loop.cc
@@ -456,11 +456,17 @@
}
void MessageLoop::RunTask(const PendingTask& pending_task) {
- TRACE_EVENT_FLOW_END0("task", "MessageLoop::PostTask",
- TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)));
+ tracked_objects::TrackedTime start_time =
+ tracked_objects::ThreadData::NowForStartOfRun(pending_task.birth_tally);
+
+ TRACE_EVENT_FLOW_END1("task", "MessageLoop::PostTask",
+ TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)),
+ "queue_duration",
+ (start_time - pending_task.EffectiveTimePosted()).InMilliseconds());
TRACE_EVENT2("task", "MessageLoop::RunTask",
"src_file", pending_task.posted_from.file_name(),
"src_func", pending_task.posted_from.function_name());
+
DCHECK(nestable_tasks_allowed_);
// Execute the task and assume the worst: It is probably not reentrant.
nestable_tasks_allowed_ = false;
@@ -476,9 +482,6 @@
HistogramEvent(kTaskRunEvent);
- tracked_objects::TrackedTime start_time =
- tracked_objects::ThreadData::NowForStartOfRun(pending_task.birth_tally);
-
FOR_EACH_OBSERVER(TaskObserver, task_observers_,
WillProcessTask(pending_task));
pending_task.task.Run();
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index c45276b..cc00ce6 100644
--- a/base/tracked_objects.cc
+++ b/base/tracked_objects.cc
@@ -465,16 +465,6 @@
if (!current_thread_data)
return;
- // To avoid conflating our stats with the delay duration in a PostDelayedTask,
- // we identify such tasks, and replace their post_time with the time they
- // were scheduled (requested?) to emerge from the delayed task queue. This
- // means that queueing delay for such tasks will show how long they went
- // unserviced, after they *could* be serviced. This is the same stat as we
- // have for non-delayed tasks, and we consistently call it queueing delay.
- TrackedTime effective_post_time = completed_task.delayed_run_time.is_null()
- ? tracked_objects::TrackedTime(completed_task.time_posted)
- : tracked_objects::TrackedTime(completed_task.delayed_run_time);
-
// Watch out for a race where status_ is changing, and hence one or both
// of start_of_run or end_of_run is zero. In that case, we didn't bother to
// get a time value since we "weren't tracking" and we were trying to be
@@ -483,7 +473,8 @@
int32 queue_duration = 0;
int32 run_duration = 0;
if (!start_of_run.is_null()) {
- queue_duration = (start_of_run - effective_post_time).InMilliseconds();
+ queue_duration = (start_of_run - completed_task.EffectiveTimePosted())
+ .InMilliseconds();
if (!end_of_run.is_null())
run_duration = (end_of_run - start_of_run).InMilliseconds();
}
diff --git a/base/tracking_info.h b/base/tracking_info.h
index dacbcea..ba9585e 100644
--- a/base/tracking_info.h
+++ b/base/tracking_info.h
@@ -11,6 +11,7 @@
#ifndef BASE_TRACKING_INFO_H_
#define BASE_TRACKING_INFO_H_
+#include "base/profiler/tracked_time.h"
#include "base/time/time.h"
namespace tracked_objects {
@@ -27,6 +28,17 @@
base::TimeTicks delayed_run_time);
~TrackingInfo();
+ // To avoid conflating our stats with the delay duration in a PostDelayedTask,
+ // we identify such tasks, and replace their post_time with the time they
+ // were scheduled (requested?) to emerge from the delayed task queue. This
+ // means that queuing delay for such tasks will show how long they went
+ // unserviced, after they *could* be serviced. This is the same stat as we
+ // have for non-delayed tasks, and we consistently call it queuing delay.
+ tracked_objects::TrackedTime EffectiveTimePosted() const {
+ return tracked_objects::TrackedTime(
+ delayed_run_time.is_null() ? time_posted : delayed_run_time);
+ }
+
// Record of location and thread that the task came from.
tracked_objects::Births* birth_tally;