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