[scheduler]: Fix tracing issues with nested IdlePeriod trace events.

components/scheduler/child/idle_helper.cc

 // Copyright 2015 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 "components/scheduler/child/idle_helper.h"
 
 #include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "base/trace_event/trace_event_argument.h"
 #include "components/scheduler/child/scheduler_helper.h"
@@ skipping 261 matching lines @@
   if (state_.idle_period_state() ==
       IdlePeriodState::IN_LONG_IDLE_PERIOD_PAUSED) {
     // Restart long idle period ticks.
     helper_->ControlTaskRunner()->PostTask(
         FROM_HERE, enable_next_long_idle_period_closure_.callback());
   }
 }
 
 base::TimeTicks IdleHelper::WillProcessIdleTask() {
   helper_->CheckOnValidThread();
-  DCHECK(IsInIdlePeriod(state_.idle_period_state()));

[Sami, 2015/08/21 10:46:58]

Would you also mind adding a TODO about not forgetting which task queue the task
is associated in TQM where we deal with posting non-nestable tasks?

[rmcilroy, 2015/08/21 10:57:47]

Added (as TODO(skyostil) ;)).

-
   state_.TraceIdleIdleTaskStart();
   return CurrentIdleTaskDeadline();
 }
 
 void IdleHelper::DidProcessIdleTask() {
   helper_->CheckOnValidThread();
   state_.TraceIdleIdleTaskEnd();
   if (IsInLongIdlePeriod(state_.idle_period_state())) {
     UpdateLongIdlePeriodStateAfterIdleTask();
   }
@@ skipping 24 matching lines @@
 }
 
 IdleHelper::State::State(SchedulerHelper* helper,
                          Delegate* delegate,
                          const char* tracing_category,
                          const char* disabled_by_default_tracing_category,
                          const char* idle_period_tracing_name)
     : helper_(helper),
       delegate_(delegate),
       idle_period_state_(IdlePeriodState::NOT_IN_IDLE_PERIOD),
-      nestable_events_started_(false),
+      idle_period_trace_event_started_(false),
+      running_idle_task_for_tracing_(false),
       tracing_category_(tracing_category),
       disabled_by_default_tracing_category_(
           disabled_by_default_tracing_category),
       idle_period_tracing_name_(idle_period_tracing_name) {
 }
 
 IdleHelper::State::~State() {
 }
 
 IdleHelper::IdlePeriodState IdleHelper::State::idle_period_state() const {
@@ skipping 14 matching lines @@
   helper_->CheckOnValidThread();
   if (new_state == idle_period_state_) {
     DCHECK_EQ(new_deadline, idle_period_deadline_);
     return;
   }
 
   bool is_tracing;
   TRACE_EVENT_CATEGORY_GROUP_ENABLED(tracing_category_, &is_tracing);
   if (is_tracing) {
     base::TimeTicks now(optional_now.is_null() ? helper_->Now() : optional_now);
-    TraceEventIdlePeriodStateChange(new_state, new_deadline, now);
-    idle_period_deadline_for_tracing_ =
-        base::TraceTicks::Now() + (new_deadline - now);
+    base::TraceTicks trace_now = base::TraceTicks::Now();
+    idle_period_deadline_for_tracing_ = trace_now + (new_deadline - now);
+    TraceEventIdlePeriodStateChange(
+        new_state, running_idle_task_for_tracing_,
+        idle_period_deadline_for_tracing_, trace_now);
   }
 
   idle_period_state_ = new_state;
   idle_period_deadline_ = new_deadline;
 
   // Inform the delegate if we are starting or ending an idle period.
   if (IsInIdlePeriod(new_state) && !IsInIdlePeriod(old_idle_period_state)) {
     delegate_->OnIdlePeriodStarted();
   } else if (!IsInIdlePeriod(new_state) &&
              IsInIdlePeriod(old_idle_period_state)) {
     delegate_->OnIdlePeriodEnded();
   }
 }
 
 void IdleHelper::State::TraceIdleIdleTaskStart() {
   helper_->CheckOnValidThread();
 
   bool is_tracing;
   TRACE_EVENT_CATEGORY_GROUP_ENABLED(tracing_category_, &is_tracing);
-  if (is_tracing && nestable_events_started_) {
-    last_idle_task_trace_time_ = base::TraceTicks::Now();
-    TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-        tracing_category_, "RunningIdleTask", this,
-        last_idle_task_trace_time_.ToInternalValue());
+  if (is_tracing) {
+    TraceEventIdlePeriodStateChange(
+        idle_period_state_, true, idle_period_deadline_for_tracing_,
+        base::TraceTicks::Now());
   }
 }
 
 void IdleHelper::State::TraceIdleIdleTaskEnd() {
   helper_->CheckOnValidThread();
 
   bool is_tracing;
   TRACE_EVENT_CATEGORY_GROUP_ENABLED(tracing_category_, &is_tracing);
-  if (is_tracing && nestable_events_started_) {
-    if (!idle_period_deadline_for_tracing_.is_null() &&
-        base::TraceTicks::Now() > idle_period_deadline_for_tracing_) {
-      TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-          tracing_category_, "DeadlineOverrun", this,
-          std::max(idle_period_deadline_for_tracing_,
-                   last_idle_task_trace_time_).ToInternalValue());
-      TRACE_EVENT_NESTABLE_ASYNC_END0(tracing_category_, "DeadlineOverrun",
-                                      this);
-    }
-    TRACE_EVENT_NESTABLE_ASYNC_END0(tracing_category_, "RunningIdleTask", this);
+  if (is_tracing) {
+    TraceEventIdlePeriodStateChange(
+        idle_period_state_, false, idle_period_deadline_for_tracing_,
+        base::TraceTicks::Now());
   }
 }
 
 void IdleHelper::State::TraceEventIdlePeriodStateChange(
     IdlePeriodState new_state,
-    base::TimeTicks new_deadline,
-    base::TimeTicks now) {
+    bool new_running_idle_task,
+    base::TraceTicks new_deadline,
+    base::TraceTicks now) {
   TRACE_EVENT2(disabled_by_default_tracing_category_, "SetIdlePeriodState",
                "old_state",
                IdleHelper::IdlePeriodStateToString(idle_period_state_),
                "new_state", IdleHelper::IdlePeriodStateToString(new_state));
-  if (nestable_events_started_) {
-    // End async tracing events for the state we are leaving.
-    if (idle_period_state_ == IdlePeriodState::IN_LONG_IDLE_PERIOD_PAUSED) {
-      TRACE_EVENT_NESTABLE_ASYNC_END0(tracing_category_, "LongIdlePeriodPaused",
-                                      this);
-    }
-    if (IsInLongIdlePeriod(idle_period_state_) &&
-        !IsInLongIdlePeriod(new_state)) {
-      TRACE_EVENT_NESTABLE_ASYNC_END0(tracing_category_, "LongIdlePeriod",
-                                      this);
-    }
-    if (idle_period_state_ == IdlePeriodState::IN_SHORT_IDLE_PERIOD) {
-      TRACE_EVENT_NESTABLE_ASYNC_END0(tracing_category_, "ShortIdlePeriod",
-                                      this);
-    }
-    if (IsInIdlePeriod(idle_period_state_) && !IsInIdlePeriod(new_state)) {
-      TRACE_EVENT_NESTABLE_ASYNC_END0(tracing_category_,
-                                      idle_period_tracing_name_, this);
-      nestable_events_started_ = false;
+
+  if (idle_period_trace_event_started_ && running_idle_task_for_tracing_ &&
+      !new_running_idle_task) {
+    running_idle_task_for_tracing_ = false;
+    if (!idle_period_deadline_for_tracing_.is_null() &&
+        now > idle_period_deadline_for_tracing_) {
+      TRACE_EVENT_ASYNC_STEP_INTO_WITH_TIMESTAMP0(
+          tracing_category_, idle_period_tracing_name_, this,
+          "DeadlineOverrun",
+          std::max(idle_period_deadline_for_tracing_,
+                   last_idle_task_trace_time_).ToInternalValue());
     }
   }
 
-  // Start async tracing events for the state we are entering.
-  if (IsInIdlePeriod(new_state) && !IsInIdlePeriod(idle_period_state_)) {
-    nestable_events_started_ = true;
-    TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
-        tracing_category_, idle_period_tracing_name_, this,
-        "idle_period_length_ms", (new_deadline - now).ToInternalValue());
-  }
-  if (new_state == IdlePeriodState::IN_SHORT_IDLE_PERIOD) {
-    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(tracing_category_, "ShortIdlePeriod",
-                                      this);
-  }
-  if (IsInLongIdlePeriod(new_state) &&
-      !IsInLongIdlePeriod(idle_period_state_)) {
-    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(tracing_category_, "LongIdlePeriod",
-                                      this);
-  }
-  if (new_state == IdlePeriodState::IN_LONG_IDLE_PERIOD_PAUSED) {
-    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(tracing_category_, "LongIdlePeriodPaused",
-                                      this);
+  if (IsInIdlePeriod(new_state)) {
+    if (!idle_period_trace_event_started_) {
+      idle_period_trace_event_started_ = true;
+      TRACE_EVENT_ASYNC_BEGIN1(
+          tracing_category_, idle_period_tracing_name_, this,
+          "idle_period_length_ms", (new_deadline - now).ToInternalValue());
+    }
+
+    if (new_running_idle_task) {
+      last_idle_task_trace_time_ = now;
+      running_idle_task_for_tracing_ = true;
+      TRACE_EVENT_ASYNC_STEP_INTO0(
+          tracing_category_, idle_period_tracing_name_, this,
+          "RunningIdleTask");
+    } else if (new_state == IdlePeriodState::IN_SHORT_IDLE_PERIOD) {
+      TRACE_EVENT_ASYNC_STEP_INTO0(
+          tracing_category_, idle_period_tracing_name_, this,
+          "ShortIdlePeriod");
+    } else if (IsInLongIdlePeriod(new_state) &&
+        new_state != IdlePeriodState::IN_LONG_IDLE_PERIOD_PAUSED) {
+      TRACE_EVENT_ASYNC_STEP_INTO0(
+          tracing_category_, idle_period_tracing_name_, this,
+          "LongIdlePeriod");
+    } else if (new_state == IdlePeriodState::IN_LONG_IDLE_PERIOD_PAUSED) {
+      TRACE_EVENT_ASYNC_STEP_INTO0(
+          tracing_category_, idle_period_tracing_name_, this,
+          "LongIdlePeriodPaused");
+    }
+  } else if (idle_period_trace_event_started_) {
+    idle_period_trace_event_started_ = false;
+    TRACE_EVENT_ASYNC_END0(tracing_category_, idle_period_tracing_name_, this);
   }
 }
 
 // static
 const char* IdleHelper::IdlePeriodStateToString(
     IdlePeriodState idle_period_state) {
   switch (idle_period_state) {
     case IdlePeriodState::NOT_IN_IDLE_PERIOD:
       return "not_in_idle_period";
     case IdlePeriodState::IN_SHORT_IDLE_PERIOD:
       return "in_short_idle_period";
     case IdlePeriodState::IN_LONG_IDLE_PERIOD:
       return "in_long_idle_period";
     case IdlePeriodState::IN_LONG_IDLE_PERIOD_WITH_MAX_DEADLINE:
       return "in_long_idle_period_with_max_deadline";
     case IdlePeriodState::IN_LONG_IDLE_PERIOD_PAUSED:
       return "in_long_idle_period_paused";
     default:
       NOTREACHED();
       return nullptr;
   }
 }
 
 }  // namespace scheduler