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
25namespace {
26
27// This test times the roundtrip IPC message cycle.
28//
29// TODO(brettw): Make this test run by default.
30
31class 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).
36class 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.
81class 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
138class 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
223TEST_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.
265MULTIPROCESS_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
278