Merge "Add the timestamps for each alloc data"

libc/malloc_debug/RecordData.cpp

@@ -28,6 +28,7 @@
 
 #include <errno.h>
 #include <fcntl.h>
+#include <inttypes.h>
 #include <pthread.h>
 #include <stdatomic.h>
 #include <stdint.h>
@@ -52,40 +53,51 @@ bool ThreadCompleteEntry::Write(int fd) const {
   return dprintf(fd, "%d: thread_done 0x0\n", tid_) > 0;
 }
 
-AllocEntry::AllocEntry(void* pointer) : pointer_(pointer) {}
+AllocEntry::AllocEntry(void* pointer, uint64_t start_ns, uint64_t end_ns)
+    : pointer_(pointer), start_ns_(start_ns), end_ns_(end_ns) {}
 
-MallocEntry::MallocEntry(void* pointer, size_t size) : AllocEntry(pointer), size_(size) {}
+MallocEntry::MallocEntry(void* pointer, size_t size, uint64_t start_ns, uint64_t end_ns)
+    : AllocEntry(pointer, start_ns, end_ns), size_(size) {}
 
 bool MallocEntry::Write(int fd) const {
-  return dprintf(fd, "%d: malloc %p %zu\n", tid_, pointer_, size_) > 0;
+  return dprintf(fd, "%d: malloc %p %zu %" PRIu64 " %" PRIu64 "\n", tid_, pointer_, size_,
+                 start_ns_, end_ns_) > 0;
 }
 
-FreeEntry::FreeEntry(void* pointer) : AllocEntry(pointer) {}
+FreeEntry::FreeEntry(void* pointer, uint64_t start_ns, uint64_t end_ns)
+    : AllocEntry(pointer, start_ns, end_ns) {}
 
 bool FreeEntry::Write(int fd) const {
-  return dprintf(fd, "%d: free %p\n", tid_, pointer_) > 0;
+  return dprintf(fd, "%d: free %p %" PRIu64 " %" PRIu64 "\n", tid_, pointer_, start_ns_, end_ns_) >
+         0;
 }
 
-CallocEntry::CallocEntry(void* pointer, size_t nmemb, size_t size)
+CallocEntry::CallocEntry(void* pointer, size_t nmemb, size_t size, uint64_t start_ns,
-    : MallocEntry(pointer, size), nmemb_(nmemb) {}
+                         uint64_t end_ns)
+    : MallocEntry(pointer, size, start_ns, end_ns), nmemb_(nmemb) {}
 
 bool CallocEntry::Write(int fd) const {
-  return dprintf(fd, "%d: calloc %p %zu %zu\n", tid_, pointer_, nmemb_, size_) > 0;
+  return dprintf(fd, "%d: calloc %p %zu %zu %" PRIu64 " %" PRIu64 "\n", tid_, pointer_, nmemb_,
+                 size_, start_ns_, end_ns_) > 0;
 }
 
-ReallocEntry::ReallocEntry(void* pointer, size_t size, void* old_pointer)
+ReallocEntry::ReallocEntry(void* pointer, size_t size, void* old_pointer, uint64_t start_ns,
-    : MallocEntry(pointer, size), old_pointer_(old_pointer) {}
+                           uint64_t end_ns)
+    : MallocEntry(pointer, size, start_ns, end_ns), old_pointer_(old_pointer) {}
 
 bool ReallocEntry::Write(int fd) const {
-  return dprintf(fd, "%d: realloc %p %p %zu\n", tid_, pointer_, old_pointer_, size_) > 0;
+  return dprintf(fd, "%d: realloc %p %p %zu %" PRIu64 " %" PRIu64 "\n", tid_, pointer_,
+                 old_pointer_, size_, start_ns_, end_ns_) > 0;
 }
 
 // aligned_alloc, posix_memalign, memalign, pvalloc, valloc all recorded with this class.
-MemalignEntry::MemalignEntry(void* pointer, size_t size, size_t alignment)
+MemalignEntry::MemalignEntry(void* pointer, size_t size, size_t alignment, uint64_t start_ns,
-    : MallocEntry(pointer, size), alignment_(alignment) {}
+                             uint64_t end_ns)
+    : MallocEntry(pointer, size, start_ns, end_ns), alignment_(alignment) {}
 
 bool MemalignEntry::Write(int fd) const {
-  return dprintf(fd, "%d: memalign %p %zu %zu\n", tid_, pointer_, alignment_, size_) > 0;
+  return dprintf(fd, "%d: memalign %p %zu %zu %" PRIu64 " %" PRIu64 "\n", tid_, pointer_,
+                 alignment_, size_, start_ns_, end_ns_) > 0;
 }
 
 struct ThreadData {

libc/malloc_debug/RecordData.h

@@ -68,19 +68,23 @@ class ThreadCompleteEntry : public RecordEntry {
 
 class AllocEntry : public RecordEntry {
  public:
-  explicit AllocEntry(void* pointer);
+  explicit AllocEntry(void* pointer, uint64_t st, uint64_t et);
   virtual ~AllocEntry() = default;
 
  protected:
   void* pointer_;
 
+  // The start/end time of this operation.
+  uint64_t start_ns_;
+  uint64_t end_ns_;
+
  private:
   BIONIC_DISALLOW_COPY_AND_ASSIGN(AllocEntry);
 };
 
 class MallocEntry : public AllocEntry {
  public:
-  MallocEntry(void* pointer, size_t size);
+  MallocEntry(void* pointer, size_t size, uint64_t st, uint64_t et);
   virtual ~MallocEntry() = default;
 
   bool Write(int fd) const override;
@@ -94,7 +98,7 @@ class MallocEntry : public AllocEntry {
 
 class FreeEntry : public AllocEntry {
  public:
-  explicit FreeEntry(void* pointer);
+  explicit FreeEntry(void* pointer, uint64_t st, uint64_t et);
   virtual ~FreeEntry() = default;
 
   bool Write(int fd) const override;
@@ -105,7 +109,7 @@ class FreeEntry : public AllocEntry {
 
 class CallocEntry : public MallocEntry {
  public:
-  CallocEntry(void* pointer, size_t size, size_t nmemb);
+  CallocEntry(void* pointer, size_t size, size_t nmemb, uint64_t st, uint64_t et);
   virtual ~CallocEntry() = default;
 
   bool Write(int fd) const override;
@@ -119,7 +123,7 @@ class CallocEntry : public MallocEntry {
 
 class ReallocEntry : public MallocEntry {
  public:
-  ReallocEntry(void* pointer, size_t size, void* old_pointer);
+  ReallocEntry(void* pointer, size_t size, void* old_pointer, uint64_t st, uint64_t et);
   virtual ~ReallocEntry() = default;
 
   bool Write(int fd) const override;
@@ -134,7 +138,7 @@ class ReallocEntry : public MallocEntry {
 // aligned_alloc, posix_memalign, memalign, pvalloc, valloc all recorded with this class.
 class MemalignEntry : public MallocEntry {
  public:
-  MemalignEntry(void* pointer, size_t size, size_t alignment);
+  MemalignEntry(void* pointer, size_t size, size_t alignment, uint64_t st, uint64_t et);
   virtual ~MemalignEntry() = default;
 
   bool Write(int fd) const override;

libc/malloc_debug/malloc_debug.cpp

@@ -68,6 +68,100 @@ DebugData* g_debug;
 bool* g_zygote_child;
 
 const MallocDispatch* g_dispatch;
+
+static __always_inline uint64_t Nanotime() {
+  struct timespec t = {};
+  clock_gettime(CLOCK_MONOTONIC, &t);
+  return static_cast<uint64_t>(t.tv_sec) * 1000000000LL + t.tv_nsec;
+}
+
+namespace {
+// A TimedResult contains the result of from malloc end_ns al. functions and the
+// start/end timestamps.
+struct TimedResult {
+  uint64_t start_ns = 0;
+  uint64_t end_ns = 0;
+  union {
+    size_t s;
+    int i;
+    void* p;
+  } v;
+
+  uint64_t GetStartTimeNS() const { return start_ns; }
+  uint64_t GetEndTimeNS() const { return end_ns; }
+  void SetStartTimeNS(uint64_t t) { start_ns = t; }
+  void SetEndTimeNS(uint64_t t) { end_ns = t; }
+
+  template <typename T>
+  void setValue(T);
+  template <>
+  void setValue(size_t s) {
+    v.s = s;
+  }
+  template <>
+  void setValue(int i) {
+    v.i = i;
+  }
+  template <>
+  void setValue(void* p) {
+    v.p = p;
+  }
+
+  template <typename T>
+  T getValue() const;
+  template <>
+  size_t getValue<size_t>() const {
+    return v.s;
+  }
+  template <>
+  int getValue<int>() const {
+    return v.i;
+  }
+  template <>
+  void* getValue<void*>() const {
+    return v.p;
+  }
+};
+
+class ScopedTimer {
+ public:
+  ScopedTimer(TimedResult& res) : res_(res) { res_.start_ns = Nanotime(); }
+
+  ~ScopedTimer() { res_.end_ns = Nanotime(); }
+
+ private:
+  TimedResult& res_;
+};
+
+}  // namespace
+
+template <typename MallocFn, typename... Args>
+static TimedResult TimerCall(MallocFn fn, Args... args) {
+  TimedResult ret;
+  decltype((g_dispatch->*fn)(args...)) r;
+  if (g_debug->config().options() & RECORD_ALLOCS) {
+    ScopedTimer t(ret);
+    r = (g_dispatch->*fn)(args...);
+  } else {
+    r = (g_dispatch->*fn)(args...);
+  }
+  ret.setValue<decltype(r)>(r);
+  return ret;
+}
+
+template <typename MallocFn, typename... Args>
+static TimedResult TimerCallVoid(MallocFn fn, Args... args) {
+  TimedResult ret;
+  {
+    ScopedTimer t(ret);
+    (g_dispatch->*fn)(args...);
+  }
+  return ret;
+}
+
+#define TCALL(FUNC, ...) TimerCall(&MallocDispatch::FUNC, __VA_ARGS__);
+#define TCALLVOID(FUNC, ...) TimerCallVoid(&MallocDispatch::FUNC, __VA_ARGS__);
+
 // ------------------------------------------------------------------------
 
 // ------------------------------------------------------------------------
@@ -419,7 +513,7 @@ size_t debug_malloc_usable_size(void* pointer) {
   return InternalMallocUsableSize(pointer);
 }
 
-static void* InternalMalloc(size_t size) {
+static TimedResult InternalMalloc(size_t size) {
   if ((g_debug->config().options() & BACKTRACE) && g_debug->pointer->ShouldDumpAndReset()) {
     debug_dump_heap(android::base::StringPrintf(
                         "%s.%d.txt", g_debug->config().backtrace_dump_prefix().c_str(), getpid())
@@ -430,30 +524,35 @@ static void* InternalMalloc(size_t size) {
     size = 1;
   }
 
+  TimedResult result;
+
   size_t real_size = size + g_debug->extra_bytes();
   if (real_size < size) {
     // Overflow.
     errno = ENOMEM;
-    return nullptr;
+    result.setValue<void*>(nullptr);
+    return result;
   }
 
   if (size > PointerInfoType::MaxSize()) {
     errno = ENOMEM;
-    return nullptr;
+    result.setValue<void*>(nullptr);
+    return result;
   }
 
-  void* pointer;
   if (g_debug->HeaderEnabled()) {
-    Header* header =
+    result = TCALL(memalign, MINIMUM_ALIGNMENT_BYTES, real_size);
-        reinterpret_cast<Header*>(g_dispatch->memalign(MINIMUM_ALIGNMENT_BYTES, real_size));
+    Header* header = reinterpret_cast<Header*>(result.getValue<void*>());
     if (header == nullptr) {
-      return nullptr;
+      return result;
     }
-    pointer = InitHeader(header, header, size);
+    result.setValue<void*>(InitHeader(header, header, size));
   } else {
-    pointer = g_dispatch->malloc(real_size);
+    result = TCALL(malloc, real_size);
   }
 
+  void* pointer = result.getValue<void*>();
+
   if (pointer != nullptr) {
     if (g_debug->TrackPointers()) {
       PointerData::Add(pointer, size);
@@ -466,7 +565,8 @@ static void* InternalMalloc(size_t size) {
       memset(pointer, g_debug->config().fill_alloc_value(), bytes);
     }
   }
-  return pointer;
+
+  return result;
 }
 
 void* debug_malloc(size_t size) {
@@ -479,16 +579,17 @@ void* debug_malloc(size_t size) {
   ScopedDisableDebugCalls disable;
   ScopedBacktraceSignalBlocker blocked;
 
-  void* pointer = InternalMalloc(size);
+  TimedResult result = InternalMalloc(size);
 
   if (g_debug->config().options() & RECORD_ALLOCS) {
-    g_debug->record->AddEntry(new MallocEntry(pointer, size));
+    g_debug->record->AddEntry(new MallocEntry(result.getValue<void*>(), size,
+                                              result.GetStartTimeNS(), result.GetEndTimeNS()));
   }
 
-  return pointer;
+  return result.getValue<void*>();
 }
 
-static void InternalFree(void* pointer) {
+static TimedResult InternalFree(void* pointer) {
   if ((g_debug->config().options() & BACKTRACE) && g_debug->pointer->ShouldDumpAndReset()) {
     debug_dump_heap(android::base::StringPrintf(
                         "%s.%d.txt", g_debug->config().backtrace_dump_prefix().c_str(), getpid())
@@ -530,6 +631,7 @@ static void InternalFree(void* pointer) {
     PointerData::Remove(pointer);
   }
 
+  TimedResult result;
   if (g_debug->config().options() & FREE_TRACK) {
     // Do not add the allocation until we are done modifying the pointer
     // itself. This avoids a race if a lot of threads are all doing
@@ -537,15 +639,15 @@ static void InternalFree(void* pointer) {
     // pointer from another thread, while still trying to free it in
     // this function.
     pointer = PointerData::AddFreed(pointer, bytes);
-    if (pointer != nullptr) {
+    if (pointer != nullptr && g_debug->HeaderEnabled()) {
-      if (g_debug->HeaderEnabled()) {
+      pointer = g_debug->GetHeader(pointer)->orig_pointer;
-        pointer = g_debug->GetHeader(pointer)->orig_pointer;
-      }
-      g_dispatch->free(pointer);
     }
+    result = TCALLVOID(free, pointer);
   } else {
-    g_dispatch->free(free_pointer);
+    result = TCALLVOID(free, free_pointer);
   }
+
+  return result;
 }
 
 void debug_free(void* pointer) {
@@ -558,15 +660,16 @@ void debug_free(void* pointer) {
   ScopedDisableDebugCalls disable;
   ScopedBacktraceSignalBlocker blocked;
 
-  if (g_debug->config().options() & RECORD_ALLOCS) {
-    g_debug->record->AddEntry(new FreeEntry(pointer));
-  }
-
   if (!VerifyPointer(pointer, "free")) {
     return;
   }
 
-  InternalFree(pointer);
+  TimedResult result = InternalFree(pointer);
+
+  if (g_debug->config().options() & RECORD_ALLOCS) {
+    g_debug->record->AddEntry(
+        new FreeEntry(pointer, result.GetStartTimeNS(), result.GetEndTimeNS()));
+  }
 }
 
 void* debug_memalign(size_t alignment, size_t bytes) {
@@ -588,6 +691,7 @@ void* debug_memalign(size_t alignment, size_t bytes) {
     return nullptr;
   }
 
+  TimedResult result;
   void* pointer;
   if (g_debug->HeaderEnabled()) {
     // Make the alignment a power of two.
@@ -610,7 +714,8 @@ void* debug_memalign(size_t alignment, size_t bytes) {
       return nullptr;
     }
 
-    pointer = g_dispatch->malloc(real_size);
+    result = TCALL(malloc, real_size);
+    pointer = result.getValue<void*>();
     if (pointer == nullptr) {
       return nullptr;
     }
@@ -620,6 +725,7 @@ void* debug_memalign(size_t alignment, size_t bytes) {
     value += (-value % alignment);
 
     Header* header = g_debug->GetHeader(reinterpret_cast<void*>(value));
+    // Don't need to update `result` here because we only need the timestamps.
     pointer = InitHeader(header, pointer, bytes);
   } else {
     size_t real_size = bytes + g_debug->extra_bytes();
@@ -628,7 +734,8 @@ void* debug_memalign(size_t alignment, size_t bytes) {
       errno = ENOMEM;
       return nullptr;
     }
-    pointer = g_dispatch->memalign(alignment, real_size);
+    result = TCALL(memalign, alignment, real_size);
+    pointer = result.getValue<void*>();
   }
 
   if (pointer != nullptr) {
@@ -644,7 +751,8 @@ void* debug_memalign(size_t alignment, size_t bytes) {
     }
 
     if (g_debug->config().options() & RECORD_ALLOCS) {
-      g_debug->record->AddEntry(new MemalignEntry(pointer, bytes, alignment));
+      g_debug->record->AddEntry(new MemalignEntry(pointer, bytes, alignment,
+                                                  result.GetStartTimeNS(), result.GetEndTimeNS()));
     }
   }
 
@@ -662,10 +770,12 @@ void* debug_realloc(void* pointer, size_t bytes) {
   ScopedBacktraceSignalBlocker blocked;
 
   if (pointer == nullptr) {
-    pointer = InternalMalloc(bytes);
+    TimedResult result = InternalMalloc(bytes);
     if (g_debug->config().options() & RECORD_ALLOCS) {
-      g_debug->record->AddEntry(new ReallocEntry(pointer, bytes, nullptr));
+      g_debug->record->AddEntry(new ReallocEntry(result.getValue<void*>(), bytes, nullptr,
+                                                 result.GetStartTimeNS(), result.GetEndTimeNS()));
     }
+    pointer = result.getValue<void*>();
     return pointer;
   }
 
@@ -674,11 +784,13 @@ void* debug_realloc(void* pointer, size_t bytes) {
   }
 
   if (bytes == 0) {
+    TimedResult result = InternalFree(pointer);
+
     if (g_debug->config().options() & RECORD_ALLOCS) {
-      g_debug->record->AddEntry(new ReallocEntry(nullptr, bytes, pointer));
+      g_debug->record->AddEntry(new ReallocEntry(nullptr, bytes, pointer, result.GetStartTimeNS(),
+                                                 result.GetEndTimeNS()));
     }
 
-    InternalFree(pointer);
     return nullptr;
   }
 
@@ -697,6 +809,7 @@ void* debug_realloc(void* pointer, size_t bytes) {
     return nullptr;
   }
 
+  TimedResult result;
   void* new_pointer;
   size_t prev_size;
   if (g_debug->HeaderEnabled()) {
@@ -730,7 +843,8 @@ void* debug_realloc(void* pointer, size_t bytes) {
     }
 
     // Allocate the new size.
-    new_pointer = InternalMalloc(bytes);
+    result = InternalMalloc(bytes);
+    new_pointer = result.getValue<void*>();
     if (new_pointer == nullptr) {
       errno = ENOMEM;
       return nullptr;
@@ -738,14 +852,18 @@ void* debug_realloc(void* pointer, size_t bytes) {
 
     prev_size = header->usable_size;
     memcpy(new_pointer, pointer, prev_size);
-    InternalFree(pointer);
+    TimedResult free_time = InternalFree(pointer);
+    // `realloc` is split into two steps, update the end time to the finish time
+    // of the second operation.
+    result.SetEndTimeNS(free_time.GetEndTimeNS());
   } else {
     if (g_debug->TrackPointers()) {
       PointerData::Remove(pointer);
     }
 
     prev_size = g_dispatch->malloc_usable_size(pointer);
-    new_pointer = g_dispatch->realloc(pointer, real_size);
+    result = TCALL(realloc, pointer, real_size);
+    new_pointer = result.getValue<void*>();
     if (new_pointer == nullptr) {
       return nullptr;
     }
@@ -767,7 +885,8 @@ void* debug_realloc(void* pointer, size_t bytes) {
   }
 
   if (g_debug->config().options() & RECORD_ALLOCS) {
-    g_debug->record->AddEntry(new ReallocEntry(new_pointer, bytes, pointer));
+    g_debug->record->AddEntry(new ReallocEntry(new_pointer, bytes, pointer, result.GetStartTimeNS(),
+                                               result.GetEndTimeNS()));
   }
 
   return new_pointer;
@@ -807,21 +926,24 @@ void* debug_calloc(size_t nmemb, size_t bytes) {
   }
 
   void* pointer;
+  TimedResult result;
   if (g_debug->HeaderEnabled()) {
     // Need to guarantee the alignment of the header.
-    Header* header =
+    result = TCALL(memalign, MINIMUM_ALIGNMENT_BYTES, real_size);
-        reinterpret_cast<Header*>(g_dispatch->memalign(MINIMUM_ALIGNMENT_BYTES, real_size));
+    Header* header = reinterpret_cast<Header*>(result.getValue<void*>());
     if (header == nullptr) {
       return nullptr;
     }
     memset(header, 0, g_dispatch->malloc_usable_size(header));
     pointer = InitHeader(header, header, size);
   } else {
-    pointer = g_dispatch->calloc(1, real_size);
+    result = TCALL(calloc, 1, real_size);
+    pointer = result.getValue<void*>();
   }
 
   if (g_debug->config().options() & RECORD_ALLOCS) {
-    g_debug->record->AddEntry(new CallocEntry(pointer, bytes, nmemb));
+    g_debug->record->AddEntry(
+        new CallocEntry(pointer, bytes, nmemb, result.GetStartTimeNS(), result.GetEndTimeNS()));
   }
 
   if (pointer != nullptr && g_debug->TrackPointers()) {

libc/malloc_debug/tests/malloc_debug_unit_tests.cpp

@@ -184,6 +184,23 @@ std::string ShowDiffs(uint8_t* a, uint8_t* b, size_t size) {
   return diff;
 }
 
+static void VerifyRecords(std::vector<std::string>& expected, std::string& actual) {
+  size_t offset = 0;
+  for (std::string& str : expected) {
+    ASSERT_STREQ(str.c_str(), actual.substr(offset, str.size()).c_str());
+    if (str.find("thread_done") != std::string::npos) {
+      offset = actual.find_first_of("\n", offset) + 1;
+      continue;
+    }
+    offset += str.size() + 1;
+    uint64_t st = strtoull(&actual[offset], nullptr, 10);
+    offset = actual.find_first_of(" ", offset) + 1;
+    uint64_t et = strtoull(&actual[offset], nullptr, 10);
+    ASSERT_GT(et, st);
+    offset = actual.find_first_of("\n", offset) + 1;
+  }
+}
+
 void VerifyAllocCalls(bool all_options) {
   size_t alloc_size = 1024;
 
@@ -2171,61 +2188,61 @@ TEST_F(MallocDebugTest, debug_valloc) {
 #endif
 
 void VerifyRecordAllocs(const std::string& record_filename) {
-  std::string expected;
+  std::vector<std::string> expected;
 
   void* pointer = debug_malloc(10);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: malloc %p 10\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 10", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   pointer = debug_calloc(1, 20);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: calloc %p 20 1\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: calloc %p 20 1", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   pointer = debug_realloc(nullptr, 30);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: realloc %p 0x0 30\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: realloc %p 0x0 30", getpid(), pointer));
   void* old_pointer = pointer;
   pointer = debug_realloc(pointer, 2048);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: realloc %p %p 2048\n", getpid(),
+  expected.push_back(
-                                          pointer, old_pointer);
+      android::base::StringPrintf("%d: realloc %p %p 2048", getpid(), pointer, old_pointer));
   debug_realloc(pointer, 0);
-  expected += android::base::StringPrintf("%d: realloc 0x0 %p 0\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: realloc 0x0 %p 0", getpid(), pointer));
 
   pointer = debug_memalign(16, 40);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: memalign %p 16 40\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: memalign %p 16 40", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   pointer = debug_aligned_alloc(32, 64);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: memalign %p 32 64\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: memalign %p 32 64", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   ASSERT_EQ(0, debug_posix_memalign(&pointer, 32, 50));
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: memalign %p 32 50\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: memalign %p 32 50", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
 #if defined(HAVE_DEPRECATED_MALLOC_FUNCS)
   pointer = debug_pvalloc(60);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: memalign %p 4096 4096\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: memalign %p 4096 4096", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   pointer = debug_valloc(70);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: memalign %p 4096 70\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: memalign %p 4096 70", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 #endif
 
   // Dump all of the data accumulated so far.
@@ -2235,7 +2252,7 @@ void VerifyRecordAllocs(const std::string& record_filename) {
   std::string actual;
   ASSERT_TRUE(android::base::ReadFileToString(record_filename, &actual));
 
-  ASSERT_STREQ(expected.c_str(), actual.c_str());
+  VerifyRecords(expected, actual);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   ASSERT_STREQ("", getFakeLogPrint().c_str());
@@ -2256,23 +2273,23 @@ TEST_F(MallocDebugTest, record_allocs_with_header) {
 TEST_F(MallocDebugTest, record_allocs_max) {
   InitRecordAllocs("record_allocs=5");
 
-  std::string expected;
+  std::vector<std::string> expected;
 
   void* pointer = debug_malloc(10);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: malloc %p 10\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 10", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   pointer = debug_malloc(20);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: malloc %p 20\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 20", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   pointer = debug_malloc(1024);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: malloc %p 1024\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 1024", getpid(), pointer));
   debug_free(pointer);
 
   // Dump all of the data accumulated so far.
@@ -2282,7 +2299,7 @@ TEST_F(MallocDebugTest, record_allocs_max) {
   std::string actual;
   ASSERT_TRUE(android::base::ReadFileToString(record_filename, &actual));
 
-  ASSERT_STREQ(expected.c_str(), actual.c_str());
+  VerifyRecords(expected, actual);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   ASSERT_STREQ(
@@ -2303,9 +2320,10 @@ TEST_F(MallocDebugTest, record_allocs_thread_done) {
   });
   thread.join();
 
-  std::string expected = android::base::StringPrintf("%d: malloc %p 100\n", tid, pointer);
+  std::vector<std::string> expected;
-  expected += android::base::StringPrintf("%d: free %p\n", tid, pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 100", tid, pointer));
-  expected += android::base::StringPrintf("%d: thread_done 0x0\n", tid);
+  expected.push_back(android::base::StringPrintf("%d: free %p", tid, pointer));
+  expected.push_back(android::base::StringPrintf("%d: thread_done 0x0", tid));
 
   // Dump all of the data accumulated so far.
   ASSERT_TRUE(kill(getpid(), SIGRTMAX - 18) == 0);
@@ -2314,7 +2332,7 @@ TEST_F(MallocDebugTest, record_allocs_thread_done) {
   std::string actual;
   ASSERT_TRUE(android::base::ReadFileToString(record_filename, &actual));
 
-  ASSERT_STREQ(expected.c_str(), actual.c_str());
+  VerifyRecords(expected, actual);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   ASSERT_STREQ("", getFakeLogPrint().c_str());
@@ -2329,13 +2347,13 @@ TEST_F(MallocDebugTest, record_allocs_file_name_fail) {
 
   ASSERT_EQ(0, symlink("/data/local/tmp/does_not_exist", record_filename.c_str()));
 
-  std::string expected;
+  std::vector<std::string> expected;
 
   void* pointer = debug_malloc(10);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: malloc %p 10\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 10", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   // Dump all of the data accumulated so far.
   ASSERT_TRUE(kill(getpid(), SIGRTMAX - 18) == 0);
@@ -2351,7 +2369,8 @@ TEST_F(MallocDebugTest, record_allocs_file_name_fail) {
   ASSERT_TRUE(kill(getpid(), SIGRTMAX - 18) == 0);
 
   ASSERT_TRUE(android::base::ReadFileToString(record_filename, &actual));
-  ASSERT_STREQ(expected.c_str(), actual.c_str());
+
+  VerifyRecords(expected, actual);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   std::string expected_log = android::base::StringPrintf(
@@ -2375,13 +2394,13 @@ TEST_F(MallocDebugTest, record_allocs_no_entries_to_write) {
 TEST_F(MallocDebugTest, record_allocs_write_entries_does_not_allocate) {
   InitRecordAllocs("record_allocs=5");
 
-  std::string expected;
+  std::vector<std::string> expected;
 
   void* pointer = debug_malloc(10);
   ASSERT_TRUE(pointer != nullptr);
-  expected += android::base::StringPrintf("%d: malloc %p 10\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: malloc %p 10", getpid(), pointer));
   debug_free(pointer);
-  expected += android::base::StringPrintf("%d: free %p\n", getpid(), pointer);
+  expected.push_back(android::base::StringPrintf("%d: free %p", getpid(), pointer));
 
   malloc_disable();
   kill(getpid(), SIGRTMAX - 18);
@@ -2389,7 +2408,8 @@ TEST_F(MallocDebugTest, record_allocs_write_entries_does_not_allocate) {
 
   std::string actual;
   ASSERT_TRUE(android::base::ReadFileToString(record_filename, &actual));
-  ASSERT_STREQ(expected.c_str(), actual.c_str());
+
+  VerifyRecords(expected, actual);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   ASSERT_STREQ("", getFakeLogPrint().c_str());