Add metadata that report whether the buffer was full, and the timestamp when that happens.

BUG=393750

Review URL: https://codereview.chromium.org/398913003

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@284264 0039d316-1c4b-4281-b951-d872f2087c98

base/debug/trace_event_impl.cc

@@ -289,10 +289,11 @@ class TraceBufferRingBuffer : public TraceBuffer {
 
 class TraceBufferVector : public TraceBuffer {
  public:
-  TraceBufferVector()
+  TraceBufferVector(size_t max_chunks)
       : in_flight_chunk_count_(0),
-        current_iteration_index_(0) {
-    chunks_.reserve(kTraceEventVectorBufferChunks);
+        current_iteration_index_(0),
+        max_chunks_(max_chunks) {
+    chunks_.reserve(max_chunks_);
   }
 
   virtual scoped_ptr<TraceBufferChunk> GetChunk(size_t* index) OVERRIDE {
@@ -318,7 +319,7 @@ class TraceBufferVector : public TraceBuffer {
   }
 
   virtual bool IsFull() const OVERRIDE {
-    return chunks_.size() >= kTraceEventVectorBufferChunks;
+    return chunks_.size() >= max_chunks_;
   }
 
   virtual size_t Size() const OVERRIDE {
@@ -327,7 +328,7 @@ class TraceBufferVector : public TraceBuffer {
   }
 
   virtual size_t Capacity() const OVERRIDE {
-    return kTraceEventVectorBufferChunks * kTraceBufferChunkSize;
+    return max_chunks_ * kTraceBufferChunkSize;
   }
 
   virtual TraceEvent* GetEventByHandle(TraceEventHandle handle) OVERRIDE {
@@ -357,6 +358,7 @@ class TraceBufferVector : public TraceBuffer {
  private:
   size_t in_flight_chunk_count_;
   size_t current_iteration_index_;
+  size_t max_chunks_;
   ScopedVector<TraceBufferChunk> chunks_;
 
   DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
@@ -1501,7 +1503,11 @@ TraceBuffer* TraceLog::CreateTraceBuffer() {
     return new TraceBufferRingBuffer(kMonitorTraceEventBufferChunks);
   else if (options & ECHO_TO_CONSOLE)
     return new TraceBufferRingBuffer(kEchoToConsoleTraceEventBufferChunks);
-  return new TraceBufferVector();
+  return CreateTraceBufferVectorOfSize(kTraceEventVectorBufferChunks);
+}
+
+TraceBuffer* TraceLog::CreateTraceBufferVectorOfSize(size_t max_chunks) {
+  return new TraceBufferVector(max_chunks);
 }
 
 TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
@@ -1533,8 +1539,12 @@ TraceEvent* TraceLog::AddEventToThreadSharedChunkWhileLocked(
 
 void TraceLog::CheckIfBufferIsFullWhileLocked() {
   lock_.AssertAcquired();
-  if (logged_events_->IsFull())
+  if (logged_events_->IsFull()) {
+    if (buffer_limit_reached_timestamp_.is_null()) {
+      buffer_limit_reached_timestamp_ = OffsetNow();
+    }
     SetDisabledWhileLocked();
+  }
 }
 
 void TraceLog::SetEventCallbackEnabled(const CategoryFilter& category_filter,
@@ -2109,6 +2119,15 @@ void TraceLog::AddMetadataEventsWhileLocked() {
                             "thread_name", "name",
                             it->second);
   }
+
+  // If buffer is full, add a metadata record to report this.
+  if (!buffer_limit_reached_timestamp_.is_null()) {
+    InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
+                            current_thread_id,
+                            "trace_buffer_overflowed",
+                            "overflowed_at_ts",
+                            buffer_limit_reached_timestamp_);
+  }
 }
 
 void TraceLog::WaitSamplingEventForTesting() {

base/debug/trace_event_impl.h

@@ -605,6 +605,8 @@ class BASE_EXPORT TraceLog {
                            TraceBufferRingBufferHalfIteration);
   FRIEND_TEST_ALL_PREFIXES(TraceEventTestFixture,
                            TraceBufferRingBufferFullIteration);
+  FRIEND_TEST_ALL_PREFIXES(TraceEventTestFixture,
+                           TraceBufferVectorReportFull);
 
   // This allows constructor and destructor to be private and usable only
   // by the Singleton class.
@@ -632,6 +634,7 @@ class BASE_EXPORT TraceLog {
 
   TraceBuffer* trace_buffer() const { return logged_events_.get(); }
   TraceBuffer* CreateTraceBuffer();
+  TraceBuffer* CreateTraceBufferVectorOfSize(size_t max_chunks);
 
   std::string EventToConsoleMessage(unsigned char phase,
                                     const TimeTicks& timestamp,
@@ -692,6 +695,8 @@ class BASE_EXPORT TraceLog {
   base::hash_map<int, std::stack<TimeTicks> > thread_event_start_times_;
   base::hash_map<std::string, int> thread_colors_;
 
+  TimeTicks buffer_limit_reached_timestamp_;
+
   // XORed with TraceID to make it unlikely to collide with other processes.
   unsigned long long process_id_hash_;
 

base/debug/trace_event_unittest.cc

@@ -2415,6 +2415,53 @@ TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecordingDuration) {
   VerifyCollectedEvent(5, TRACE_EVENT_PHASE_END, "callback", "duration1");
 }
 
+TEST_F(TraceEventTestFixture, TraceBufferVectorReportFull) {
+  TraceLog* trace_log = TraceLog::GetInstance();
+  trace_log->SetEnabled(CategoryFilter("*"),
+      base::debug::TraceLog::RECORDING_MODE,
+      TraceLog::RECORD_UNTIL_FULL);
+  trace_log->logged_events_.reset(
+      trace_log->CreateTraceBufferVectorOfSize(100));
+  do {
+    TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
+        "all", "with_timestamp", 0, 0,
+        TimeTicks::NowFromSystemTraceTime().ToInternalValue());
+    TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
+        "all", "with_timestamp", 0, 0,
+        TimeTicks::NowFromSystemTraceTime().ToInternalValue());
+  } while (!trace_log->BufferIsFull());
+
+  EndTraceAndFlush();
+
+  const DictionaryValue* trace_full_metadata = NULL;
+
+  trace_full_metadata = FindTraceEntry(trace_parsed_,
+                                       "overflowed_at_ts");
+  std::string phase;
+  double buffer_limit_reached_timestamp = 0;
+
+  EXPECT_TRUE(trace_full_metadata);
+  EXPECT_TRUE(trace_full_metadata->GetString("ph", &phase));
+  EXPECT_EQ("M", phase);
+  EXPECT_TRUE(trace_full_metadata->GetDouble(
+      "args.overflowed_at_ts", &buffer_limit_reached_timestamp));
+  EXPECT_DOUBLE_EQ(
+      static_cast<double>(
+          trace_log->buffer_limit_reached_timestamp_.ToInternalValue()),
+      buffer_limit_reached_timestamp);
+
+  // Test that buffer_limit_reached_timestamp's value is near to the timestamp
+  // of the last trace event.
+  DropTracedMetadataRecords();
+  const DictionaryValue* last_trace_event = NULL;
+  double last_trace_event_timestamp = 0;
+  EXPECT_TRUE(trace_parsed_.GetDictionary(trace_parsed_.GetSize() - 1,
+                                          &last_trace_event));
+  EXPECT_TRUE(last_trace_event->GetDouble("ts", &last_trace_event_timestamp));
+  // The difference between the two timestamps should be less than 50ms.
+  EXPECT_NEAR(last_trace_event_timestamp, buffer_limit_reached_timestamp, 50);
+}
+
 TEST_F(TraceEventTestFixture, TraceBufferRingBufferGetReturnChunk) {
   TraceLog::GetInstance()->SetEnabled(CategoryFilter("*"),
                                       base::debug::TraceLog::RECORDING_MODE,