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

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

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<CpuWrapper> cpu_;
+  scoped_ptr<EventWrapper> event_;
+};
+
+}  // namespace webrtc
+
+#endif  // SRC_SYSTEM_WRAPPERS_SOURCE_CPU_MEASUREMENT_HARNESS_H_

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', {

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 <stdarg.h>
 #include <stdio.h>
 #include <string.h>
+#include <sys/time.h>
 #include <time.h>
 #ifdef WEBRTC_ANDROID
     #include <pthread.h>
@@ -38,8 +39,9 @@
 namespace webrtc {
 TracePosix::TracePosix()
 {
-    _prevAPITickCount = time(NULL);
+    struct timeval systemTimeHighRes;
-    _prevTickCount = _prevAPITickCount;
+    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 timeval systemTimeHighRes;
-    struct tm systemTime;
+    if (gettimeofday(&systemTimeHighRes, 0) == -1)
-    gmtime_r(&dwCurrentTimeInSeconds, &systemTime);
-
-    if(level == kTraceApiCall)
     {
-        WebRtc_UWord32 dwDeltaTime = dwCurrentTimeInSeconds - _prevTickCount;
+        return -1;
-        _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<unsigned long>(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<unsigned long>(dwDeltaTime));
     }
-    // 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<unsigned long>(dwDeltaTime));
+    // Messages are 22 characters.
     return 22;
 }
 

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);
+}