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:
EventTimeTracker(const char * name)38 explicit EventTimeTracker(const char* name)
39 : name_(name),
40 count_(0) {
41 }
42
AddEvent(const base::TimeTicks & start,const base::TimeTicks & end)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
ShowResults() const51 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
Reset()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:
ChannelReflectorListener()83 ChannelReflectorListener()
84 : channel_(NULL),
85 latency_tracker_("Client messages") {
86 VLOG(1) << "Client listener up";
87 }
88
~ChannelReflectorListener()89 virtual ~ChannelReflectorListener() {
90 VLOG(1) << "Client listener down";
91 latency_tracker_.ShowResults();
92 }
93
Init(IPC::Channel * channel)94 void Init(IPC::Channel* channel) {
95 DCHECK(!channel_);
96 channel_ = channel;
97 }
98
OnMessageReceived(const IPC::Message & message)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:
PerformanceChannelListener()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
~PerformanceChannelListener()149 virtual ~PerformanceChannelListener() {
150 VLOG(1) << "Server listener down";
151 }
152
Init(IPC::Channel * channel)153 void Init(IPC::Channel* channel) {
154 DCHECK(!channel_);
155 channel_ = channel;
156 }
157
158 // Call this before running the message loop.
SetTestParams(int msg_count,size_t msg_size)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
OnMessageReceived(const IPC::Message & message)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
TEST_F(IPCChannelPerfTest,Performance)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 // 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.
MULTIPROCESS_IPC_TEST_CLIENT_MAIN(PerformanceClient)265 MULTIPROCESS_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