Automate ipc_perftests.

Make it run with a decent spread of parameters.

TBR=jam

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

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

1 files changed, 151 insertions, 81 deletions

diff --git a/ipc/ipc_perftests.cc b/ipc/ipc_perftests.cc
index d6473cb..98aae54 100644
--- a/ipc/ipc_perftests.cc
+++ b/ipc/ipc_perftests.cc
@@ -11,13 +11,15 @@
 #include <unistd.h>
 #endif
 
+#include <algorithm>
 #include <string>
 
-#include "base/base_switches.h"
-#include "base/command_line.h"
-#include "base/debug/debug_on_start_win.h"
+#include "base/basictypes.h"
+#include "base/logging.h"
+#include "base/memory/scoped_ptr.h"
 #include "base/perftimer.h"
 #include "base/pickle.h"
+#include "base/stringprintf.h"
 #include "base/threading/thread.h"
 #include "base/time.h"
 #include "ipc/ipc_descriptors.h"
@@ -31,38 +33,74 @@
 
 namespace {
 
-// This test times the roundtrip IPC message cycle. It is enabled with a
-// special preprocessor define to enable it instead of the standard IPC
-// unit tests. This works around some funny termination conditions in the
-// regular unit tests.
+// This test times the roundtrip IPC message cycle.
 //
-// This test is not automated. To test, you will want to vary the message
-// count and message size in TEST to get the numbers you want.
-//
-// FIXME(brettw): Automate this test and have it run by default.
+// TODO(brettw): Make this test run by default.
 
 class IPCChannelPerfTest : public IPCTestBase {
 };
 
+// This class simply collects stats about abstract "events" (each of which has a
+// start time and an end time).
+class EventTimeTracker {
+ public:
+  explicit EventTimeTracker(const char* name)
+      : name_(name),
+        count_(0) {
+  }
+
+  void AddEvent(const base::TimeTicks& start, const base::TimeTicks& end) {
+    DCHECK(end >= start);
+    count_++;
+    base::TimeDelta duration = end - start;
+    total_duration_ += duration;
+    max_duration_ = std::max(max_duration_, duration);
+  }
+
+  void ShowResults() const {
+    VLOG(1) << name_ << " count: " << count_;
+    VLOG(1) << name_ << " total duration: "
+            << total_duration_.InMillisecondsF() << " ms";
+    VLOG(1) << name_ << " average duration: "
+            << (total_duration_.InMillisecondsF() / static_cast<double>(count_))
+            << " ms";
+    VLOG(1) << name_ << " maximum duration: "
+            << max_duration_.InMillisecondsF() << " ms";
+  }
+
+  void Reset() {
+    count_ = 0;
+    total_duration_ = base::TimeDelta();
+    max_duration_ = base::TimeDelta();
+  }
+
+ private:
+  const std::string name_;
+
+  uint64 count_;
+  base::TimeDelta total_duration_;
+  base::TimeDelta max_duration_;
+
+  DISALLOW_COPY_AND_ASSIGN(EventTimeTracker);
+};
+
 // This channel listener just replies to all messages with the exact same
 // message. It assumes each message has one string parameter. When the string
 // "quit" is sent, it will exit.
 class ChannelReflectorListener : public IPC::Listener {
  public:
-  explicit ChannelReflectorListener(IPC::Channel *channel) :
-    channel_(channel),
-    count_messages_(0) {
-    std::cout << "Reflector up" << std::endl;
+  explicit ChannelReflectorListener(IPC::Channel* channel)
+      : channel_(channel),
+        latency_tracker_("Client messages") {
+    VLOG(1) << "Client listener up";
   }
 
   ~ChannelReflectorListener() {
-    std::cout << "Client Messages: " << count_messages_ << std::endl;
-    std::cout << "Client Latency: " << latency_messages_.InMilliseconds()
-              << std::endl;
+    VLOG(1) << "Client listener down";
+    latency_tracker_.ShowResults();
   }
 
   virtual bool OnMessageReceived(const IPC::Message& message) {
-    count_messages_++;
     PickleIterator iter(message);
     int64 time_internal;
     EXPECT_TRUE(iter.ReadInt64(&time_internal));
@@ -70,17 +108,23 @@ class ChannelReflectorListener : public IPC::Listener {
     EXPECT_TRUE(iter.ReadInt(&msgid));
     std::string payload;
     EXPECT_TRUE(iter.ReadString(&payload));
-    // TODO(vtl): Should we use |HighResNow()| instead of |Now()|?
-    latency_messages_ += base::TimeTicks::Now() -
-                         base::TimeTicks::FromInternalValue(time_internal);
 
-    // cout << "reflector msg received: " << msgid << endl;
-    if (payload == "quit")
-      MessageLoop::current()->Quit();
+    // Include message deserialization in latency.
+    base::TimeTicks now = base::TimeTicks::Now();
+
+    if (payload == "hello") {
+      latency_tracker_.Reset();
+    } else if (payload == "quit") {
+      latency_tracker_.ShowResults();
+      MessageLoop::current()->QuitWhenIdle();
+      return true;
+    } else {
+      // Don't track hello and quit messages.
+      latency_tracker_.AddEvent(
+          base::TimeTicks::FromInternalValue(time_internal), now);
+    }
 
-    IPC::Message* msg = new IPC::Message(0,
-                                         2,
-                                         IPC::Message::PRIORITY_NORMAL);
+    IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
     msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
     msg->WriteInt(msgid);
     msg->WriteString(payload);
@@ -89,59 +133,70 @@ class ChannelReflectorListener : public IPC::Listener {
   }
 
  private:
-  IPC::Channel *channel_;
-  int count_messages_;
-  base::TimeDelta latency_messages_;
+  IPC::Channel* channel_;
+  EventTimeTracker latency_tracker_;
 };
 
 class ChannelPerfListener : public IPC::Listener {
  public:
-  ChannelPerfListener(IPC::Channel* channel, int msg_count, int msg_size) :
-       count_down_(msg_count),
-       channel_(channel),
-       count_messages_(0) {
-    payload_.resize(msg_size);
-    for (int i = 0; i < static_cast<int>(payload_.size()); i++)
-      payload_[i] = 'a';
-    std::cout << "perflistener up" << std::endl;
+  ChannelPerfListener(IPC::Channel* channel)
+      : channel_(channel),
+        msg_count_(0),
+        msg_size_(0),
+        count_down_(0),
+        latency_tracker_("Server messages") {
+    VLOG(1) << "Server listener up";
   }
 
   ~ChannelPerfListener() {
-    std::cout << "Server Messages: " << count_messages_ << std::endl;
-    std::cout << "Server Latency: " << latency_messages_.InMilliseconds()
-              << std::endl;
+    VLOG(1) << "Server listener down";
+  }
+
+  // Call this before running the message loop.
+  void SetTestParams(int msg_count, size_t msg_size) {
+    DCHECK_EQ(0, count_down_);
+    msg_count_ = msg_count;
+    msg_size_ = msg_size;
+    count_down_ = msg_count_;
+    payload_ = std::string(msg_size_, 'a');
   }
 
   virtual bool OnMessageReceived(const IPC::Message& message) {
-    count_messages_++;
-    // Decode the string so this gets counted in the total time.
     PickleIterator iter(message);
     int64 time_internal;
     EXPECT_TRUE(iter.ReadInt64(&time_internal));
     int msgid;
     EXPECT_TRUE(iter.ReadInt(&msgid));
-    std::string cur;
-    EXPECT_TRUE(iter.ReadString(&cur));
-    latency_messages_ += base::TimeTicks::Now() -
-                         base::TimeTicks::FromInternalValue(time_internal);
-
-    count_down_--;
-    if (count_down_ == 0) {
-      IPC::Message* msg = new IPC::Message(0,
-                                           2,
-                                           IPC::Message::PRIORITY_NORMAL);
-      msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
-      msg->WriteInt(count_down_);
-      msg->WriteString("quit");
-      channel_->Send(msg);
+    std::string reflected_payload;
+    EXPECT_TRUE(iter.ReadString(&reflected_payload));
 
-      MessageLoop::current()->QuitWhenIdle();
-      return true;
+    // Include message deserialization in latency.
+    base::TimeTicks now = base::TimeTicks::Now();
+
+    if (reflected_payload == "hello") {
+      // Start timing on hello.
+      latency_tracker_.Reset();
+      DCHECK(!perf_logger_.get());
+      std::string test_name = base::StringPrintf(
+          "IPC_Perf_%dx_%u", msg_count_, static_cast<unsigned>(msg_size_));
+      perf_logger_.reset(new PerfTimeLogger(test_name.c_str()));
+    } else {
+      DCHECK_EQ(payload_.size(), reflected_payload.size());
+
+      latency_tracker_.AddEvent(
+          base::TimeTicks::FromInternalValue(time_internal), now);
+
+      CHECK(count_down_ > 0);
+      count_down_--;
+      if (count_down_ == 0) {
+        perf_logger_.reset();  // Stop the perf timer now.
+        latency_tracker_.ShowResults();
+        MessageLoop::current()->QuitWhenIdle();
+        return true;
+      }
     }
 
-    IPC::Message* msg = new IPC::Message(0,
-                                         2,
-                                         IPC::Message::PRIORITY_NORMAL);
+    IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
     msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
     msg->WriteInt(count_down_);
     msg->WriteString(payload_);
@@ -150,46 +205,61 @@ class ChannelPerfListener : public IPC::Listener {
   }
 
  private:
+  IPC::Channel* channel_;
+  int msg_count_;
+  size_t msg_size_;
+
   int count_down_;
   std::string payload_;
-  IPC::Channel *channel_;
-  int count_messages_;
-  base::TimeDelta latency_messages_;
+  EventTimeTracker latency_tracker_;
+  scoped_ptr<PerfTimeLogger> perf_logger_;
 };
 
 TEST_F(IPCChannelPerfTest, Performance) {
-  // setup IPC channel
+  // Setup IPC channel.
   IPC::Channel chan(kReflectorChannel, IPC::Channel::MODE_SERVER, NULL);
-  ChannelPerfListener perf_listener(&chan, 10000, 100000);
+  ChannelPerfListener perf_listener(&chan);
   chan.set_listener(&perf_listener);
   ASSERT_TRUE(chan.Connect());
 
   base::ProcessHandle process_handle = SpawnChild(TEST_REFLECTOR, &chan);
   ASSERT_TRUE(process_handle);
 
-  base::PlatformThread::Sleep(base::TimeDelta::FromSeconds(1));
+  const size_t kMsgSizeBase = 12;
+  const int kMsgSizeMaxExp = 5;
+  int msg_count = 100000;
+  size_t msg_size = kMsgSizeBase;
+  for (int i = 1; i <= kMsgSizeMaxExp; i++) {
+    perf_listener.SetTestParams(msg_count, msg_size);
+
+    // This initial message will kick-start the ping-pong of messages.
+    IPC::Message* message =
+        new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
+    message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
+    message->WriteInt(-1);
+    message->WriteString("hello");
+    chan.Send(message);
 
-  PerfTimeLogger logger("IPC_Perf");
+    // Run message loop.
+    MessageLoop::current()->Run();
 
-  // this initial message will kick-start the ping-pong of messages
-  IPC::Message* message = new IPC::Message(0,
-                                           2,
-                                           IPC::Message::PRIORITY_NORMAL);
+    msg_size *= kMsgSizeBase;
+  }
+
+  // Send quit message.
+  IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
   message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
   message->WriteInt(-1);
-  message->WriteString("Hello");
+  message->WriteString("quit");
   chan.Send(message);
 
-  // run message loop
-  MessageLoop::current()->Run();
-
   // Clean up child process.
-  EXPECT_TRUE(base::WaitForSingleProcess(
-      process_handle, base::TimeDelta::FromSeconds(5)));
+  EXPECT_TRUE(base::WaitForSingleProcess(process_handle,
+                                         base::TimeDelta::FromSeconds(5)));
   base::CloseProcessHandle(process_handle);
 }
 
-// This message loop bounces all messages back to the sender
+// This message loop bounces all messages back to the sender.
 MULTIPROCESS_IPC_TEST_MAIN(RunReflector) {
   MessageLoopForIO main_message_loop;
   IPC::Channel chan(kReflectorChannel, IPC::Channel::MODE_CLIENT, NULL);