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.
5 #include "build/build_config.h"
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"
27 // This test times the roundtrip IPC message cycle.
29 // TODO(brettw): Make this test run by default.
31 class IPCChannelPerfTest : public IPCTestBase {
34 // This class simply collects stats about abstract "events" (each of which has a
35 // start time and an end time).
36 class EventTimeTracker {
38 explicit EventTimeTracker(const char* name)
43 void AddEvent(const base::TimeTicks& start, const base::TimeTicks& end) {
46 base::TimeDelta duration = end - start;
47 total_duration_ += duration;
48 max_duration_ = std::max(max_duration_, duration);
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_))
58 VLOG(1) << name_ << " maximum duration: "
59 << max_duration_.InMillisecondsF() << " ms";
64 total_duration_ = base::TimeDelta();
65 max_duration_ = base::TimeDelta();
69 const std::string name_;
72 base::TimeDelta total_duration_;
73 base::TimeDelta max_duration_;
75 DISALLOW_COPY_AND_ASSIGN(EventTimeTracker);
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 {
83 ChannelReflectorListener()
85 latency_tracker_("Client messages") {
86 VLOG(1) << "Client listener up";
89 virtual ~ChannelReflectorListener() {
90 VLOG(1) << "Client listener down";
91 latency_tracker_.ShowResults();
94 void Init(IPC::Channel* channel) {
99 virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE {
102 PickleIterator iter(message);
104 EXPECT_TRUE(iter.ReadInt64(&time_internal));
106 EXPECT_TRUE(iter.ReadInt(&msgid));
108 EXPECT_TRUE(iter.ReadString(&payload));
110 // Include message deserialization in latency.
111 base::TimeTicks now = base::TimeTicks::Now();
113 if (payload == "hello") {
114 latency_tracker_.Reset();
115 } else if (payload == "quit") {
116 latency_tracker_.ShowResults();
117 base::MessageLoop::current()->QuitWhenIdle();
120 // Don't track hello and quit messages.
121 latency_tracker_.AddEvent(
122 base::TimeTicks::FromInternalValue(time_internal), now);
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);
134 IPC::Channel* channel_;
135 EventTimeTracker latency_tracker_;
138 class PerformanceChannelListener : public IPC::Listener {
140 PerformanceChannelListener()
145 latency_tracker_("Server messages") {
146 VLOG(1) << "Server listener up";
149 virtual ~PerformanceChannelListener() {
150 VLOG(1) << "Server listener down";
153 void Init(IPC::Channel* channel) {
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');
167 virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE {
170 PickleIterator iter(message);
172 EXPECT_TRUE(iter.ReadInt64(&time_internal));
174 EXPECT_TRUE(iter.ReadInt(&msgid));
175 std::string reflected_payload;
176 EXPECT_TRUE(iter.ReadString(&reflected_payload));
178 // Include message deserialization in latency.
179 base::TimeTicks now = base::TimeTicks::Now();
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()));
189 DCHECK_EQ(payload_.size(), reflected_payload.size());
191 latency_tracker_.AddEvent(
192 base::TimeTicks::FromInternalValue(time_internal), now);
194 CHECK(count_down_ > 0);
196 if (count_down_ == 0) {
197 perf_logger_.reset(); // Stop the perf timer now.
198 latency_tracker_.ShowResults();
199 base::MessageLoop::current()->QuitWhenIdle();
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_);
213 IPC::Channel* channel_;
218 std::string payload_;
219 EventTimeTracker latency_tracker_;
220 scoped_ptr<base::PerfTimeLogger> perf_logger_;
223 TEST_F(IPCChannelPerfTest, Performance) {
224 Init("PerformanceClient");
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());
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);
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);
249 base::MessageLoop::current()->Run();
251 msg_size *= kMsgSizeBase;
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);
261 EXPECT_TRUE(WaitForClientShutdown());
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,
272 listener.Init(&channel);
273 CHECK(channel.Connect());
275 base::MessageLoop::current()->Run();