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
26namespace IPC {
27namespace test {
28
29// This class simply collects stats about abstract "events" (each of which has a
30// start time and an end time).
31class 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.
76class 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
133class 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
223std::vector<PingPongTestParams>
224IPCChannelPerfTestBase::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
236void 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
274void 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
315PingPongTestClient::PingPongTestClient()
316    : listener_(new ChannelReflectorListener()) {
317}
318
319PingPongTestClient::~PingPongTestClient() {
320}
321
322scoped_ptr<Channel> PingPongTestClient::CreateChannel(
323    Listener* listener) {
324  return Channel::CreateClient(
325      IPCTestBase::GetChannelName("PerformanceClient"), listener);
326}
327
328int 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
337scoped_refptr<base::TaskRunner> PingPongTestClient::task_runner() {
338  return main_message_loop_.message_loop_proxy();
339}
340
341}  // namespace test
342}  // namespace IPC
343