| OLD | NEW |
| 1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. | 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 | 2 // Use of this source code is governed by a BSD-style license that can be |
| 3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
| 4 | 4 |
| 5 #include "build/build_config.h" | 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 "ipc/ipc_channel.h" | |
| 20 #include "ipc/ipc_channel_proxy.h" | |
| 21 #include "ipc/ipc_descriptors.h" | |
| 22 #include "ipc/ipc_message_utils.h" | |
| 23 #include "ipc/ipc_sender.h" | |
| 24 #include "ipc/ipc_test_base.h" | |
| 25 | 6 |
| 26 namespace { | 7 namespace { |
| 27 | 8 |
| 28 // This test times the roundtrip IPC message cycle. | 9 // This test times the roundtrip IPC message cycle. |
| 29 // | 10 // |
| 30 // TODO(brettw): Make this test run by default. | 11 // TODO(brettw): Make this test run by default. |
| 31 | 12 |
| 32 class IPCChannelPerfTest : public IPCTestBase { | 13 class IPCChannelPerfTest : public IPC::test::IPCChannelPerfTestBase { |
| 33 }; | |
| 34 | |
| 35 // This class simply collects stats about abstract "events" (each of which has a | |
| 36 // start time and an end time). | |
| 37 class EventTimeTracker { | |
| 38 public: | |
| 39 explicit EventTimeTracker(const char* name) | |
| 40 : name_(name), | |
| 41 count_(0) { | |
| 42 } | |
| 43 | |
| 44 void AddEvent(const base::TimeTicks& start, const base::TimeTicks& end) { | |
| 45 DCHECK(end >= start); | |
| 46 count_++; | |
| 47 base::TimeDelta duration = end - start; | |
| 48 total_duration_ += duration; | |
| 49 max_duration_ = std::max(max_duration_, duration); | |
| 50 } | |
| 51 | |
| 52 void ShowResults() const { | |
| 53 VLOG(1) << name_ << " count: " << count_; | |
| 54 VLOG(1) << name_ << " total duration: " | |
| 55 << total_duration_.InMillisecondsF() << " ms"; | |
| 56 VLOG(1) << name_ << " average duration: " | |
| 57 << (total_duration_.InMillisecondsF() / static_cast<double>(count_)) | |
| 58 << " ms"; | |
| 59 VLOG(1) << name_ << " maximum duration: " | |
| 60 << max_duration_.InMillisecondsF() << " ms"; | |
| 61 } | |
| 62 | |
| 63 void Reset() { | |
| 64 count_ = 0; | |
| 65 total_duration_ = base::TimeDelta(); | |
| 66 max_duration_ = base::TimeDelta(); | |
| 67 } | |
| 68 | |
| 69 private: | |
| 70 const std::string name_; | |
| 71 | |
| 72 uint64 count_; | |
| 73 base::TimeDelta total_duration_; | |
| 74 base::TimeDelta max_duration_; | |
| 75 | |
| 76 DISALLOW_COPY_AND_ASSIGN(EventTimeTracker); | |
| 77 }; | |
| 78 | |
| 79 // This channel listener just replies to all messages with the exact same | |
| 80 // message. It assumes each message has one string parameter. When the string | |
| 81 // "quit" is sent, it will exit. | |
| 82 class ChannelReflectorListener : public IPC::Listener { | |
| 83 public: | |
| 84 ChannelReflectorListener() | |
| 85 : channel_(NULL), | |
| 86 latency_tracker_("Client messages") { | |
| 87 VLOG(1) << "Client listener up"; | |
| 88 } | |
| 89 | |
| 90 virtual ~ChannelReflectorListener() { | |
| 91 VLOG(1) << "Client listener down"; | |
| 92 latency_tracker_.ShowResults(); | |
| 93 } | |
| 94 | |
| 95 void Init(IPC::Channel* channel) { | |
| 96 DCHECK(!channel_); | |
| 97 channel_ = channel; | |
| 98 } | |
| 99 | |
| 100 virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE { | |
| 101 CHECK(channel_); | |
| 102 | |
| 103 PickleIterator iter(message); | |
| 104 int64 time_internal; | |
| 105 EXPECT_TRUE(iter.ReadInt64(&time_internal)); | |
| 106 int msgid; | |
| 107 EXPECT_TRUE(iter.ReadInt(&msgid)); | |
| 108 std::string payload; | |
| 109 EXPECT_TRUE(iter.ReadString(&payload)); | |
| 110 | |
| 111 // Include message deserialization in latency. | |
| 112 base::TimeTicks now = base::TimeTicks::Now(); | |
| 113 | |
| 114 if (payload == "hello") { | |
| 115 latency_tracker_.Reset(); | |
| 116 } else if (payload == "quit") { | |
| 117 latency_tracker_.ShowResults(); | |
| 118 base::MessageLoop::current()->QuitWhenIdle(); | |
| 119 return true; | |
| 120 } else { | |
| 121 // Don't track hello and quit messages. | |
| 122 latency_tracker_.AddEvent( | |
| 123 base::TimeTicks::FromInternalValue(time_internal), now); | |
| 124 } | |
| 125 | |
| 126 IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); | |
| 127 msg->WriteInt64(base::TimeTicks::Now().ToInternalValue()); | |
| 128 msg->WriteInt(msgid); | |
| 129 msg->WriteString(payload); | |
| 130 channel_->Send(msg); | |
| 131 return true; | |
| 132 } | |
| 133 | |
| 134 private: | |
| 135 IPC::Channel* channel_; | |
| 136 EventTimeTracker latency_tracker_; | |
| 137 }; | |
| 138 | |
| 139 class PerformanceChannelListener : public IPC::Listener { | |
| 140 public: | |
| 141 explicit PerformanceChannelListener(const std::string& label) | |
| 142 : label_(label), | |
| 143 sender_(NULL), | |
| 144 msg_count_(0), | |
| 145 msg_size_(0), | |
| 146 count_down_(0), | |
| 147 latency_tracker_("Server messages") { | |
| 148 VLOG(1) << "Server listener up"; | |
| 149 } | |
| 150 | |
| 151 virtual ~PerformanceChannelListener() { | |
| 152 VLOG(1) << "Server listener down"; | |
| 153 } | |
| 154 | |
| 155 void Init(IPC::Sender* sender) { | |
| 156 DCHECK(!sender_); | |
| 157 sender_ = sender; | |
| 158 } | |
| 159 | |
| 160 // Call this before running the message loop. | |
| 161 void SetTestParams(int msg_count, size_t msg_size) { | |
| 162 DCHECK_EQ(0, count_down_); | |
| 163 msg_count_ = msg_count; | |
| 164 msg_size_ = msg_size; | |
| 165 count_down_ = msg_count_; | |
| 166 payload_ = std::string(msg_size_, 'a'); | |
| 167 } | |
| 168 | |
| 169 virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE { | |
| 170 CHECK(sender_); | |
| 171 | |
| 172 PickleIterator iter(message); | |
| 173 int64 time_internal; | |
| 174 EXPECT_TRUE(iter.ReadInt64(&time_internal)); | |
| 175 int msgid; | |
| 176 EXPECT_TRUE(iter.ReadInt(&msgid)); | |
| 177 std::string reflected_payload; | |
| 178 EXPECT_TRUE(iter.ReadString(&reflected_payload)); | |
| 179 | |
| 180 // Include message deserialization in latency. | |
| 181 base::TimeTicks now = base::TimeTicks::Now(); | |
| 182 | |
| 183 if (reflected_payload == "hello") { | |
| 184 // Start timing on hello. | |
| 185 latency_tracker_.Reset(); | |
| 186 DCHECK(!perf_logger_.get()); | |
| 187 std::string test_name = | |
| 188 base::StringPrintf("IPC_%s_Perf_%dx_%u", | |
| 189 label_.c_str(), | |
| 190 msg_count_, | |
| 191 static_cast<unsigned>(msg_size_)); | |
| 192 perf_logger_.reset(new base::PerfTimeLogger(test_name.c_str())); | |
| 193 } else { | |
| 194 DCHECK_EQ(payload_.size(), reflected_payload.size()); | |
| 195 | |
| 196 latency_tracker_.AddEvent( | |
| 197 base::TimeTicks::FromInternalValue(time_internal), now); | |
| 198 | |
| 199 CHECK(count_down_ > 0); | |
| 200 count_down_--; | |
| 201 if (count_down_ == 0) { | |
| 202 perf_logger_.reset(); // Stop the perf timer now. | |
| 203 latency_tracker_.ShowResults(); | |
| 204 base::MessageLoop::current()->QuitWhenIdle(); | |
| 205 return true; | |
| 206 } | |
| 207 } | |
| 208 | |
| 209 IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); | |
| 210 msg->WriteInt64(base::TimeTicks::Now().ToInternalValue()); | |
| 211 msg->WriteInt(count_down_); | |
| 212 msg->WriteString(payload_); | |
| 213 sender_->Send(msg); | |
| 214 return true; | |
| 215 } | |
| 216 | |
| 217 private: | |
| 218 std::string label_; | |
| 219 IPC::Sender* sender_; | |
| 220 int msg_count_; | |
| 221 size_t msg_size_; | |
| 222 | |
| 223 int count_down_; | |
| 224 std::string payload_; | |
| 225 EventTimeTracker latency_tracker_; | |
| 226 scoped_ptr<base::PerfTimeLogger> perf_logger_; | |
| 227 }; | 14 }; |
| 228 | 15 |
| 229 TEST_F(IPCChannelPerfTest, ChannelPingPong) { | 16 TEST_F(IPCChannelPerfTest, ChannelPingPong) { |
| 230 Init("PerformanceClient"); | 17 RunTestChannelPingPong(GetDefaultTestParams()); |
| 231 | |
| 232 // Set up IPC channel and start client. | |
| 233 PerformanceChannelListener listener("Channel"); | |
| 234 CreateChannel(&listener); | |
| 235 listener.Init(channel()); | |
| 236 ASSERT_TRUE(ConnectChannel()); | |
| 237 ASSERT_TRUE(StartClient()); | |
| 238 | |
| 239 // Test several sizes. We use 12^N for message size, and limit the message | |
| 240 // count to keep the test duration reasonable. | |
| 241 const size_t kMsgSize[5] = {12, 144, 1728, 20736, 248832}; | |
| 242 const int kMessageCount[5] = {50000, 50000, 50000, 12000, 1000}; | |
| 243 | |
| 244 for (size_t i = 0; i < 5; i++) { | |
| 245 listener.SetTestParams(kMessageCount[i], kMsgSize[i]); | |
| 246 | |
| 247 // This initial message will kick-start the ping-pong of messages. | |
| 248 IPC::Message* message = | |
| 249 new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); | |
| 250 message->WriteInt64(base::TimeTicks::Now().ToInternalValue()); | |
| 251 message->WriteInt(-1); | |
| 252 message->WriteString("hello"); | |
| 253 sender()->Send(message); | |
| 254 | |
| 255 // Run message loop. | |
| 256 base::MessageLoop::current()->Run(); | |
| 257 } | |
| 258 | |
| 259 // Send quit message. | |
| 260 IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); | |
| 261 message->WriteInt64(base::TimeTicks::Now().ToInternalValue()); | |
| 262 message->WriteInt(-1); | |
| 263 message->WriteString("quit"); | |
| 264 sender()->Send(message); | |
| 265 | |
| 266 EXPECT_TRUE(WaitForClientShutdown()); | |
| 267 DestroyChannel(); | |
| 268 } | |
| 269 | |
| 270 // This message loop bounces all messages back to the sender. | |
| 271 MULTIPROCESS_IPC_TEST_CLIENT_MAIN(PerformanceClient) { | |
| 272 base::MessageLoopForIO main_message_loop; | |
| 273 ChannelReflectorListener listener; | |
| 274 scoped_ptr<IPC::Channel> channel(IPC::Channel::CreateClient( | |
| 275 IPCTestBase::GetChannelName("PerformanceClient"), &listener)); | |
| 276 listener.Init(channel.get()); | |
| 277 CHECK(channel->Connect()); | |
| 278 | |
| 279 base::MessageLoop::current()->Run(); | |
| 280 return 0; | |
| 281 } | 18 } |
| 282 | 19 |
| 283 TEST_F(IPCChannelPerfTest, ChannelProxyPingPong) { | 20 TEST_F(IPCChannelPerfTest, ChannelProxyPingPong) { |
| 284 InitWithCustomMessageLoop("PerformanceClient", | 21 RunTestChannelProxyPingPong(GetDefaultTestParams()); |
| 285 make_scoped_ptr(new base::MessageLoop())); | 22 } |
| 286 | 23 |
| 287 base::TestIOThread io_thread(base::TestIOThread::kAutoStart); | 24 MULTIPROCESS_IPC_TEST_CLIENT_MAIN(PerformanceClient) { |
| 288 | 25 IPC::test::PingPongTestClient client; |
| 289 // Set up IPC channel and start client. | 26 return client.RunMain(); |
| 290 PerformanceChannelListener listener("ChannelProxy"); | |
| 291 CreateChannelProxy(&listener, io_thread.task_runner()); | |
| 292 listener.Init(channel_proxy()); | |
| 293 ASSERT_TRUE(StartClient()); | |
| 294 | |
| 295 // Test several sizes. We use 12^N for message size, and limit the message | |
| 296 // count to keep the test duration reasonable. | |
| 297 const size_t kMsgSize[5] = {12, 144, 1728, 20736, 248832}; | |
| 298 const int kMessageCount[5] = {50000, 50000, 50000, 12000, 1000}; | |
| 299 | |
| 300 for (size_t i = 0; i < 5; i++) { | |
| 301 listener.SetTestParams(kMessageCount[i], kMsgSize[i]); | |
| 302 | |
| 303 // This initial message will kick-start the ping-pong of messages. | |
| 304 IPC::Message* message = | |
| 305 new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); | |
| 306 message->WriteInt64(base::TimeTicks::Now().ToInternalValue()); | |
| 307 message->WriteInt(-1); | |
| 308 message->WriteString("hello"); | |
| 309 sender()->Send(message); | |
| 310 | |
| 311 // Run message loop. | |
| 312 base::MessageLoop::current()->Run(); | |
| 313 } | |
| 314 | |
| 315 // Send quit message. | |
| 316 IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); | |
| 317 message->WriteInt64(base::TimeTicks::Now().ToInternalValue()); | |
| 318 message->WriteInt(-1); | |
| 319 message->WriteString("quit"); | |
| 320 sender()->Send(message); | |
| 321 | |
| 322 EXPECT_TRUE(WaitForClientShutdown()); | |
| 323 DestroyChannelProxy(); | |
| 324 } | 27 } |
| 325 | 28 |
| 326 } // namespace | 29 } // namespace |
| OLD | NEW |