Fix TraceEventTestFixture flakiness

base/debug/trace_event_unittest.cc

 // Copyright (c) 2012 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/trace_event.h"
+#include "base/debug/trace_event_unittest.h"
 
 #include "base/bind.h"
 #include "base/command_line.h"
+#include "base/debug/trace_event.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
 #include "base/memory/ref_counted_memory.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/memory/singleton.h"
 #include "base/process_util.h"
 #include "base/stringprintf.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/threading/platform_thread.h"
 #include "base/threading/thread.h"
 #include "base/values.h"
 #include "testing/gmock/include/gmock/gmock.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
+using base::debug::HighResSleepForTraceTest;
+
 namespace base {
 namespace debug {
 
 namespace {
 
 enum CompareOp {
   IS_EQUAL,
   IS_NOT_EQUAL,
 };
 
@@ skipping 593 matching lines @@
 
 void TraceCallsWithCachedCategoryPointersPointers(const char* name_str) {
   TRACE_EVENT0("category name1", name_str);
   TRACE_EVENT_INSTANT0("category name2", name_str);
   TRACE_EVENT_BEGIN0("category name3", name_str);
   TRACE_EVENT_END0("category name4", name_str);
 }
 
 }  // namespace
 
+void HighResSleepForTraceTest(base::TimeDelta elapsed) {
+  base::TimeTicks end_time = base::TimeTicks::HighResNow() + elapsed;
+  do {
+    base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(1));

[jar (doing other things), 2012/08/16 01:23:35]

As per our discussion... it is very alarming that ::Sleep() can return a full
10ms too soon... and you had to try to play this game....

It will be very interesting to see if this really cures the flakyness that would
otherwise appear around line 856 of this (modified) file.

+  } while (base::TimeTicks::HighResNow() < end_time);
+}
+
 // Simple Test for emitting data and validating it was received.
 TEST_F(TraceEventTestFixture, DataCaptured) {
   ManualTestSetUp();
   TraceLog::GetInstance()->SetEnabled(true);
 
   TraceWithAllMacroVariants(NULL);
 
   TraceLog::GetInstance()->SetEnabled(false);
 
   ValidateAllTraceMacrosCreatedData(trace_parsed_);
@@ skipping 190 matching lines @@
   TraceLog::GetInstance()->SetEnabled(true);
 
   // Test that events at the same level are properly filtered by threshold.
   {
     TRACE_EVENT_IF_LONGER_THAN0(100, "time", "threshold 100");
     TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "threshold 1000");
     TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "threshold 10000");
     // 100+ seconds to avoid flakiness.
     TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "threshold long1");
     TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "threshold long2");
-    base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(20));
+    HighResSleepForTraceTest(base::TimeDelta::FromMilliseconds(20));
   }
 
   // Test that a normal nested event remains after it's parent event is dropped.
   {
     TRACE_EVENT_IF_LONGER_THAN0(1000000, "time", "2threshold10000");
     {
       TRACE_EVENT0("time", "nonthreshold1");
     }
   }
 
   // Test that parent thresholded events are dropped while some nested events
   // remain.
   {
     TRACE_EVENT0("time", "nonthreshold3");
     {
       TRACE_EVENT_IF_LONGER_THAN0(200000000, "time", "3thresholdlong2");
       {
         TRACE_EVENT_IF_LONGER_THAN0(100000000, "time", "3thresholdlong1");
         {
           TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "3threshold10000");
           {
             TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "3threshold1000");
             {
               TRACE_EVENT_IF_LONGER_THAN0(100, "time", "3threshold100");
-              base::PlatformThread::Sleep(
-                  base::TimeDelta::FromMilliseconds(20));
+              HighResSleepForTraceTest(base::TimeDelta::FromMilliseconds(20));
             }
           }
         }
       }
     }
   }
 
   // Test that child thresholded events are dropped while some parent events
   // remain.
   {
     TRACE_EVENT0("time", "nonthreshold4");
     {
       TRACE_EVENT_IF_LONGER_THAN0(100, "time", "4threshold100");
       {
         TRACE_EVENT_IF_LONGER_THAN0(1000, "time", "4threshold1000");
         {
           TRACE_EVENT_IF_LONGER_THAN0(10000, "time", "4threshold10000");
           {
             TRACE_EVENT_IF_LONGER_THAN0(100000000, "time",
                                         "4thresholdlong1");
             {
               TRACE_EVENT_IF_LONGER_THAN0(200000000, "time",
                                           "4thresholdlong2");
-              base::PlatformThread::Sleep(
-                  base::TimeDelta::FromMilliseconds(20));
+              HighResSleepForTraceTest(base::TimeDelta::FromMilliseconds(20));
             }
           }
         }
       }
     }
   }
 
   TraceLog::GetInstance()->SetEnabled(false);
 
 #define EXPECT_FIND_BE_(str) \
@@ skipping 459 matching lines @@
   Clear();
 
   trace_buffer_.Start();
   trace_buffer_.AddFragment("bla1,bla2,bla3,bla4");
   trace_buffer_.Finish();
   EXPECT_STREQ(json_output_.json_output.c_str(), "[bla1,bla2,bla3,bla4]");
 }
 
 }  // namespace debug
 }  // namespace base