henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 1 | /* |
| 2 | * Copyright 2004 The WebRTC Project Authors. All rights reserved. |
| 3 | * |
| 4 | * Use of this source code is governed by a BSD-style license |
| 5 | * that can be found in the LICENSE file in the root of the source |
| 6 | * tree. An additional intellectual property rights grant can be found |
| 7 | * in the file PATENTS. All contributing project authors may |
| 8 | * be found in the AUTHORS file in the root of the source tree. |
| 9 | */ |
| 10 | |
Mirko Bonadei | 92ea95e | 2017-09-15 06:47:31 +0200 | [diff] [blame] | 11 | #include "rtc_base/logging.h" |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 12 | #include "rtc_base/arraysize.h" |
| 13 | #include "rtc_base/checks.h" |
| 14 | #include "rtc_base/event.h" |
| 15 | #include "rtc_base/gunit.h" |
| 16 | #include "rtc_base/platform_thread.h" |
Mirko Bonadei | 92ea95e | 2017-09-15 06:47:31 +0200 | [diff] [blame] | 17 | #include "rtc_base/stream.h" |
Mirko Bonadei | 92ea95e | 2017-09-15 06:47:31 +0200 | [diff] [blame] | 18 | #include "test/testsupport/fileutils.h" |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 19 | |
| 20 | namespace rtc { |
| 21 | |
Niels Möller | ff3dd0c | 2018-06-20 10:27:53 +0200 | [diff] [blame] | 22 | namespace { |
| 23 | |
| 24 | class StringStream : public StreamInterface { |
| 25 | public: |
| 26 | explicit StringStream(std::string* str); |
| 27 | explicit StringStream(const std::string& str); |
| 28 | |
| 29 | StreamState GetState() const override; |
| 30 | StreamResult Read(void* buffer, |
| 31 | size_t buffer_len, |
| 32 | size_t* read, |
| 33 | int* error) override; |
| 34 | StreamResult Write(const void* data, |
| 35 | size_t data_len, |
| 36 | size_t* written, |
| 37 | int* error) override; |
| 38 | void Close() override; |
| 39 | bool SetPosition(size_t position) override; |
| 40 | bool GetPosition(size_t* position) const override; |
| 41 | bool GetSize(size_t* size) const override; |
| 42 | bool GetAvailable(size_t* size) const override; |
| 43 | bool ReserveSize(size_t size) override; |
| 44 | |
| 45 | private: |
| 46 | std::string& str_; |
| 47 | size_t read_pos_; |
| 48 | bool read_only_; |
| 49 | }; |
| 50 | |
| 51 | StringStream::StringStream(std::string* str) |
| 52 | : str_(*str), read_pos_(0), read_only_(false) {} |
| 53 | |
| 54 | StringStream::StringStream(const std::string& str) |
| 55 | : str_(const_cast<std::string&>(str)), read_pos_(0), read_only_(true) {} |
| 56 | |
| 57 | StreamState StringStream::GetState() const { |
| 58 | return SS_OPEN; |
| 59 | } |
| 60 | |
| 61 | StreamResult StringStream::Read(void* buffer, |
| 62 | size_t buffer_len, |
| 63 | size_t* read, |
| 64 | int* error) { |
| 65 | size_t available = std::min(buffer_len, str_.size() - read_pos_); |
| 66 | if (!available) |
| 67 | return SR_EOS; |
| 68 | memcpy(buffer, str_.data() + read_pos_, available); |
| 69 | read_pos_ += available; |
| 70 | if (read) |
| 71 | *read = available; |
| 72 | return SR_SUCCESS; |
| 73 | } |
| 74 | |
| 75 | StreamResult StringStream::Write(const void* data, |
| 76 | size_t data_len, |
| 77 | size_t* written, |
| 78 | int* error) { |
| 79 | if (read_only_) { |
| 80 | if (error) { |
| 81 | *error = -1; |
| 82 | } |
| 83 | return SR_ERROR; |
| 84 | } |
| 85 | str_.append(static_cast<const char*>(data), |
| 86 | static_cast<const char*>(data) + data_len); |
| 87 | if (written) |
| 88 | *written = data_len; |
| 89 | return SR_SUCCESS; |
| 90 | } |
| 91 | |
| 92 | void StringStream::Close() {} |
| 93 | |
| 94 | bool StringStream::SetPosition(size_t position) { |
| 95 | if (position > str_.size()) |
| 96 | return false; |
| 97 | read_pos_ = position; |
| 98 | return true; |
| 99 | } |
| 100 | |
| 101 | bool StringStream::GetPosition(size_t* position) const { |
| 102 | if (position) |
| 103 | *position = read_pos_; |
| 104 | return true; |
| 105 | } |
| 106 | |
| 107 | bool StringStream::GetSize(size_t* size) const { |
| 108 | if (size) |
| 109 | *size = str_.size(); |
| 110 | return true; |
| 111 | } |
| 112 | |
| 113 | bool StringStream::GetAvailable(size_t* size) const { |
| 114 | if (size) |
| 115 | *size = str_.size() - read_pos_; |
| 116 | return true; |
| 117 | } |
| 118 | |
| 119 | bool StringStream::ReserveSize(size_t size) { |
| 120 | if (read_only_) |
| 121 | return false; |
| 122 | str_.reserve(size); |
| 123 | return true; |
| 124 | } |
| 125 | |
| 126 | } // namespace |
| 127 | |
Tommi | 0eefb4d | 2015-05-23 09:54:07 +0200 | [diff] [blame] | 128 | template <typename Base> |
Yves Gerey | 665174f | 2018-06-19 15:03:05 +0200 | [diff] [blame] | 129 | class LogSinkImpl : public LogSink, public Base { |
Tommi | 0eefb4d | 2015-05-23 09:54:07 +0200 | [diff] [blame] | 130 | public: |
| 131 | LogSinkImpl() {} |
| 132 | |
Yves Gerey | 665174f | 2018-06-19 15:03:05 +0200 | [diff] [blame] | 133 | template <typename P> |
Tommi | 00aac5a | 2015-05-25 11:25:59 +0200 | [diff] [blame] | 134 | explicit LogSinkImpl(P* p) : Base(p) {} |
Tommi | 0eefb4d | 2015-05-23 09:54:07 +0200 | [diff] [blame] | 135 | |
| 136 | private: |
| 137 | void OnLogMessage(const std::string& message) override { |
Yves Gerey | 665174f | 2018-06-19 15:03:05 +0200 | [diff] [blame] | 138 | static_cast<Base*>(this)->WriteAll(message.data(), message.size(), nullptr, |
| 139 | nullptr); |
Tommi | 0eefb4d | 2015-05-23 09:54:07 +0200 | [diff] [blame] | 140 | } |
| 141 | }; |
| 142 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 143 | class LogMessageForTesting : public LogMessage { |
| 144 | public: |
| 145 | LogMessageForTesting(const char* file, |
| 146 | int line, |
| 147 | LoggingSeverity sev, |
| 148 | LogErrorContext err_ctx = ERRCTX_NONE, |
| 149 | int err = 0) |
| 150 | : LogMessage(file, line, sev, err_ctx, err) {} |
| 151 | |
| 152 | const std::string& get_extra() const { return extra_; } |
| 153 | bool is_noop() const { return is_noop_; } |
Paulina Hensman | f1e3cb4 | 2018-06-20 14:07:05 +0200 | [diff] [blame] | 154 | #if defined(WEBRTC_ANDROID) |
| 155 | const char* get_tag() const { return tag_; } |
| 156 | #endif |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 157 | |
| 158 | // Returns the contents of the internal log stream. |
| 159 | // Note that parts of the stream won't (as is) be available until *after* the |
| 160 | // dtor of the parent class has run. So, as is, this only represents a |
| 161 | // partially built stream. |
| 162 | std::string GetPrintStream() { |
| 163 | RTC_DCHECK(!is_finished_); |
| 164 | is_finished_ = true; |
| 165 | FinishPrintStream(); |
| 166 | std::string ret = print_stream_.str(); |
| 167 | // Just to make an error even more clear if the stream gets used after this. |
| 168 | print_stream_.clear(); |
| 169 | return ret; |
| 170 | } |
| 171 | |
| 172 | private: |
| 173 | bool is_finished_ = false; |
| 174 | }; |
| 175 | |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 176 | // Test basic logging operation. We should get the INFO log but not the VERBOSE. |
| 177 | // We should restore the correct global state at the end. |
| 178 | TEST(LogTest, SingleStream) { |
deadbeef | 37f5ecf | 2017-02-27 14:06:41 -0800 | [diff] [blame] | 179 | int sev = LogMessage::GetLogToStream(nullptr); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 180 | |
| 181 | std::string str; |
Tommi | 00aac5a | 2015-05-25 11:25:59 +0200 | [diff] [blame] | 182 | LogSinkImpl<StringStream> stream(&str); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 183 | LogMessage::AddLogToStream(&stream, LS_INFO); |
| 184 | EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream)); |
| 185 | |
Mirko Bonadei | 675513b | 2017-11-09 11:09:25 +0100 | [diff] [blame] | 186 | RTC_LOG(LS_INFO) << "INFO"; |
| 187 | RTC_LOG(LS_VERBOSE) << "VERBOSE"; |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 188 | EXPECT_NE(std::string::npos, str.find("INFO")); |
| 189 | EXPECT_EQ(std::string::npos, str.find("VERBOSE")); |
| 190 | |
| 191 | LogMessage::RemoveLogToStream(&stream); |
Tommi | 0eefb4d | 2015-05-23 09:54:07 +0200 | [diff] [blame] | 192 | EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream)); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 193 | |
deadbeef | 37f5ecf | 2017-02-27 14:06:41 -0800 | [diff] [blame] | 194 | EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr)); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 195 | } |
| 196 | |
Jonas Olsson | ae18886 | 2018-06-18 11:19:22 +0200 | [diff] [blame] | 197 | /* |
Jonas Olsson | f8e5c11 | 2018-06-14 13:14:22 +0200 | [diff] [blame] | 198 | #if GTEST_HAS_DEATH_TEST && !defined(WEBRTC_ANDROID) |
| 199 | TEST(LogTest, Checks) { |
| 200 | EXPECT_DEATH(FATAL() << "message", |
| 201 | "\n\n#\n" |
| 202 | "# Fatal error in: \\S+, line \\d+\n" |
| 203 | "# last system error: \\d+\n" |
| 204 | "# Check failed: FATAL\\(\\)\n" |
| 205 | "# message" |
| 206 | ); |
| 207 | |
| 208 | int a = 1, b = 2; |
| 209 | EXPECT_DEATH(RTC_CHECK_EQ(a, b) << 1 << 2u, |
| 210 | "\n\n#\n" |
| 211 | "# Fatal error in: \\S+, line \\d+\n" |
| 212 | "# last system error: \\d+\n" |
| 213 | "# Check failed: a == b \\(1 vs. 2\\)\n" |
| 214 | "# 12" |
| 215 | ); |
| 216 | RTC_CHECK_EQ(5, 5); |
| 217 | |
| 218 | RTC_CHECK(true) << "Shouldn't crash" << 1; |
| 219 | EXPECT_DEATH(RTC_CHECK(false) << "Hi there!", |
| 220 | "\n\n#\n" |
| 221 | "# Fatal error in: \\S+, line \\d+\n" |
| 222 | "# last system error: \\d+\n" |
| 223 | "# Check failed: false\n" |
| 224 | "# Hi there!" |
| 225 | ); |
| 226 | } |
| 227 | #endif |
Jonas Olsson | ae18886 | 2018-06-18 11:19:22 +0200 | [diff] [blame] | 228 | */ |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 229 | // Test using multiple log streams. The INFO stream should get the INFO message, |
| 230 | // the VERBOSE stream should get the INFO and the VERBOSE. |
| 231 | // We should restore the correct global state at the end. |
| 232 | TEST(LogTest, MultipleStreams) { |
deadbeef | 37f5ecf | 2017-02-27 14:06:41 -0800 | [diff] [blame] | 233 | int sev = LogMessage::GetLogToStream(nullptr); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 234 | |
| 235 | std::string str1, str2; |
Tommi | 00aac5a | 2015-05-25 11:25:59 +0200 | [diff] [blame] | 236 | LogSinkImpl<StringStream> stream1(&str1), stream2(&str2); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 237 | LogMessage::AddLogToStream(&stream1, LS_INFO); |
| 238 | LogMessage::AddLogToStream(&stream2, LS_VERBOSE); |
| 239 | EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream1)); |
| 240 | EXPECT_EQ(LS_VERBOSE, LogMessage::GetLogToStream(&stream2)); |
| 241 | |
Mirko Bonadei | 675513b | 2017-11-09 11:09:25 +0100 | [diff] [blame] | 242 | RTC_LOG(LS_INFO) << "INFO"; |
| 243 | RTC_LOG(LS_VERBOSE) << "VERBOSE"; |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 244 | |
| 245 | EXPECT_NE(std::string::npos, str1.find("INFO")); |
| 246 | EXPECT_EQ(std::string::npos, str1.find("VERBOSE")); |
| 247 | EXPECT_NE(std::string::npos, str2.find("INFO")); |
| 248 | EXPECT_NE(std::string::npos, str2.find("VERBOSE")); |
| 249 | |
| 250 | LogMessage::RemoveLogToStream(&stream2); |
| 251 | LogMessage::RemoveLogToStream(&stream1); |
Tommi | 0eefb4d | 2015-05-23 09:54:07 +0200 | [diff] [blame] | 252 | EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream2)); |
| 253 | EXPECT_EQ(LS_NONE, LogMessage::GetLogToStream(&stream1)); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 254 | |
deadbeef | 37f5ecf | 2017-02-27 14:06:41 -0800 | [diff] [blame] | 255 | EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr)); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 256 | } |
| 257 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 258 | class LogThread { |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 259 | public: |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 260 | LogThread() : thread_(&ThreadEntry, this, "LogThread") {} |
| 261 | ~LogThread() { thread_.Stop(); } |
tommi | e725159 | 2017-07-14 14:44:46 -0700 | [diff] [blame] | 262 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 263 | void Start() { thread_.Start(); } |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 264 | |
| 265 | private: |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 266 | void Run() { |
| 267 | // LS_SENSITIVE by default to avoid cluttering up any real logging going on. |
Mirko Bonadei | 675513b | 2017-11-09 11:09:25 +0100 | [diff] [blame] | 268 | RTC_LOG(LS_SENSITIVE) << "RTC_LOG"; |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 269 | } |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 270 | |
| 271 | static void ThreadEntry(void* p) { static_cast<LogThread*>(p)->Run(); } |
| 272 | |
| 273 | PlatformThread thread_; |
| 274 | Event event_{false, false}; |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 275 | }; |
| 276 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 277 | // Ensure we don't crash when adding/removing streams while threads are going. |
| 278 | // We should restore the correct global state at the end. |
henrike@webrtc.org | c732a3e | 2014-10-09 22:08:15 +0000 | [diff] [blame] | 279 | TEST(LogTest, MultipleThreads) { |
deadbeef | 37f5ecf | 2017-02-27 14:06:41 -0800 | [diff] [blame] | 280 | int sev = LogMessage::GetLogToStream(nullptr); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 281 | |
| 282 | LogThread thread1, thread2, thread3; |
| 283 | thread1.Start(); |
| 284 | thread2.Start(); |
| 285 | thread3.Start(); |
| 286 | |
Niels Möller | ff3dd0c | 2018-06-20 10:27:53 +0200 | [diff] [blame] | 287 | std::string s1, s2, s3; |
| 288 | LogSinkImpl<StringStream> stream1(&s1), stream2(&s2), stream3(&s3); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 289 | for (int i = 0; i < 1000; ++i) { |
| 290 | LogMessage::AddLogToStream(&stream1, LS_INFO); |
| 291 | LogMessage::AddLogToStream(&stream2, LS_VERBOSE); |
| 292 | LogMessage::AddLogToStream(&stream3, LS_SENSITIVE); |
| 293 | LogMessage::RemoveLogToStream(&stream1); |
| 294 | LogMessage::RemoveLogToStream(&stream2); |
| 295 | LogMessage::RemoveLogToStream(&stream3); |
| 296 | } |
| 297 | |
deadbeef | 37f5ecf | 2017-02-27 14:06:41 -0800 | [diff] [blame] | 298 | EXPECT_EQ(sev, LogMessage::GetLogToStream(nullptr)); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 299 | } |
| 300 | |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 301 | TEST(LogTest, WallClockStartTime) { |
Peter Boström | 0c4e06b | 2015-10-07 12:23:21 +0200 | [diff] [blame] | 302 | uint32_t time = LogMessage::WallClockStartTime(); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 303 | // Expect the time to be in a sensible range, e.g. > 2012-01-01. |
| 304 | EXPECT_GT(time, 1325376000u); |
| 305 | } |
| 306 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 307 | TEST(LogTest, CheckExtraErrorField) { |
| 308 | LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_WARNING, |
| 309 | ERRCTX_ERRNO, 0xD); |
| 310 | ASSERT_FALSE(log_msg.is_noop()); |
| 311 | log_msg.stream() << "This gets added at dtor time"; |
phoglund | bb73873 | 2016-07-15 03:57:12 -0700 | [diff] [blame] | 312 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 313 | const std::string& extra = log_msg.get_extra(); |
| 314 | const size_t length_to_check = arraysize("[0x12345678]") - 1; |
| 315 | ASSERT_GE(extra.length(), length_to_check); |
| 316 | EXPECT_EQ(std::string("[0x0000000D]"), extra.substr(0, length_to_check)); |
| 317 | } |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 318 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 319 | TEST(LogTest, CheckFilePathParsed) { |
| 320 | LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO); |
| 321 | ASSERT_FALSE(log_msg.is_noop()); |
| 322 | log_msg.stream() << "<- Does this look right?"; |
| 323 | |
| 324 | const std::string stream = log_msg.GetPrintStream(); |
Paulina Hensman | f1e3cb4 | 2018-06-20 14:07:05 +0200 | [diff] [blame] | 325 | #if defined(WEBRTC_ANDROID) |
| 326 | const char* tag = log_msg.get_tag(); |
| 327 | EXPECT_NE(nullptr, strstr(tag, "myfile.cc")); |
| 328 | EXPECT_NE(std::string::npos, stream.find("100")); |
| 329 | #else |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 330 | EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)")); |
Paulina Hensman | f1e3cb4 | 2018-06-20 14:07:05 +0200 | [diff] [blame] | 331 | #endif |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 332 | } |
| 333 | |
Paulina Hensman | f1e3cb4 | 2018-06-20 14:07:05 +0200 | [diff] [blame] | 334 | #if defined(WEBRTC_ANDROID) |
| 335 | TEST(LogTest, CheckTagAddedToStringInDefaultOnLogMessageAndroid) { |
| 336 | std::string str; |
| 337 | LogSinkImpl<StringStream> stream(&str); |
| 338 | LogMessage::AddLogToStream(&stream, LS_INFO); |
| 339 | EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream)); |
| 340 | |
| 341 | RTC_LOG_TAG(LS_INFO, "my_tag") << "INFO"; |
| 342 | EXPECT_NE(std::string::npos, str.find("INFO")); |
| 343 | EXPECT_NE(std::string::npos, str.find("my_tag")); |
| 344 | } |
| 345 | #endif |
| 346 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 347 | TEST(LogTest, CheckNoopLogEntry) { |
| 348 | if (LogMessage::GetLogToDebug() <= LS_SENSITIVE) { |
| 349 | printf("CheckNoopLogEntry: skipping. Global severity is being overridden."); |
| 350 | return; |
| 351 | } |
| 352 | |
| 353 | // Logging at LS_SENSITIVE severity, is by default turned off, so this should |
| 354 | // be treated as a noop message. |
| 355 | LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_SENSITIVE); |
| 356 | log_msg.stream() << "Should be logged to nowhere."; |
| 357 | EXPECT_TRUE(log_msg.is_noop()); |
| 358 | const std::string stream = log_msg.GetPrintStream(); |
| 359 | EXPECT_TRUE(stream.empty()); |
| 360 | } |
| 361 | |
| 362 | // Test the time required to write 1000 80-character logs to a string. |
| 363 | TEST(LogTest, Perf) { |
| 364 | std::string str; |
| 365 | LogSinkImpl<StringStream> stream(&str); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 366 | LogMessage::AddLogToStream(&stream, LS_SENSITIVE); |
| 367 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 368 | const std::string message(80, 'X'); |
| 369 | { |
| 370 | // Just to be sure that we're not measuring the performance of logging |
| 371 | // noop log messages. |
| 372 | LogMessageForTesting sanity_check_msg(__FILE__, __LINE__, LS_SENSITIVE); |
| 373 | ASSERT_FALSE(sanity_check_msg.is_noop()); |
| 374 | } |
| 375 | |
| 376 | // We now know how many bytes the logging framework will tag onto every msg. |
| 377 | const size_t logging_overhead = str.size(); |
| 378 | // Reset the stream to 0 size. |
| 379 | str.clear(); |
| 380 | str.reserve(120000); |
| 381 | static const int kRepetitions = 1000; |
| 382 | |
Honghai Zhang | 82d7862 | 2016-05-06 11:29:15 -0700 | [diff] [blame] | 383 | int64_t start = TimeMillis(), finish; |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 384 | for (int i = 0; i < kRepetitions; ++i) { |
| 385 | LogMessageForTesting(__FILE__, __LINE__, LS_SENSITIVE).stream() << message; |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 386 | } |
Honghai Zhang | 82d7862 | 2016-05-06 11:29:15 -0700 | [diff] [blame] | 387 | finish = TimeMillis(); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 388 | |
| 389 | LogMessage::RemoveLogToStream(&stream); |
| 390 | stream.Close(); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 391 | |
Tommi | fef0500 | 2018-02-27 13:51:08 +0100 | [diff] [blame] | 392 | EXPECT_EQ(str.size(), (message.size() + logging_overhead) * kRepetitions); |
| 393 | RTC_LOG(LS_INFO) << "Total log time: " << TimeDiff(finish, start) << " ms " |
| 394 | << " total bytes logged: " << str.size(); |
henrike@webrtc.org | f048872 | 2014-05-13 18:00:26 +0000 | [diff] [blame] | 395 | } |
| 396 | |
| 397 | } // namespace rtc |