Add timing of allocation functions.

Report the time it takes to execute every different allocation function
during the replay.

Change-Id: I4e8321409357824c10f2f176b02c7c33538d353b

7 files changed, 62 insertions, 9 deletions

diff --git a/memory_replay/Action.cpp b/memory_replay/Action.cpp
index 3c97c438..c9671e17 100644
--- a/memory_replay/Action.cpp
+++ b/memory_replay/Action.cpp
@@ -21,6 +21,7 @@
 #include <stdlib.h>
 #include <string.h>
 #include <sys/param.h>
+#include <time.h>
 
 #include <new>
 
@@ -28,13 +29,20 @@
 #include "Threads.h"
 #include "Pointers.h"
 
+static uint64_t nanotime() {
+  struct timespec t;
+  t.tv_sec = t.tv_nsec = 0;
+  clock_gettime(CLOCK_MONOTONIC, &t);
+  return static_cast<uint64_t>(t.tv_sec) * 1000000000LL + t.tv_nsec;
+}
+
 class EndThreadAction : public Action {
  public:
   EndThreadAction() {}
 
   bool EndThread() override { return true; }
 
-  void Execute(Pointers*) override {}
+  uint64_t Execute(Pointers*) override { return 0; }
 };
 
 class AllocAction : public Action {
@@ -54,10 +62,15 @@ class MallocAction : public AllocAction {
     }
   }
 
-  void Execute(Pointers* pointers) override {
+  uint64_t Execute(Pointers* pointers) override {
+    uint64_t time_nsecs = nanotime();
     void* memory = malloc(size_);
+    time_nsecs = nanotime() - time_nsecs;
+
     memset(memory, 1, size_);
     pointers->Add(key_pointer_, memory);
+
+    return time_nsecs;
   }
 };
 
@@ -69,10 +82,15 @@ class CallocAction : public AllocAction {
     }
   }
 
-  void Execute(Pointers* pointers) override {
+  uint64_t Execute(Pointers* pointers) override {
+    uint64_t time_nsecs = nanotime();
     void* memory = calloc(n_elements_, size_);
+    time_nsecs = nanotime() - time_nsecs;
+
     memset(memory, 0, n_elements_ * size_);
     pointers->Add(key_pointer_, memory);
+
+    return time_nsecs;
   }
 
  private:
@@ -89,14 +107,20 @@ class ReallocAction : public AllocAction {
 
   bool DoesFree() override { return old_pointer_ != 0; }
 
-  void Execute(Pointers* pointers) override {
+  uint64_t Execute(Pointers* pointers) override {
     void* old_memory = nullptr;
     if (old_pointer_ != 0) {
       old_memory = pointers->Remove(old_pointer_);
     }
+
+    uint64_t time_nsecs = nanotime();
     void* memory = realloc(old_memory, size_);
+    time_nsecs = nanotime() - time_nsecs;
+
     memset(memory, 1, size_);
     pointers->Add(key_pointer_, memory);
+
+    return time_nsecs;
   }
 
  private:
@@ -111,10 +135,15 @@ class MemalignAction : public AllocAction {
     }
   }
 
-  void Execute(Pointers* pointers) override {
+  uint64_t Execute(Pointers* pointers) override {
+    uint64_t time_nsecs = nanotime();
     void* memory = memalign(align_, size_);
+    time_nsecs = nanotime() - time_nsecs;
+
     memset(memory, 1, size_);
     pointers->Add(key_pointer_, memory);
+
+    return time_nsecs;
   }
 
  private:
@@ -128,11 +157,14 @@ class FreeAction : public AllocAction {
 
   bool DoesFree() override { return key_pointer_ != 0; }
 
-  void Execute(Pointers* pointers) override {
+  uint64_t Execute(Pointers* pointers) override {
     if (key_pointer_) {
       void* memory = pointers->Remove(key_pointer_);
+      uint64_t time_nsecs = nanotime();
       free(memory);
+      return nanotime() - time_nsecs;
     }
+    return 0;
   }
 };
 
diff --git a/memory_replay/Action.h b/memory_replay/Action.h
index 0f010aaf..f498f526 100644
--- a/memory_replay/Action.h
+++ b/memory_replay/Action.h
@@ -26,7 +26,7 @@ class Action {
   Action() {}
   virtual ~Action() {}
 
-  virtual void Execute(Pointers* pointers) = 0;
+  virtual uint64_t Execute(Pointers* pointers) = 0;
 
   bool IsError() { return is_error_; };
 
diff --git a/memory_replay/Android.mk b/memory_replay/Android.mk
index c550d5ea..7179d614 100644
--- a/memory_replay/Android.mk
+++ b/memory_replay/Android.mk
@@ -26,6 +26,7 @@ LOCAL_CFLAGS := -Wall -Wextra -Werror
 LOCAL_MODULE_TAGS := debug
 LOCAL_MODULE := memory_replay
 LOCAL_MODULE_HOST_OS := linux
+LOCAL_LDLIBS := -lrt
 include $(BUILD_HOST_EXECUTABLE)
 
 memory_replay_test_src_files := \
@@ -67,7 +68,11 @@ LOCAL_MODULE := memory_replay_tests
 LOCAL_MODULE_HOST_OS := linux
 
 LOCAL_SHARED_LIBRARIES := libbase
+LOCAL_LDLIBS := -lrt
 
+LOCAL_MULTILIB := both
+LOCAL_MODULE_STEM_32 := $(LOCAL_MODULE)32
+LOCAL_MODULE_STEM_64 := $(LOCAL_MODULE)64
 include $(BUILD_HOST_NATIVE_TEST)
 
 memory_replay_src_files :=
diff --git a/memory_replay/Thread.h b/memory_replay/Thread.h
index 66226542..7724c12e 100644
--- a/memory_replay/Thread.h
+++ b/memory_replay/Thread.h
@@ -37,6 +37,7 @@ class Thread {
   void ClearPending();
 
   Action* CreateAction(uintptr_t key_pointer, const char* type, const char* line);
+  void AddTimeNsecs(uint64_t nsecs) { total_time_nsecs_ += nsecs; }
 
   void set_pointers(Pointers* pointers) { pointers_ = pointers; }
   Pointers* pointers() { return pointers_; }
@@ -50,6 +51,7 @@ class Thread {
 
   pthread_t thread_id_;
   pid_t tid_ = 0;
+  uint64_t total_time_nsecs_ = 0;
 
   Pointers* pointers_ = nullptr;
 
diff --git a/memory_replay/Threads.cpp b/memory_replay/Threads.cpp
index 24835e95..81a679e9 100644
--- a/memory_replay/Threads.cpp
+++ b/memory_replay/Threads.cpp
@@ -18,6 +18,8 @@
 #include <errno.h>
 #include <pthread.h>
 #include <stdint.h>
+#include <stdio.h>
+#include <stdlib.h>
 #include <string.h>
 #include <sys/mman.h>
 #include <unistd.h>
@@ -33,7 +35,7 @@ void* ThreadRunner(void* data) {
   while (true) {
     thread->WaitForPending();
     Action* action = thread->GetAction();
-    action->Execute(thread->pointers());
+    thread->AddTimeNsecs(action->Execute(thread->pointers()));
     bool end_thread = action->EndThread();
     thread->ClearPending();
     if (end_thread) {
@@ -82,6 +84,7 @@ Thread* Threads::CreateThread(pid_t tid) {
   }
   thread->tid_ = tid;
   thread->pointers_ = pointers_;
+  thread->total_time_nsecs_ = 0;
   if (pthread_create(&thread->thread_id_, nullptr, ThreadRunner, thread) == -1) {
     err(1, "Failed to create thread %d: %s\n", tid, strerror(errno));
   }
@@ -135,7 +138,12 @@ Thread* Threads::FindEmptyEntry(pid_t tid) {
 }
 
 void Threads::Finish(Thread* thread) {
-  pthread_join(thread->thread_id_, nullptr);
+  int ret = pthread_join(thread->thread_id_, nullptr);
+  if (ret != 0) {
+    fprintf(stderr, "pthread_join failed: %s\n", strerror(ret));
+    exit(1);
+  }
+  total_time_nsecs_ += thread->total_time_nsecs_;
   thread->tid_ = 0;
   num_threads_--;
 }
diff --git a/memory_replay/Threads.h b/memory_replay/Threads.h
index af4815c3..4778bff3 100644
--- a/memory_replay/Threads.h
+++ b/memory_replay/Threads.h
@@ -36,6 +36,7 @@ class Threads {
 
   size_t num_threads() { return num_threads_; }
   size_t max_threads() { return max_threads_; }
+  uint64_t total_time_nsecs() { return total_time_nsecs_; }
 
  private:
   Pointers* pointers_ = nullptr;
@@ -43,6 +44,7 @@ class Threads {
   size_t data_size_ = 0;
   size_t max_threads_ = 0;
   size_t num_threads_= 0;
+  uint64_t total_time_nsecs_ = 0;
 
   Thread* FindEmptyEntry(pid_t tid);
   size_t GetHashEntry(pid_t tid);
diff --git a/memory_replay/main.cpp b/memory_replay/main.cpp
index b4dbef24..42b52983 100644
--- a/memory_replay/main.cpp
+++ b/memory_replay/main.cpp
@@ -147,6 +147,10 @@ void ProcessDump(int fd, size_t max_allocs, size_t max_threads) {
   // is leaked and everything is accounted for during a run.
   threads.FinishAll();
   pointers.FreeAll();
+
+  // Print out the total time making all allocation calls.
+  printf("Total Allocation/Free Time: %" PRIu64 "ns %0.2fs\n",
+         threads.total_time_nsecs(), threads.total_time_nsecs()/1000000000.0);
 }
 
 constexpr size_t DEFAULT_MAX_THREADS = 512;