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: 38 explicit EventTimeTracker(const char* name) 39 : name_(name), 40 count_(0) { 41 } 42 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 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_)) 57 << " ms"; 58 VLOG(1) << name_ << " maximum duration: " 59 << max_duration_.InMillisecondsF() << " ms"; 60 } 61 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: 83 ChannelReflectorListener() 84 : channel_(NULL), 85 latency_tracker_("Client messages") { 86 VLOG(1) << "Client listener up"; 87 } 88 89 virtual ~ChannelReflectorListener() { 90 VLOG(1) << "Client listener down"; 91 latency_tracker_.ShowResults(); 92 } 93 94 void Init(IPC::Channel* channel) { 95 DCHECK(!channel_); 96 channel_ = channel; 97 } 98 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: 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 149 virtual ~PerformanceChannelListener() { 150 VLOG(1) << "Server listener down"; 151 } 152 153 void Init(IPC::Channel* channel) { 154 DCHECK(!channel_); 155 channel_ = channel; 156 } 157 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'); 165 } 166 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 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 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); 239 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); 247 248 // Run message loop. 249 base::MessageLoop::current()->Run(); 250 251 msg_size *= kMsgSizeBase; 252 } 253 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); 260 261 EXPECT_TRUE(WaitForClientShutdown()); 262 DestroyChannel(); 263 } 264 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, 271 &listener); 272 listener.Init(&channel); 273 CHECK(channel.Connect()); 274 275 base::MessageLoop::current()->Run(); 276 return 0; 277 } 278 279 } // namespace 280
