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 #include <algorithm>
   8 #include <string>
   9
  10 #include "base/basictypes.h"
  11 #include "base/logging.h"
  12 #include "base/memory/scoped_ptr.h"
  13 #include "base/pickle.h"
  14 #include "base/strings/stringprintf.h"
  15 #include "base/test/perf_time_logger.h"
  16 #include "base/test/test_io_thread.h"
  17 #include "base/threading/thread.h"
  18 #include "base/time/time.h"
  19 #include "ipc/ipc_channel.h"
  20 #include "ipc/ipc_channel_proxy.h"
  21 #include "ipc/ipc_descriptors.h"
  22 #include "ipc/ipc_message_utils.h"
  23 #include "ipc/ipc_sender.h"
  24 #include "ipc/ipc_test_base.h"
  25
  26 namespace {
  27
  28 // This test times the roundtrip IPC message cycle.
  29 //
  30 // TODO(brettw): Make this test run by default.
  31
  32 class IPCChannelPerfTest : public IPCTestBase {
  33 };
  34
  35 // This class simply collects stats about abstract "events" (each of which has a
  36 // start time and an end time).
  37 class EventTimeTracker {
  38  public:
  39   explicit EventTimeTracker(const char* name)
  40       : name_(name),
  41         count_(0) {
  42   }
  43
  44   void AddEvent(const base::TimeTicks& start, const base::TimeTicks& end) {
  45     DCHECK(end >= start);
  46     count_++;
  47     base::TimeDelta duration = end - start;
  48     total_duration_ += duration;
  49     max_duration_ = std::max(max_duration_, duration);
  50   }
  51
  52   void ShowResults() const {
  53     VLOG(1) << name_ << " count: " << count_;
  54     VLOG(1) << name_ << " total duration: "
  55             << total_duration_.InMillisecondsF() << " ms";
  56     VLOG(1) << name_ << " average duration: "
  57             << (total_duration_.InMillisecondsF() / static_cast<double>(count_))
  58             << " ms";
  59     VLOG(1) << name_ << " maximum duration: "
  60             << max_duration_.InMillisecondsF() << " ms";
  61   }
  62
  63   void Reset() {
  64     count_ = 0;
  65     total_duration_ = base::TimeDelta();
  66     max_duration_ = base::TimeDelta();
  67   }
  68
  69  private:
  70   const std::string name_;
  71
  72   uint64 count_;
  73   base::TimeDelta total_duration_;
  74   base::TimeDelta max_duration_;
  75
  76   DISALLOW_COPY_AND_ASSIGN(EventTimeTracker);
  77 };
  78
  79 // This channel listener just replies to all messages with the exact same
  80 // message. It assumes each message has one string parameter. When the string
  81 // "quit" is sent, it will exit.
  82 class ChannelReflectorListener : public IPC::Listener {
  83  public:
  84   ChannelReflectorListener()
  85       : channel_(NULL),
  86         latency_tracker_("Client messages") {
  87     VLOG(1) << "Client listener up";
  88   }
  89
  90   virtual ~ChannelReflectorListener() {
  91     VLOG(1) << "Client listener down";
  92     latency_tracker_.ShowResults();
  93   }
  94
  95   void Init(IPC::Channel* channel) {
  96     DCHECK(!channel_);
  97     channel_ = channel;
  98   }
  99
 100   virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE {
 101     CHECK(channel_);
 102
 103     PickleIterator iter(message);
 104     int64 time_internal;
 105     EXPECT_TRUE(iter.ReadInt64(&time_internal));
 106     int msgid;
 107     EXPECT_TRUE(iter.ReadInt(&msgid));
 108     std::string payload;
 109     EXPECT_TRUE(iter.ReadString(&payload));
 110
 111     // Include message deserialization in latency.
 112     base::TimeTicks now = base::TimeTicks::Now();
 113
 114     if (payload == "hello") {
 115       latency_tracker_.Reset();
 116     } else if (payload == "quit") {
 117       latency_tracker_.ShowResults();
 118       base::MessageLoop::current()->QuitWhenIdle();
 119       return true;
 120     } else {
 121       // Don't track hello and quit messages.
 122       latency_tracker_.AddEvent(
 123           base::TimeTicks::FromInternalValue(time_internal), now);
 124     }
 125
 126     IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 127     msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 128     msg->WriteInt(msgid);
 129     msg->WriteString(payload);
 130     channel_->Send(msg);
 131     return true;
 132   }
 133
 134  private:
 135   IPC::Channel* channel_;
 136   EventTimeTracker latency_tracker_;
 137 };
 138
 139 class PerformanceChannelListener : public IPC::Listener {
 140  public:
 141   explicit PerformanceChannelListener(const std::string& label)
 142       : label_(label),
 143         sender_(NULL),
 144         msg_count_(0),
 145         msg_size_(0),
 146         count_down_(0),
 147         latency_tracker_("Server messages") {
 148     VLOG(1) << "Server listener up";
 149   }
 150
 151   virtual ~PerformanceChannelListener() {
 152     VLOG(1) << "Server listener down";
 153   }
 154
 155   void Init(IPC::Sender* sender) {
 156     DCHECK(!sender_);
 157     sender_ = sender;
 158   }
 159
 160   // Call this before running the message loop.
 161   void SetTestParams(int msg_count, size_t msg_size) {
 162     DCHECK_EQ(0, count_down_);
 163     msg_count_ = msg_count;
 164     msg_size_ = msg_size;
 165     count_down_ = msg_count_;
 166     payload_ = std::string(msg_size_, 'a');
 167   }
 168
 169   virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE {
 170     CHECK(sender_);
 171
 172     PickleIterator iter(message);
 173     int64 time_internal;
 174     EXPECT_TRUE(iter.ReadInt64(&time_internal));
 175     int msgid;
 176     EXPECT_TRUE(iter.ReadInt(&msgid));
 177     std::string reflected_payload;
 178     EXPECT_TRUE(iter.ReadString(&reflected_payload));
 179
 180     // Include message deserialization in latency.
 181     base::TimeTicks now = base::TimeTicks::Now();
 182
 183     if (reflected_payload == "hello") {
 184       // Start timing on hello.
 185       latency_tracker_.Reset();
 186       DCHECK(!perf_logger_.get());
 187       std::string test_name =
 188           base::StringPrintf("IPC_%s_Perf_%dx_%u",
 189                              label_.c_str(),
 190                              msg_count_,
 191                              static_cast<unsigned>(msg_size_));
 192       perf_logger_.reset(new base::PerfTimeLogger(test_name.c_str()));
 193     } else {
 194       DCHECK_EQ(payload_.size(), reflected_payload.size());
 195
 196       latency_tracker_.AddEvent(
 197           base::TimeTicks::FromInternalValue(time_internal), now);
 198
 199       CHECK(count_down_ > 0);
 200       count_down_--;
 201       if (count_down_ == 0) {
 202         perf_logger_.reset();  // Stop the perf timer now.
 203         latency_tracker_.ShowResults();
 204         base::MessageLoop::current()->QuitWhenIdle();
 205         return true;
 206       }
 207     }
 208
 209     IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 210     msg->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 211     msg->WriteInt(count_down_);
 212     msg->WriteString(payload_);
 213     sender_->Send(msg);
 214     return true;
 215   }
 216
 217  private:
 218   std::string label_;
 219   IPC::Sender* sender_;
 220   int msg_count_;
 221   size_t msg_size_;
 222
 223   int count_down_;
 224   std::string payload_;
 225   EventTimeTracker latency_tracker_;
 226   scoped_ptr<base::PerfTimeLogger> perf_logger_;
 227 };
 228
 229 TEST_F(IPCChannelPerfTest, ChannelPingPong) {
 230   Init("PerformanceClient");
 231
 232   // Set up IPC channel and start client.
 233   PerformanceChannelListener listener("Channel");
 234   CreateChannel(&listener);
 235   listener.Init(channel());
 236   ASSERT_TRUE(ConnectChannel());
 237   ASSERT_TRUE(StartClient());
 238
 239   // Test several sizes. We use 12^N for message size, and limit the message
 240   // count to keep the test duration reasonable.
 241   const size_t kMsgSize[5] = {12, 144, 1728, 20736, 248832};
 242   const int kMessageCount[5] = {50000, 50000, 50000, 12000, 1000};
 243
 244   for (size_t i = 0; i < 5; i++) {
 245     listener.SetTestParams(kMessageCount[i], kMsgSize[i]);
 246
 247     // This initial message will kick-start the ping-pong of messages.
 248     IPC::Message* message =
 249         new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 250     message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 251     message->WriteInt(-1);
 252     message->WriteString("hello");
 253     sender()->Send(message);
 254
 255     // Run message loop.
 256     base::MessageLoop::current()->Run();
 257   }
 258
 259   // Send quit message.
 260   IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 261   message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 262   message->WriteInt(-1);
 263   message->WriteString("quit");
 264   sender()->Send(message);
 265
 266   EXPECT_TRUE(WaitForClientShutdown());
 267   DestroyChannel();
 268 }
 269
 270 // This message loop bounces all messages back to the sender.
 271 MULTIPROCESS_IPC_TEST_CLIENT_MAIN(PerformanceClient) {
 272   base::MessageLoopForIO main_message_loop;
 273   ChannelReflectorListener listener;
 274   scoped_ptr<IPC::Channel> channel(IPC::Channel::CreateClient(
 275       IPCTestBase::GetChannelName("PerformanceClient"), &listener));
 276   listener.Init(channel.get());
 277   CHECK(channel->Connect());
 278
 279   base::MessageLoop::current()->Run();
 280   return 0;
 281 }
 282
 283 TEST_F(IPCChannelPerfTest, ChannelProxyPingPong) {
 284   InitWithCustomMessageLoop("PerformanceClient",
 285                             make_scoped_ptr(new base::MessageLoop()));
 286
 287   base::TestIOThread io_thread(base::TestIOThread::kAutoStart);
 288
 289   // Set up IPC channel and start client.
 290   PerformanceChannelListener listener("ChannelProxy");
 291   CreateChannelProxy(&listener, io_thread.task_runner());
 292   listener.Init(channel_proxy());
 293   ASSERT_TRUE(StartClient());
 294
 295   // Test several sizes. We use 12^N for message size, and limit the message
 296   // count to keep the test duration reasonable.
 297   const size_t kMsgSize[5] = {12, 144, 1728, 20736, 248832};
 298   const int kMessageCount[5] = {50000, 50000, 50000, 12000, 1000};
 299
 300   for (size_t i = 0; i < 5; i++) {
 301     listener.SetTestParams(kMessageCount[i], kMsgSize[i]);
 302
 303     // This initial message will kick-start the ping-pong of messages.
 304     IPC::Message* message =
 305         new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 306     message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 307     message->WriteInt(-1);
 308     message->WriteString("hello");
 309     sender()->Send(message);
 310
 311     // Run message loop.
 312     base::MessageLoop::current()->Run();
 313   }
 314
 315   // Send quit message.
 316   IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
 317   message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
 318   message->WriteInt(-1);
 319   message->WriteString("quit");
 320   sender()->Send(message);
 321
 322   EXPECT_TRUE(WaitForClientShutdown());
 323   DestroyChannelProxy();
 324 }
 325
 326 }  // namespace