ipc/ipc_perftests.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "build/build_config.h"
   6
   7 #if defined(OS_WIN)
   8 #include <windows.h>
   9 #elif defined(OS_POSIX)
  10 #include <sys/types.h>
  11 #include <unistd.h>
  12 #endif
  13
  14 #include <algorithm>
  15 #include <string>
  16
  17 #include "base/basictypes.h"
  18 #include "base/logging.h"
  19 #include "base/memory/scoped_ptr.h"
  20 #include "base/perftimer.h"
  21 #include "base/pickle.h"
  22 #include "base/stringprintf.h"
  23 #include "base/threading/thread.h"
  24 #include "base/time.h"
  25 #include "ipc/ipc_descriptors.h"
  26 #include "ipc/ipc_channel.h"
  27 #include "ipc/ipc_channel_proxy.h"
  28 #include "ipc/ipc_message_utils.h"
  29 #include "ipc/ipc_multiprocess_test.h"
  30 #include "ipc/ipc_sender.h"
  31 #include "ipc/ipc_test_base.h"
  32
  33 namespace {
  34
  35 // This test times the roundtrip IPC message cycle.
  36 //
  37 // TODO(brettw): Make this test run by default.
  38
  39 class IPCChannelPerfTest : public IPCTestBase {
  40 };
  41
  42 // This class simply collects stats about abstract "events" (each of which has a
  43 // start time and an end time).
  44 class EventTimeTracker {
  45  public:
  46   explicit EventTimeTracker(const char* name)
  47       : name_(name),
  48         count_(0) {
  49   }
  50
  51   void AddEvent(const base::TimeTicks& start, const base::TimeTicks& end) {
  52     DCHECK(end >= start);
  53     count_++;
  54     base::TimeDelta duration = end - start;
  55     total_duration_ += duration;
  56     max_duration_ = std::max(max_duration_, duration);
  57   }
  58
  59   void ShowResults() const {
  60     VLOG(1) << name_ << " count: " << count_;
  61     VLOG(1) << name_ << " total duration: "
  62             << total_duration_.InMillisecondsF() << " ms";
  63     VLOG(1) << name_ << " average duration: "
  64             << (total_duration_.InMillisecondsF() / static_cast<double>(count_))
  65             << " ms";
  66     VLOG(1) << name_ << " maximum duration: "
  67             << max_duration_.InMillisecondsF() << " ms";
  68   }
  69
  70   void Reset() {
  71     count_ = 0;
  72     total_duration_ = base::TimeDelta();
  73     max_duration_ = base::TimeDelta();
  74   }
  75
  76  private:
  77   const std::string name_;
  78
  79   uint64 count_;
  80   base::TimeDelta total_duration_;
  81   base::TimeDelta max_duration_;
  82
  83   DISALLOW_COPY_AND_ASSIGN(EventTimeTracker);
  84 };
  85
  86 // This channel listener just replies to all messages with the exact same
  87 // message. It assumes each message has one string parameter. When the string
  88 // "quit" is sent, it will exit.
  89 class ChannelReflectorListener : public IPC::Listener {
  90  public:
  91   ChannelReflectorListener()
  92       : channel_(NULL),
  93         latency_tracker_("Client messages") {
  94     VLOG(1) << "Client listener up";
  95   }
  96
  97   ~ChannelReflectorListener() {
  98     VLOG(1) << "Client listener down";
  99     latency_tracker_.ShowResults();
 100   }
 101
 102   void Init(IPC::Channel* channel) {
 103     DCHECK(!channel_);
 104     channel_ = channel;
 105   }
 106
 107   virtual bool OnMessageReceived(const IPC::Message& message) {
 108     CHECK(channel_);
 109
 110     PickleIterator iter(message);
 111     int64 time_internal;
 112     EXPECT_TRUE(iter.ReadInt64(&time_internal));
 113     int msgid;
 114     EXPECT_TRUE(iter.ReadInt(&msgid));
 115     std::string payload;
 116     EXPECT_TRUE(iter.ReadString(&payload));
 117
 118     // Include message deserialization in latency.
 119     base::TimeTicks now = base::TimeTicks::Now();
 120
 121     if (payload == "hello") {
 122       latency_tracker_.Reset();
 123     } else if (payload == "quit") {
 124       latency_tracker_.ShowResults();
 125       MessageLoop::current()->QuitWhenIdle();
 126       return true;
 127     } else {
 128       // Don't track hello and quit messages.
 129       latency_tracker_.AddEvent(
 130           base::TimeTicks::FromInternalValue(time_internal), now);
 131     }
 132
 133     IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 134     msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 135     msg->WriteInt(msgid);
 136     msg->WriteString(payload);
 137     channel_->Send(msg);
 138     return true;
 139   }
 140
 141  private:
 142   IPC::Channel* channel_;
 143   EventTimeTracker latency_tracker_;
 144 };
 145
 146 class ChannelPerfListener : public IPC::Listener {
 147  public:
 148   ChannelPerfListener()
 149       : channel_(NULL),
 150         msg_count_(0),
 151         msg_size_(0),
 152         count_down_(0),
 153         latency_tracker_("Server messages") {
 154     VLOG(1) << "Server listener up";
 155   }
 156
 157   ~ChannelPerfListener() {
 158     VLOG(1) << "Server listener down";
 159   }
 160
 161   void Init(IPC::Channel* channel) {
 162     DCHECK(!channel_);
 163     channel_ = channel;
 164   }
 165
 166   // Call this before running the message loop.
 167   void SetTestParams(int msg_count, size_t msg_size) {
 168     DCHECK_EQ(0, count_down_);
 169     msg_count_ = msg_count;
 170     msg_size_ = msg_size;
 171     count_down_ = msg_count_;
 172     payload_ = std::string(msg_size_, 'a');
 173   }
 174
 175   virtual bool OnMessageReceived(const IPC::Message& message) {
 176     CHECK(channel_);
 177
 178     PickleIterator iter(message);
 179     int64 time_internal;
 180     EXPECT_TRUE(iter.ReadInt64(&time_internal));
 181     int msgid;
 182     EXPECT_TRUE(iter.ReadInt(&msgid));
 183     std::string reflected_payload;
 184     EXPECT_TRUE(iter.ReadString(&reflected_payload));
 185
 186     // Include message deserialization in latency.
 187     base::TimeTicks now = base::TimeTicks::Now();
 188
 189     if (reflected_payload == "hello") {
 190       // Start timing on hello.
 191       latency_tracker_.Reset();
 192       DCHECK(!perf_logger_.get());
 193       std::string test_name = base::StringPrintf(
 194           "IPC_Perf_%dx_%u", msg_count_, static_cast<unsigned>(msg_size_));
 195       perf_logger_.reset(new PerfTimeLogger(test_name.c_str()));
 196     } else {
 197       DCHECK_EQ(payload_.size(), reflected_payload.size());
 198
 199       latency_tracker_.AddEvent(
 200           base::TimeTicks::FromInternalValue(time_internal), now);
 201
 202       CHECK(count_down_ > 0);
 203       count_down_--;
 204       if (count_down_ == 0) {
 205         perf_logger_.reset();  // Stop the perf timer now.
 206         latency_tracker_.ShowResults();
 207         MessageLoop::current()->QuitWhenIdle();
 208         return true;
 209       }
 210     }
 211
 212     IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 213     msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 214     msg->WriteInt(count_down_);
 215     msg->WriteString(payload_);
 216     channel_->Send(msg);
 217     return true;
 218   }
 219
 220  private:
 221   IPC::Channel* channel_;
 222   int msg_count_;
 223   size_t msg_size_;
 224
 225   int count_down_;
 226   std::string payload_;
 227   EventTimeTracker latency_tracker_;
 228   scoped_ptr<PerfTimeLogger> perf_logger_;
 229 };
 230
 231 TEST_F(IPCChannelPerfTest, Performance) {
 232   // Setup IPC channel.
 233   ChannelPerfListener perf_listener;
 234   IPC::Channel chan(kReflectorChannel, IPC::Channel::MODE_SERVER,
 235                     &perf_listener);
 236   perf_listener.Init(&chan);
 237   ASSERT_TRUE(chan.Connect());
 238
 239   base::ProcessHandle process_handle = SpawnChild(TEST_REFLECTOR, &chan);
 240   ASSERT_TRUE(process_handle);
 241
 242   const size_t kMsgSizeBase = 12;
 243   const int kMsgSizeMaxExp = 5;
 244   int msg_count = 100000;
 245   size_t msg_size = kMsgSizeBase;
 246   for (int i = 1; i <= kMsgSizeMaxExp; i++) {
 247     perf_listener.SetTestParams(msg_count, msg_size);
 248
 249     // This initial message will kick-start the ping-pong of messages.
 250     IPC::Message* message =
 251         new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 252     message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 253     message->WriteInt(-1);
 254     message->WriteString("hello");
 255     chan.Send(message);
 256
 257     // Run message loop.
 258     MessageLoop::current()->Run();
 259
 260     msg_size *= kMsgSizeBase;
 261   }
 262
 263   // Send quit message.
 264   IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 265   message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 266   message->WriteInt(-1);
 267   message->WriteString("quit");
 268   chan.Send(message);
 269
 270   // Clean up child process.
 271   EXPECT_TRUE(base::WaitForSingleProcess(process_handle,
 272                                          base::TimeDelta::FromSeconds(5)));
 273   base::CloseProcessHandle(process_handle);
 274 }
 275
 276 // This message loop bounces all messages back to the sender.
 277 MULTIPROCESS_IPC_TEST_MAIN(RunReflector) {
 278   MessageLoopForIO main_message_loop;
 279   ChannelReflectorListener channel_reflector_listener;
 280   IPC::Channel chan(kReflectorChannel, IPC::Channel::MODE_CLIENT,
 281                     &channel_reflector_listener);
 282   channel_reflector_listener.Init(&chan);
 283   CHECK(chan.Connect());
 284
 285   MessageLoop::current()->Run();
 286   return 0;
 287 }
 288
 289 }  // namespace