Home | History | Annotate | Download | only in ipc
      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   const size_t kMsgSizeBase = 12;
    234   const int kMsgSizeMaxExp = 5;
    235   int msg_count = 100000;
    236   size_t msg_size = kMsgSizeBase;
    237   for (int i = 1; i <= kMsgSizeMaxExp; i++) {
    238     listener.SetTestParams(msg_count, msg_size);
    239 
    240     // This initial message will kick-start the ping-pong of messages.
    241     IPC::Message* message =
    242         new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
    243     message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
    244     message->WriteInt(-1);
    245     message->WriteString("hello");
    246     sender()->Send(message);
    247 
    248     // Run message loop.
    249     base::MessageLoop::current()->Run();
    250 
    251     msg_size *= kMsgSizeBase;
    252   }
    253 
    254   // Send quit message.
    255   IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL);
    256   message->WriteInt64(base::TimeTicks::Now().ToInternalValue());
    257   message->WriteInt(-1);
    258   message->WriteString("quit");
    259   sender()->Send(message);
    260 
    261   EXPECT_TRUE(WaitForClientShutdown());
    262   DestroyChannel();
    263 }
    264 
    265 // This message loop bounces all messages back to the sender.
    266 MULTIPROCESS_IPC_TEST_CLIENT_MAIN(PerformanceClient) {
    267   base::MessageLoopForIO main_message_loop;
    268   ChannelReflectorListener listener;
    269   IPC::Channel channel(IPCTestBase::GetChannelName("PerformanceClient"),
    270                        IPC::Channel::MODE_CLIENT,
    271                        &listener);
    272   listener.Init(&channel);
    273   CHECK(channel.Connect());
    274 
    275   base::MessageLoop::current()->Run();
    276   return 0;
    277 }
    278 
    279 }  // namespace
    280