viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 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 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 7 | #include <algorithm> |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 8 | #include <string> |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 9 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 10 | #include "base/basictypes.h" |
| 11 | #include "base/logging.h" |
| 12 | #include "base/memory/scoped_ptr.h" |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 13 | #include "base/pickle.h" |
avi@chromium.org | e7eaf39 | 2013-06-11 15:32:18 +0900 | [diff] [blame] | 14 | #include "base/strings/stringprintf.h" |
tfarina@chromium.org | 530d884 | 2013-09-17 09:34:38 +0900 | [diff] [blame] | 15 | #include "base/test/perf_time_logger.h" |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 16 | #include "base/threading/thread.h" |
avi@chromium.org | 78a7e7b | 2013-06-29 00:20:02 +0900 | [diff] [blame] | 17 | #include "base/time/time.h" |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 18 | #include "ipc/ipc_channel.h" |
| 19 | #include "ipc/ipc_channel_proxy.h" |
avi@chromium.org | e7eaf39 | 2013-06-11 15:32:18 +0900 | [diff] [blame] | 20 | #include "ipc/ipc_descriptors.h" |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 21 | #include "ipc/ipc_message_utils.h" |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 22 | #include "ipc/ipc_sender.h" |
viettrungluu@chromium.org | e977842 | 2013-01-12 06:19:15 +0900 | [diff] [blame] | 23 | #include "ipc/ipc_test_base.h" |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 24 | |
viettrungluu@chromium.org | 7ca1913 | 2013-01-12 05:56:22 +0900 | [diff] [blame] | 25 | namespace { |
| 26 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 27 | // This test times the roundtrip IPC message cycle. |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 28 | // |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 29 | // TODO(brettw): Make this test run by default. |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 30 | |
| 31 | class IPCChannelPerfTest : public IPCTestBase { |
| 32 | }; |
| 33 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 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 | |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 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: |
viettrungluu@chromium.org | 721fe99 | 2013-01-17 04:33:32 +0900 | [diff] [blame] | 83 | ChannelReflectorListener() |
| 84 | : channel_(NULL), |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 85 | latency_tracker_("Client messages") { |
| 86 | VLOG(1) << "Client listener up"; |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 87 | } |
| 88 | |
rsleevi@chromium.org | 5a8d7ef | 2013-02-06 19:08:55 +0900 | [diff] [blame] | 89 | virtual ~ChannelReflectorListener() { |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 90 | VLOG(1) << "Client listener down"; |
| 91 | latency_tracker_.ShowResults(); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 92 | } |
| 93 | |
viettrungluu@chromium.org | 721fe99 | 2013-01-17 04:33:32 +0900 | [diff] [blame] | 94 | void Init(IPC::Channel* channel) { |
| 95 | DCHECK(!channel_); |
| 96 | channel_ = channel; |
| 97 | } |
| 98 | |
rsleevi@chromium.org | 5a8d7ef | 2013-02-06 19:08:55 +0900 | [diff] [blame] | 99 | virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE { |
viettrungluu@chromium.org | 721fe99 | 2013-01-17 04:33:32 +0900 | [diff] [blame] | 100 | CHECK(channel_); |
| 101 | |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 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)); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 109 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 110 | // Include message deserialization in latency. |
| 111 | base::TimeTicks now = base::TimeTicks::Now(); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 112 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 113 | if (payload == "hello") { |
| 114 | latency_tracker_.Reset(); |
| 115 | } else if (payload == "quit") { |
| 116 | latency_tracker_.ShowResults(); |
xhwang@chromium.org | 0b2c2a5 | 2013-05-01 05:55:03 +0900 | [diff] [blame] | 117 | base::MessageLoop::current()->QuitWhenIdle(); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 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 | |
bbudge@chromium.org | ab4c6bc | 2013-11-05 07:28:12 +0900 | [diff] [blame] | 125 | IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 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: |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 134 | IPC::Channel* channel_; |
| 135 | EventTimeTracker latency_tracker_; |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 136 | }; |
| 137 | |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 138 | class PerformanceChannelListener : public IPC::Listener { |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 139 | public: |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 140 | PerformanceChannelListener() |
viettrungluu@chromium.org | 721fe99 | 2013-01-17 04:33:32 +0900 | [diff] [blame] | 141 | : channel_(NULL), |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 142 | msg_count_(0), |
| 143 | msg_size_(0), |
| 144 | count_down_(0), |
| 145 | latency_tracker_("Server messages") { |
| 146 | VLOG(1) << "Server listener up"; |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 147 | } |
| 148 | |
rsleevi@chromium.org | 5a8d7ef | 2013-02-06 19:08:55 +0900 | [diff] [blame] | 149 | virtual ~PerformanceChannelListener() { |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 150 | VLOG(1) << "Server listener down"; |
| 151 | } |
| 152 | |
viettrungluu@chromium.org | 721fe99 | 2013-01-17 04:33:32 +0900 | [diff] [blame] | 153 | void Init(IPC::Channel* channel) { |
| 154 | DCHECK(!channel_); |
| 155 | channel_ = channel; |
| 156 | } |
| 157 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 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'); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 165 | } |
| 166 | |
rsleevi@chromium.org | 5a8d7ef | 2013-02-06 19:08:55 +0900 | [diff] [blame] | 167 | virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE { |
viettrungluu@chromium.org | 721fe99 | 2013-01-17 04:33:32 +0900 | [diff] [blame] | 168 | CHECK(channel_); |
| 169 | |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 170 | PickleIterator iter(message); |
| 171 | int64 time_internal; |
| 172 | EXPECT_TRUE(iter.ReadInt64(&time_internal)); |
| 173 | int msgid; |
| 174 | EXPECT_TRUE(iter.ReadInt(&msgid)); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 175 | std::string reflected_payload; |
| 176 | EXPECT_TRUE(iter.ReadString(&reflected_payload)); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 177 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 178 | // Include message deserialization in latency. |
| 179 | base::TimeTicks now = base::TimeTicks::Now(); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 180 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 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_)); |
tfarina@chromium.org | 530d884 | 2013-09-17 09:34:38 +0900 | [diff] [blame] | 187 | perf_logger_.reset(new base::PerfTimeLogger(test_name.c_str())); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 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(); |
xhwang@chromium.org | 0b2c2a5 | 2013-05-01 05:55:03 +0900 | [diff] [blame] | 199 | base::MessageLoop::current()->QuitWhenIdle(); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 200 | return true; |
| 201 | } |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 202 | } |
| 203 | |
bbudge@chromium.org | ab4c6bc | 2013-11-05 07:28:12 +0900 | [diff] [blame] | 204 | IPC::Message* msg = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 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: |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 213 | IPC::Channel* channel_; |
| 214 | int msg_count_; |
| 215 | size_t msg_size_; |
| 216 | |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 217 | int count_down_; |
| 218 | std::string payload_; |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 219 | EventTimeTracker latency_tracker_; |
tfarina@chromium.org | 530d884 | 2013-09-17 09:34:38 +0900 | [diff] [blame] | 220 | scoped_ptr<base::PerfTimeLogger> perf_logger_; |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 221 | }; |
| 222 | |
| 223 | TEST_F(IPCChannelPerfTest, Performance) { |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 224 | Init("PerformanceClient"); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 225 | |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 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()); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 232 | |
epenner@chromium.org | 913c948 | 2014-03-19 15:34:52 +0900 | [diff] [blame] | 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}; |
epenner@chromium.org | e0970ad | 2014-03-21 08:36:25 +0900 | [diff] [blame] | 236 | const int kMessageCount[5] = {50000, 50000, 50000, 12000, 1000}; |
epenner@chromium.org | 913c948 | 2014-03-19 15:34:52 +0900 | [diff] [blame] | 237 | |
| 238 | for (size_t i = 0; i < 5; i++) { |
| 239 | listener.SetTestParams(kMessageCount[i], kMsgSize[i]); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 240 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 241 | // This initial message will kick-start the ping-pong of messages. |
| 242 | IPC::Message* message = |
bbudge@chromium.org | ab4c6bc | 2013-11-05 07:28:12 +0900 | [diff] [blame] | 243 | new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 244 | message->WriteInt64(base::TimeTicks::Now().ToInternalValue()); |
| 245 | message->WriteInt(-1); |
| 246 | message->WriteString("hello"); |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 247 | sender()->Send(message); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 248 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 249 | // Run message loop. |
xhwang@chromium.org | 0b2c2a5 | 2013-05-01 05:55:03 +0900 | [diff] [blame] | 250 | base::MessageLoop::current()->Run(); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 251 | } |
| 252 | |
| 253 | // Send quit message. |
bbudge@chromium.org | ab4c6bc | 2013-11-05 07:28:12 +0900 | [diff] [blame] | 254 | IPC::Message* message = new IPC::Message(0, 2, IPC::Message::PRIORITY_NORMAL); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 255 | message->WriteInt64(base::TimeTicks::Now().ToInternalValue()); |
| 256 | message->WriteInt(-1); |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 257 | message->WriteString("quit"); |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 258 | sender()->Send(message); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 259 | |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 260 | EXPECT_TRUE(WaitForClientShutdown()); |
| 261 | DestroyChannel(); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 262 | } |
| 263 | |
viettrungluu@chromium.org | 0615143 | 2013-01-16 05:14:22 +0900 | [diff] [blame] | 264 | // This message loop bounces all messages back to the sender. |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 265 | MULTIPROCESS_IPC_TEST_CLIENT_MAIN(PerformanceClient) { |
xhwang@chromium.org | 0b2c2a5 | 2013-05-01 05:55:03 +0900 | [diff] [blame] | 266 | base::MessageLoopForIO main_message_loop; |
viettrungluu@chromium.org | 0015594 | 2013-01-26 06:51:35 +0900 | [diff] [blame] | 267 | ChannelReflectorListener listener; |
morrita@chromium.org | 2ced004 | 2014-05-30 12:58:59 +0900 | [diff] [blame] | 268 | scoped_ptr<IPC::Channel> channel(IPC::Channel::CreateClient( |
| 269 | IPCTestBase::GetChannelName("PerformanceClient"), &listener)); |
| 270 | listener.Init(channel.get()); |
| 271 | CHECK(channel->Connect()); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 272 | |
xhwang@chromium.org | 0b2c2a5 | 2013-05-01 05:55:03 +0900 | [diff] [blame] | 273 | base::MessageLoop::current()->Run(); |
viettrungluu@chromium.org | 7d86af2 | 2013-01-12 00:13:37 +0900 | [diff] [blame] | 274 | return 0; |
| 275 | } |
viettrungluu@chromium.org | 7ca1913 | 2013-01-12 05:56:22 +0900 | [diff] [blame] | 276 | |
| 277 | } // namespace |