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