Use a more concise binary format when dumping long running methods

We used to use a human readable format to dump long running methods.
To make the dumps more concise we are moving to a binary format that
cuts the size by a 3rd. A trace that was about 60K earlier is now about
20K. The format is very similar to the method trace that uses leb
encoding and encodes the incremental difference from the previous entry
both for method ids and the timestamps.

Bug: 352518093
Test: Manual testing with feature enabled and dumping to file and also
to an ANR report.

Change-Id: Ief407dc7dc6f335b0d5add2a1e0f439ad01e318e

2 files changed, 122 insertions, 54 deletions

diff --git a/runtime/trace_profile.cc b/runtime/trace_profile.cc
index 4c0abbf1da..58927d8948 100644
--- a/runtime/trace_profile.cc
+++ b/runtime/trace_profile.cc
@@ -88,6 +88,26 @@ void TraceData::SignalTraceDumpComplete() {
   trace_dump_condition_.Broadcast(Thread::Current());
 }
 
+void TraceData::AppendToLongRunningMethods(const uint8_t* buffer, size_t size) {
+  MutexLock mu(Thread::Current(), trace_data_lock_);
+  if (curr_buffer_ == nullptr) {
+    curr_buffer_.reset(new uint8_t[kBufSizeForEncodedData]);
+    curr_index_ = 0;
+  }
+  if (curr_index_ + size <= kBufSizeForEncodedData) {
+    memcpy(curr_buffer_.get() + curr_index_, buffer, size);
+    curr_index_ += size;
+  } else {
+    size_t remaining_bytes = kBufSizeForEncodedData - curr_index_;
+    if (remaining_bytes != 0) {
+      memcpy(curr_buffer_.get() + curr_index_, buffer, remaining_bytes);
+    }
+    overflow_buffers_.push_back(std::move(curr_buffer_));
+    curr_buffer_.reset(new uint8_t[kBufSizeForEncodedData]);
+    memcpy(curr_buffer_.get(), buffer + remaining_bytes, size - remaining_bytes);
+  }
+}
+
 void TraceProfiler::AllocateBuffer(Thread* thread) {
   if (!art_flags::always_enable_profile_code()) {
     return;
@@ -162,8 +182,6 @@ void RecordMethodsOnThreadStack(Thread* thread, uintptr_t* method_trace_buffer)
   uint64_t init_time = TimestampCounter::GetNanoTime(TimestampCounter::GetTimestamp());
   // Set the lsb to 0 to indicate method entry.
   init_time = init_time & ~1;
-  std::ostringstream os;
-  os << "Thread:" << thread->GetTid() << "\n";
   size_t index = kAlwaysOnTraceBufSize - 1;
   for (auto smi = visitor.stack_methods_.rbegin(); smi != visitor.stack_methods_.rend(); smi++) {
     method_trace_buffer[index--] = reinterpret_cast<uintptr_t>(*smi);
@@ -477,38 +495,60 @@ void TraceProfiler::TraceTimeElapsed() {
   TraceProfiler::StopLocked();
 }
 
-void TraceProfiler::DumpLongRunningMethodBuffer(uint32_t thread_id,
-                                                uintptr_t* method_trace_entries,
-                                                uintptr_t* end_trace_entries,
-                                                std::unordered_set<ArtMethod*>& methods,
-                                                std::ostringstream& os) {
-  os << "Thread:" << thread_id << "\n";
-  for (uintptr_t* ptr = method_trace_entries + kAlwaysOnTraceBufSize - 1;
-       ptr >= end_trace_entries;) {
-    uintptr_t entry = *ptr;
-    if (entry == 0x1) {
-      // This is the special placeholder exit we added to record all methods on the stack at the
-      // start of the trace. Just ignore this entry.
-    } else if (entry & 0x1) {
-      // Method exit
-      os << "<-" << TimestampCounter::GetNanoTime(entry & ~1) << "\n";
+size_t TraceProfiler::DumpLongRunningMethodBuffer(uint32_t thread_id,
+                                                  uintptr_t* method_trace_entries,
+                                                  uintptr_t* end_trace_entries,
+                                                  uint8_t* buffer,
+                                                  std::unordered_set<ArtMethod*>& methods) {
+  // Encode header at the end once we compute the number of records.
+  uint8_t* curr_buffer_ptr = buffer + kAlwaysOnTraceHeaderSize;
+
+  int num_records = 0;
+  uintptr_t prev_timestamp_action_encoding = 0;
+  uintptr_t prev_method_ptr = 0;
+  size_t end_index = end_trace_entries - method_trace_entries;
+  for (size_t i = kAlwaysOnTraceBufSize - 1; i >= end_index;) {
+    uintptr_t event = method_trace_entries[i--];
+    bool is_method_exit = event & 0x1;
+    uint64_t timestamp_action_encoding;
+    uintptr_t method_ptr;
+    if (is_method_exit) {
+      // Method exit. We only have timestamp here.
+      timestamp_action_encoding = event & ~1;
     } else {
-      // Method entry
-      ArtMethod* method = reinterpret_cast<ArtMethod*>(entry);
-      ptr--;
-      CHECK(ptr >= end_trace_entries);
-      os << "->" << method << " " << TimestampCounter::GetNanoTime(*ptr) << "\n";
+      // method entry
+      method_ptr = event;
+      timestamp_action_encoding = method_trace_entries[i--];
+    }
+
+    int64_t timestamp_action_diff = timestamp_action_encoding - prev_timestamp_action_encoding;
+    int64_t method_diff;
+    if (!is_method_exit) {
+      method_diff = method_ptr - prev_method_ptr;
+      ArtMethod* method = reinterpret_cast<ArtMethod*>(method_ptr);
       methods.insert(method);
+      prev_method_ptr = method_ptr;
+      curr_buffer_ptr = EncodeSignedLeb128(curr_buffer_ptr, method_diff);
     }
-    ptr--;
+    curr_buffer_ptr = EncodeSignedLeb128(curr_buffer_ptr, timestamp_action_diff);
+    num_records++;
+    prev_timestamp_action_encoding = timestamp_action_encoding;
   }
+
+  // Fill in header information:
+  // 1 byte of header identifier
+  // 4 bytes of thread_id
+  // 3 bytes of number of records
+  buffer[0] = kEntryHeaderV2;
+  Append4LE(buffer + 1, thread_id);
+  Append3LE(buffer + 5, num_records);
+  return curr_buffer_ptr - buffer;
 }
 
 void TraceProfiler::FlushBufferAndRecordTraceEvent(ArtMethod* method,
                                                    Thread* thread,
                                                    bool is_entry) {
   uint64_t timestamp = TimestampCounter::GetTimestamp();
-  std::ostringstream os;
   std::unordered_set<ArtMethod*> traced_methods;
   uintptr_t* method_trace_entries = thread->GetMethodTraceBuffer();
   DCHECK(method_trace_entries != nullptr);
@@ -529,19 +569,28 @@ void TraceProfiler::FlushBufferAndRecordTraceEvent(ArtMethod* method,
 
   size_t num_occupied_entries = (processed_events_ptr - *method_trace_curr_ptr);
   size_t index = kAlwaysOnTraceBufSize;
+
+  std::unique_ptr<uint8_t> buffer_ptr(new uint8_t[kBufSizeForEncodedData]);
+  size_t num_bytes;
   if (num_occupied_entries > kMaxEntriesAfterFlush) {
     // If we don't have sufficient space just record a placeholder exit and flush all the existing
     // events. We have accurate timestamps to filter out these events in a post-processing step.
     // This would happen only when we have very deeply (~1024) nested code.
-    DumpLongRunningMethodBuffer(
-        thread->GetTid(), method_trace_entries, *method_trace_curr_ptr, traced_methods, os);
+    num_bytes = DumpLongRunningMethodBuffer(thread->GetTid(),
+                                            method_trace_entries,
+                                            *method_trace_curr_ptr,
+                                            buffer_ptr.get(),
+                                            traced_methods);
 
     // Encode a placeholder exit event. This will be ignored when dumping the methods.
     method_trace_entries[--index] = 0x1;
   } else {
     // Flush all the entries till the method exit event.
-    DumpLongRunningMethodBuffer(
-        thread->GetTid(), method_trace_entries, processed_events_ptr, traced_methods, os);
+    num_bytes = DumpLongRunningMethodBuffer(thread->GetTid(),
+                                            method_trace_entries,
+                                            processed_events_ptr,
+                                            buffer_ptr.get(),
+                                            traced_methods);
 
     // Move the remaining events to the start of the buffer.
     for (uintptr_t* ptr = processed_events_ptr - 1; ptr >= *method_trace_curr_ptr; ptr--) {
@@ -569,7 +618,7 @@ void TraceProfiler::FlushBufferAndRecordTraceEvent(ArtMethod* method,
   *method_trace_curr_ptr = method_trace_entries + index;
 
   MutexLock mu(Thread::Current(), *Locks::trace_lock_);
-  trace_data_->AppendToLongRunningMethods(os.str());
+  trace_data_->AppendToLongRunningMethods(buffer_ptr.get(), num_bytes);
   trace_data_->AddTracedMethods(traced_methods);
   trace_data_->AddTracedThread(thread);
 }
@@ -590,10 +639,20 @@ void TraceDumpCheckpoint::Run(Thread* thread) {
     std::unordered_set<ArtMethod*> traced_methods;
     if (trace_data_->GetTraceType() == LowOverheadTraceType::kLongRunningMethods) {
       uintptr_t* method_trace_curr_ptr = *(thread->GetTraceBufferCurrEntryPtr());
-      std::ostringstream os;
-      TraceProfiler::DumpLongRunningMethodBuffer(
-          thread->GetTid(), method_trace_entries, method_trace_curr_ptr, traced_methods, os);
-      trace_data_->AppendToLongRunningMethods(os.str());
+      std::unique_ptr<uint8_t> buffer_ptr(new uint8_t[kBufSizeForEncodedData]);
+      size_t num_bytes = TraceProfiler::DumpLongRunningMethodBuffer(thread->GetTid(),
+                                                                    method_trace_entries,
+                                                                    method_trace_curr_ptr,
+                                                                    buffer_ptr.get(),
+                                                                    traced_methods);
+      MutexLock mu(Thread::Current(), trace_file_lock_);
+      if (trace_file_ != nullptr) {
+        if (!trace_file_->WriteFully(buffer_ptr.get(), num_bytes)) {
+          PLOG(WARNING) << "Failed streaming a tracing event.";
+        }
+      } else {
+        trace_data_->AppendToLongRunningMethods(buffer_ptr.get(), num_bytes);
+      }
     } else {
       std::unique_ptr<uint8_t> buffer_ptr(new uint8_t[kBufSizeForEncodedData]);
       size_t num_bytes = TraceProfiler::DumpBuffer(
@@ -632,8 +691,12 @@ void TraceData::DumpData(std::ostringstream& os) {
     // We cannot dump method information while holding trace_lock_, since we have to also
     // acquire a mutator lock. Take a snapshot of thread and method information.
     MutexLock mu(Thread::Current(), trace_data_lock_);
-    if (long_running_methods_.length() > 0) {
-      os << long_running_methods_;
+    if (curr_buffer_ != nullptr) {
+      for (size_t i = 0; i < overflow_buffers_.size(); i++) {
+        os.write(reinterpret_cast<char*>(overflow_buffers_[i].get()), kBufSizeForEncodedData);
+      }
+
+      os.write(reinterpret_cast<char*>(curr_buffer_.get()), curr_index_);
     }
 
     methods = traced_methods_;
diff --git a/runtime/trace_profile.h b/runtime/trace_profile.h
index df8ddec387..6cfc91b1fb 100644
--- a/runtime/trace_profile.h
+++ b/runtime/trace_profile.h
@@ -46,7 +46,9 @@ enum class LowOverheadTraceType {
 class TraceData {
  public:
   explicit TraceData(LowOverheadTraceType trace_type)
-      : trace_type_(trace_type),
+      : curr_buffer_(nullptr),
+        curr_index_(0),
+        trace_type_(trace_type),
         trace_end_time_(0),
         trace_dump_in_progress_(false),
         trace_dump_condition_("trace dump condition", *Locks::trace_lock_),
@@ -64,14 +66,11 @@ class TraceData {
     trace_end_time_ = end_time;
   }
 
-  // Dumps events collected in long_running_methods_ and the information about
-  // threads and methods into the output stream.
+  // Dumps events collected in the buffers and the information about threads and methods into the
+  // output stream.
   void DumpData(std::ostringstream& os);
 
-  void AppendToLongRunningMethods(const std::string& str) {
-    MutexLock mu(Thread::Current(), trace_data_lock_);
-    long_running_methods_.append(str);
-  }
+  void AppendToLongRunningMethods(const uint8_t* buffer, size_t size);
 
   void AddTracedMethods(std::unordered_set<ArtMethod*>& methods) {
     MutexLock mu(Thread::Current(), trace_data_lock_);
@@ -102,9 +101,14 @@ class TraceData {
   }
 
  private:
-  // This is used to hold the initial methods on stack and also long running methods when there is a
-  // buffer overflow.
-  std::string long_running_methods_ GUARDED_BY(trace_data_lock_);
+  // This is used to hold the long running methods when the per-thread buffer overflows.
+  std::unique_ptr<uint8_t> curr_buffer_ GUARDED_BY(trace_data_lock_);
+
+  // The index of the next free space in the curr_buffer_
+  size_t curr_index_ GUARDED_BY(trace_data_lock_);
+
+  // When the curr_buffer_ becomes full, we store it in this list and allocate a new buffer.
+  std::vector<std::unique_ptr<uint8_t>> overflow_buffers_ GUARDED_BY(trace_data_lock_);
 
   LowOverheadTraceType trace_type_;
 
@@ -126,7 +130,7 @@ class TraceData {
   bool trace_dump_in_progress_ GUARDED_BY(Locks::trace_lock_);
   ConditionVariable trace_dump_condition_ GUARDED_BY(Locks::trace_lock_);
 
-  // Lock to synchronize access to traced_methods_, traced_threads_ and long_running_methods_ which
+  // Lock to synchronize access to traced_methods_, traced_threads_ and curr_buffer_ which
   // can be accessed simultaneously by multiple threads when running TraceDumpCheckpoint.
   Mutex trace_data_lock_;
 };
@@ -150,7 +154,8 @@ class TraceDumpCheckpoint final : public Closure {
   // Trace data to record the data from each thread.
   TraceData* trace_data_;
 
-  // Trace file to flush the data.
+  // Trace file to flush the data. If the trace_file_ is empty then the data is recorded in the
+  // trace_data_.
   const std::unique_ptr<File>& trace_file_ GUARDED_BY(trace_file_lock_);
 
   // Lock to synchronize access to trace_file_. We need to write the data of
@@ -225,13 +230,13 @@ class TraceProfiler {
                            uint8_t* buffer /* out */,
                            std::unordered_set<ArtMethod*>& methods /* out */);
 
-  // Dumps all the events in the buffer into the file. Also records the ArtMethods from the events
-  // which is then used to record information about these methods.
-  static void DumpLongRunningMethodBuffer(uint32_t thread_id,
-                                          uintptr_t* thread_buffer,
-                                          uintptr_t* end_buffer,
-                                          std::unordered_set<ArtMethod*>& methods /* out */,
-                                          std::ostringstream& os);
+  // Dumps all the trace events from the thread into the buffer. Also records the ArtMethods from
+  // the events which is then used to record information about these methods.
+  static size_t DumpLongRunningMethodBuffer(uint32_t thread_id,
+                                            uintptr_t* method_trace_entries,
+                                            uintptr_t* end_trace_entries,
+                                            uint8_t* buffer,
+                                            std::unordered_set<ArtMethod*>& methods);
 
   static bool profile_in_progress_ GUARDED_BY(Locks::trace_lock_);