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