From 0e7c060256182c112bec3962749b06e2954562e9 Mon Sep 17 00:00:00 2001 From: "henrike@webrtc.org" Date: Wed, 8 Feb 2012 18:53:50 +0000 Subject: [PATCH] Linux logs were not displaying time at ms resolution. Review URL: https://webrtc-codereview.appspot.com/267012 git-svn-id: http://webrtc.googlecode.com/svn/trunk@1644 4adac7df-926f-26a2-2b94-8c16560cd09d --- .../source/cpu_measurement_harness.cc | 127 ++++++++++++++++++ .../source/cpu_measurement_harness.h | 66 +++++++++ .../source/system_wrappers.gyp | 3 + src/system_wrappers/source/trace_posix.cc | 88 ++++++------ src/system_wrappers/source/trace_unittest.cc | 57 ++++++++ 5 files changed, 293 insertions(+), 48 deletions(-) create mode 100644 src/system_wrappers/source/cpu_measurement_harness.cc create mode 100644 src/system_wrappers/source/cpu_measurement_harness.h create mode 100644 src/system_wrappers/source/trace_unittest.cc diff --git a/src/system_wrappers/source/cpu_measurement_harness.cc b/src/system_wrappers/source/cpu_measurement_harness.cc new file mode 100644 index 000000000..237e77650 --- /dev/null +++ b/src/system_wrappers/source/cpu_measurement_harness.cc @@ -0,0 +1,127 @@ +/* + * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#include "system_wrappers/interface/cpu_wrapper.h" +#include "system_wrappers/interface/event_wrapper.h" +#include "system_wrappers/interface/scoped_ptr.h" +#include "system_wrappers/source/cpu_measurement_harness.h" + +const int kCpuCheckPeriodMs = 100; + +namespace webrtc { + +CpuMeasurementHarness* CpuMeasurementHarness::Create( + CpuTarget* target, + int work_period_ms, + int work_iterations_per_period, + int duration_ms) { + if (target == NULL) { + return NULL; + } + if (work_period_ms > duration_ms) { + return NULL; + } + if (work_period_ms < 0) { + return NULL; + } + if (duration_ms < 0) { + return NULL; + } + if (work_iterations_per_period < 1) { + return NULL; + } + return new CpuMeasurementHarness(target, work_period_ms, + work_iterations_per_period, duration_ms); +} + +CpuMeasurementHarness::CpuMeasurementHarness(CpuTarget* target, + int work_period_ms, + int work_iterations_per_period, + int duration_ms) + : cpu_target_(target), + work_period_ms_(work_period_ms), + work_iterations_per_period_(work_iterations_per_period), + duration_ms_(duration_ms), + cpu_sum_(0), + cpu_iterations_(0), + cpu_(CpuWrapper::CreateCpu()), + event_(EventWrapper::Create()) { +} + +CpuMeasurementHarness::~CpuMeasurementHarness() { +} + +bool CpuMeasurementHarness::Run() { + if (!WaitForCpuInit()) { + return false; + } + // No need for precision. Run for approximately the asked for duration. + // TODO(hellner): very low prio if at all, the actual duration of the test + // will be longer if calling DoWork() is not negligable and/or called many + // times. It may make sense to compensate for drift here. This will, + // however, only add complexity with minimal gains. Perhaps renaming the + // duration_ms_ to something more fuzzy is a better idea. However, the name + // would be very convoluted if it is to be self documenting. + int elapsed_time_ms = 0; + int last_measured_time = 0; + while (elapsed_time_ms < duration_ms_) { + if (((elapsed_time_ms - last_measured_time) / kCpuCheckPeriodMs) >= 1) { + last_measured_time = elapsed_time_ms; + Measure(); + } + if (!DoWork()) { + return false; + } + event_->Wait(work_period_ms_); + elapsed_time_ms += work_period_ms_; + } + return true; +} + +int CpuMeasurementHarness::AverageCpu() { + if (cpu_iterations_ == 0) { + return 0; + } + assert(cpu_sum_ >= 0); + assert(cpu_iterations_ >= 0); + return cpu_sum_ / cpu_iterations_; +} + +bool CpuMeasurementHarness::WaitForCpuInit() { + bool cpu_usage_available = false; + int num_iterations = 0; + // Initializing the CPU measurements may take a couple of seconds on Windows. + // Since the initialization is lazy we need to wait until it is completed. + // Should not take more than 10000 ms. + while (!cpu_usage_available && (++num_iterations < 10000)) { + event_->Wait(1); + cpu_usage_available = cpu_->CpuUsage() != -1; + } + return cpu_usage_available; +} + +void CpuMeasurementHarness::Measure() { + WebRtc_UWord32 num_cores = 0; + WebRtc_UWord32* cores = NULL; + // Return the average CPU for now. + cpu_sum_ = cpu_->CpuUsageMultiCore(num_cores, cores); + ++cpu_iterations_; +} + +bool CpuMeasurementHarness::DoWork() { + for (int i = 0; i < work_iterations_per_period_; ++i) { + if (!cpu_target_->DoWork()) { + return false; + } + } + return true; +} + +} // namespace webrtc diff --git a/src/system_wrappers/source/cpu_measurement_harness.h b/src/system_wrappers/source/cpu_measurement_harness.h new file mode 100644 index 000000000..3b87f2775 --- /dev/null +++ b/src/system_wrappers/source/cpu_measurement_harness.h @@ -0,0 +1,66 @@ +/* + * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#ifndef SRC_SYSTEM_WRAPPERS_SOURCE_CPU_MEASUREMENT_HARNESS_H_ +#define SRC_SYSTEM_WRAPPERS_SOURCE_CPU_MEASUREMENT_HARNESS_H_ + +#include "system_wrappers/interface/scoped_ptr.h" + +namespace webrtc { + +class CpuWrapper; +class EventWrapper; +class ThreadWrapper; + +// This abstract class provides an interface that should be passed to +// CpuMeasurementHarness. CpuMeasurementHarness will call it with the +// frequency requested and measure the CPU usage for all calls. +class CpuTarget { + public: + // Callback function for which the CPU usage should be calculated. + virtual bool DoWork() = 0; + + protected: + CpuTarget() {} + virtual ~CpuTarget() {} +}; + +class CpuMeasurementHarness { + public: + static CpuMeasurementHarness* Create(CpuTarget* target, + int work_period_ms, + int work_iterations_per_period, + int duration_ms); + ~CpuMeasurementHarness(); + bool Run(); + int AverageCpu(); + + protected: + CpuMeasurementHarness(CpuTarget* target, int work_period_ms, + int work_iterations_per_period, int duration_ms); + + private: + bool WaitForCpuInit(); + void Measure(); + bool DoWork(); + + CpuTarget* cpu_target_; + const int work_period_ms_; + const int work_iterations_per_period_; + const int duration_ms_; + int cpu_sum_; + int cpu_iterations_; + scoped_ptr cpu_; + scoped_ptr event_; +}; + +} // namespace webrtc + +#endif // SRC_SYSTEM_WRAPPERS_SOURCE_CPU_MEASUREMENT_HARNESS_H_ diff --git a/src/system_wrappers/source/system_wrappers.gyp b/src/system_wrappers/source/system_wrappers.gyp index ce2438ffe..79820e93f 100644 --- a/src/system_wrappers/source/system_wrappers.gyp +++ b/src/system_wrappers/source/system_wrappers.gyp @@ -159,6 +159,8 @@ ], 'sources': [ 'cpu_wrapper_unittest.cc', + 'cpu_measurement_harness.h', + 'cpu_measurement_harness.cc', 'list_unittest.cc', 'map_unittest.cc', 'data_log_unittest.cc', @@ -166,6 +168,7 @@ 'data_log_helpers_unittest.cc', 'data_log_c_helpers_unittest.c', 'data_log_c_helpers_unittest.h', + 'trace_unittest.cc', ], 'conditions': [ ['enable_data_logging==1', { diff --git a/src/system_wrappers/source/trace_posix.cc b/src/system_wrappers/source/trace_posix.cc index 877e87d70..caf11286d 100644 --- a/src/system_wrappers/source/trace_posix.cc +++ b/src/system_wrappers/source/trace_posix.cc @@ -1,5 +1,5 @@ /* - * Copyright (c) 2011 The WebRTC project authors. All Rights Reserved. + * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. * * Use of this source code is governed by a BSD-style license * that can be found in the LICENSE file in the root of the source @@ -14,6 +14,7 @@ #include #include #include +#include #include #ifdef WEBRTC_ANDROID #include @@ -38,8 +39,9 @@ namespace webrtc { TracePosix::TracePosix() { - _prevAPITickCount = time(NULL); - _prevTickCount = _prevAPITickCount; + struct timeval systemTimeHighRes; + gettimeofday(&systemTimeHighRes, 0); + _prevAPITickCount = _prevTickCount = systemTimeHighRes.tv_sec; } TracePosix::~TracePosix() @@ -50,53 +52,43 @@ TracePosix::~TracePosix() WebRtc_Word32 TracePosix::AddTime(char* traceMessage, const TraceLevel level) const { - time_t dwCurrentTimeInSeconds = time(NULL); - struct tm systemTime; - gmtime_r(&dwCurrentTimeInSeconds, &systemTime); - - if(level == kTraceApiCall) + struct timeval systemTimeHighRes; + if (gettimeofday(&systemTimeHighRes, 0) == -1) { - WebRtc_UWord32 dwDeltaTime = dwCurrentTimeInSeconds - _prevTickCount; - _prevTickCount = dwCurrentTimeInSeconds; - - if(_prevTickCount == 0) - { - dwDeltaTime = 0; - } - if(dwDeltaTime > 0x0fffffff) - { - // Either wraparound or data race. - dwDeltaTime = 0; - } - if(dwDeltaTime > 99999) - { - dwDeltaTime = 99999; - } - - sprintf(traceMessage, "(%2u:%2u:%2u:%3u |%5lu) ", systemTime.tm_hour, - systemTime.tm_min, systemTime.tm_sec, 0, - static_cast(dwDeltaTime)); - } else { - WebRtc_UWord32 dwDeltaTime = dwCurrentTimeInSeconds - _prevAPITickCount; - _prevAPITickCount = dwCurrentTimeInSeconds; - if(_prevAPITickCount == 0) - { - dwDeltaTime = 0; - } - if(dwDeltaTime > 0x0fffffff) - { - // Either wraparound or data race. - dwDeltaTime = 0; - } - if(dwDeltaTime > 99999) - { - dwDeltaTime = 99999; - } - sprintf(traceMessage, "(%2u:%2u:%2u:%3u |%5lu) ", systemTime.tm_hour, - systemTime.tm_min, systemTime.tm_sec, 0, - static_cast(dwDeltaTime)); + return -1; } - // Messages is 22 characters. + const struct tm* systemTime = + localtime(&systemTimeHighRes.tv_sec); + + const WebRtc_UWord32 ms_time = systemTimeHighRes.tv_usec / 1000; + WebRtc_UWord32 prevTickCount = 0; + if (level == kTraceApiCall) + { + prevTickCount = _prevTickCount; + _prevTickCount = ms_time; + } else { + prevTickCount = _prevAPITickCount; + _prevAPITickCount = ms_time; + } + WebRtc_UWord32 dwDeltaTime = ms_time - prevTickCount; + if (prevTickCount == 0) + { + dwDeltaTime = 0; + } + if (dwDeltaTime > 0x0fffffff) + { + // Either wraparound or data race. + dwDeltaTime = 0; + } + if(dwDeltaTime > 99999) + { + dwDeltaTime = 99999; + } + + sprintf(traceMessage, "(%2u:%2u:%2u:%3u |%5lu) ", systemTime->tm_hour, + systemTime->tm_min, systemTime->tm_sec, ms_time, + static_cast(dwDeltaTime)); + // Messages are 22 characters. return 22; } diff --git a/src/system_wrappers/source/trace_unittest.cc b/src/system_wrappers/source/trace_unittest.cc new file mode 100644 index 000000000..982e71572 --- /dev/null +++ b/src/system_wrappers/source/trace_unittest.cc @@ -0,0 +1,57 @@ +/* + * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. + * + * Use of this source code is governed by a BSD-style license + * that can be found in the LICENSE file in the root of the source + * tree. An additional intellectual property rights grant can be found + * in the file PATENTS. All contributing project authors may + * be found in the AUTHORS file in the root of the source tree. + */ + +#include "system_wrappers/interface/trace.h" + +#include "gtest/gtest.h" +#include "system_wrappers/source/cpu_measurement_harness.h" +#include "testsupport/fileutils.h" + +using webrtc::CpuMeasurementHarness; +using webrtc::Trace; +using webrtc::kTraceWarning; +using webrtc::kTraceUtility; + +class Logger : public webrtc::CpuTarget { + public: + Logger() { + Trace::CreateTrace(); + std::string trace_file = webrtc::test::OutputPath() + + "trace_unittest.txt"; + Trace::SetTraceFile(trace_file.c_str()); + Trace::SetLevelFilter(webrtc::kTraceAll); + } + virtual ~Logger() { + Trace::ReturnTrace(); + } + + virtual bool DoWork() { + // Use input paremeters to WEBRTC_TRACE that are not likely to be removed + // in future code. E.g. warnings will likely be kept and this file is in + // utility so it should use kTraceUtility. + WEBRTC_TRACE(kTraceWarning, kTraceUtility, 0, "Log line"); + return true; + } +}; + +// This test is disabled because it measures CPU usage. This is flaky because +// the CPU usage for a machine may spike due to OS or other application. +TEST(TraceTest, DISABLED_CpuUsage) { + Logger logger; + const int periodicity_ms = 1; + const int iterations_per_period = 10; + const int duration_ms = 1000; + CpuMeasurementHarness* cpu_harness = + CpuMeasurementHarness::Create(&logger, periodicity_ms, + iterations_per_period, duration_ms); + cpu_harness->Run(); + const int average_cpu = cpu_harness->AverageCpu(); + EXPECT_GE(5, average_cpu); +}