Logging for BWE test framework.

BUG=
R=stefan@webrtc.org, tina.legrand@webrtc.org

Review URL: https://webrtc-codereview.appspot.com/2749004

git-svn-id: http://webrtc.googlecode.com/svn/trunk@5055 4adac7df-926f-26a2-2b94-8c16560cd09d

webrtc/build/common.gypi

@@ -61,6 +61,9 @@
     # third party code will still have the reduced warning settings.
     'chromium_code': 1,
 
+    # Remote bitrate estimator logging/plotting.
+    'enable_bwe_test_logging%': 0,
+
     # Adds video support to dependencies shared by voice and video engine.
     # This should normally be enabled; the intended use is to disable only
     # when building voice engine exclusively.

webrtc/modules/modules.gyp

@@ -174,14 +174,16 @@
             'pacing/paced_sender_unittest.cc',
             'remote_bitrate_estimator/include/mock/mock_remote_bitrate_observer.h',
             'remote_bitrate_estimator/bitrate_estimator_unittest.cc',
-            'remote_bitrate_estimator/bwe_test_framework.cc',
-            'remote_bitrate_estimator/bwe_test_framework.h',
-            'remote_bitrate_estimator/bwe_test_framework_unittest.cc',
             'remote_bitrate_estimator/remote_bitrate_estimator_single_stream_unittest.cc',
             'remote_bitrate_estimator/remote_bitrate_estimator_unittest_helper.cc',
             'remote_bitrate_estimator/remote_bitrate_estimator_unittest_helper.h',
             'remote_bitrate_estimator/remote_bitrate_estimators_test.cc',
             'remote_bitrate_estimator/rtp_to_ntp_unittest.cc',
+            'remote_bitrate_estimator/test/bwe_test_framework.cc',
+            'remote_bitrate_estimator/test/bwe_test_framework.h',
+            'remote_bitrate_estimator/test/bwe_test_framework_unittest.cc',
+            'remote_bitrate_estimator/test/bwe_test_logging.cc',
+            'remote_bitrate_estimator/test/bwe_test_logging.h',
             'rtp_rtcp/source/mock/mock_rtp_payload_strategy.h',
             'rtp_rtcp/source/fec_receiver_unittest.cc',
             'rtp_rtcp/source/fec_test_helper.cc',
@@ -240,6 +242,14 @@
             'video_processing/main/test/unit_test/video_processing_unittest.h',
           ],
           'conditions': [
+            ['enable_bwe_test_logging==1', {
+              'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=1' ],
+            }, {
+              'defines': [ 'BWE_TEST_LOGGING_COMPILE_TIME_ENABLE=0' ],
+              'sources!': [
+                'remote_bitrate_estimator/test/bwe_test_logging.cc'
+              ],
+            }],
             # Run screen/window capturer tests only on platforms where they are
             # supported.
             ['desktop_capture_supported==0', {

webrtc/modules/remote_bitrate_estimator/remote_bitrate_estimators_test.cc

@@ -9,7 +9,7 @@
  */
 
 #include "gtest/gtest.h"
-#include "webrtc/modules/remote_bitrate_estimator/bwe_test_framework.h"
+#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_framework.h"
 #include "webrtc/modules/remote_bitrate_estimator/include/remote_bitrate_estimator.h"
 #include "webrtc/system_wrappers/interface/clock.h"
 #include "webrtc/system_wrappers/interface/constructor_magic.h"
@@ -69,11 +69,14 @@ class TestedEstimator : public RemoteBitrateObserver {
   }
 
   void EatPacket(const BwePacket& packet) {
+    BWE_TEST_LOGGING_CONTEXT(debug_name_);
+
     latest_estimate_kbps_ = -1.0;
 
     // We're treating the send time (from previous filter) as the arrival
     // time once packet reaches the estimator.
     int64_t packet_time_ms = (packet.send_time_us() + 500) / 1000;
+    BWE_TEST_LOGGING_TIME(packet_time_ms);
 
     int64_t step_ms = estimator_->TimeUntilNextProcess();
     while ((clock_.TimeInMilliseconds() + step_ms) < packet_time_ms) {
@@ -90,9 +93,12 @@ class TestedEstimator : public RemoteBitrateObserver {
   }
 
   void CheckEstimate() {
+    BWE_TEST_LOGGING_CONTEXT(debug_name_);
     double estimated_kbps = 0.0;
     if (LatestEstimate(&estimated_kbps)) {
       stats_.Push(estimated_kbps);
+      BWE_TEST_LOGGING_PLOT("Estimate", clock_.TimeInMilliseconds(),
+                            estimated_kbps / 100);
       double relative_estimate_kbps = 0.0;
       if (relative_estimator_ &&
           relative_estimator_->LatestEstimate(&relative_estimate_kbps)) {
@@ -102,13 +108,12 @@ class TestedEstimator : public RemoteBitrateObserver {
   }
 
   void LogStats() {
-    printf("%s Mean ", debug_name_.c_str());
+    BWE_TEST_LOGGING_CONTEXT(debug_name_);
+    BWE_TEST_LOGGING_CONTEXT("Mean");
     stats_.Log("kbps");
-    printf("\n");
     if (relative_estimator_) {
-      printf("%s Diff ", debug_name_.c_str());
+      BWE_TEST_LOGGING_CONTEXT("Diff");
       relative_estimator_stats_.Log("kbps");
-      printf("\n");
     }
   }
 
@@ -229,7 +234,7 @@ class RemoteBitrateEstimatorsTest : public ::testing::Test {
       processors_.push_back(video_senders_.back());
       total_capacity += configs[i].kbps;
     }
-    printf("RequiredLinkCapacity %d kbps\n", total_capacity);
+    BWE_TEST_LOGGING_LOG1("RequiredLinkCapacity", "%d kbps", total_capacity)
   }
 
   void LogStats() {
@@ -306,8 +311,8 @@ class RemoteBitrateEstimatorsTest : public ::testing::Test {
     RateCounterFilter counter;
     processors_.push_back(&jitter);
     processors_.push_back(&counter);
-    jitter.SetJitter(120);
+    jitter.SetJitter(20);
-    RunFor(10 * 60 * 1000);
+    RunFor(2 * 60 * 1000);
   }
   void IncreasingJitter1Test() {
     JitterFilter jitter;
@@ -407,37 +412,39 @@ class RemoteBitrateEstimatorsTest : public ::testing::Test {
   DISALLOW_COPY_AND_ASSIGN(RemoteBitrateEstimatorsTest);
 };
 
-#define SINGLE_TEST(enabled, test_name, video_senders)\
+#define SINGLE_TEST(enabled, test_name, video_senders, log)\
     TEST_F(RemoteBitrateEstimatorsTest, test_name##_##video_senders##Sender) {\
+      BWE_TEST_LOGGING_ENABLE(log);\
       if (enabled) {\
+        BWE_TEST_LOGGING_CONTEXT(#test_name);\
         AddVideoSenders(video_senders);\
         test_name##Test();\
         LogStats();\
       }\
     }
 
-#define MULTI_TEST(enabled, test_name)\
+#define MULTI_TEST(enabled, test_name, log)\
-    SINGLE_TEST((enabled) && ENABLE_1_SENDER, test_name, 1)\
+    SINGLE_TEST((enabled) && ENABLE_1_SENDER, test_name, 1, log)\
-    SINGLE_TEST((enabled) && ENABLE_3_SENDERS, test_name, 3)\
+    SINGLE_TEST((enabled) && ENABLE_3_SENDERS, test_name, 3, log)\
-    SINGLE_TEST((enabled) && ENABLE_10_SENDERS, test_name, 10)
+    SINGLE_TEST((enabled) && ENABLE_10_SENDERS, test_name, 10, log)
 
-MULTI_TEST(ENABLE_BASIC_TESTS, UnlimitedSpeed)
+MULTI_TEST(ENABLE_BASIC_TESTS, UnlimitedSpeed, true)
-MULTI_TEST(ENABLE_LOSS_TESTS, SteadyLoss)
+MULTI_TEST(ENABLE_LOSS_TESTS, SteadyLoss, true)
-MULTI_TEST(ENABLE_LOSS_TESTS, IncreasingLoss1)
+MULTI_TEST(ENABLE_LOSS_TESTS, IncreasingLoss1, true)
-MULTI_TEST(ENABLE_DELAY_TESTS, SteadyDelay)
+MULTI_TEST(ENABLE_DELAY_TESTS, SteadyDelay, true)
-MULTI_TEST(ENABLE_DELAY_TESTS, IncreasingDelay1)
+MULTI_TEST(ENABLE_DELAY_TESTS, IncreasingDelay1, true)
-MULTI_TEST(ENABLE_DELAY_TESTS, IncreasingDelay2)
+MULTI_TEST(ENABLE_DELAY_TESTS, IncreasingDelay2, true)
-MULTI_TEST(ENABLE_DELAY_TESTS, JumpyDelay1)
+MULTI_TEST(ENABLE_DELAY_TESTS, JumpyDelay1, true)
-MULTI_TEST(ENABLE_JITTER_TESTS, SteadyJitter)
+MULTI_TEST(ENABLE_JITTER_TESTS, SteadyJitter, true)
-MULTI_TEST(ENABLE_JITTER_TESTS, IncreasingJitter1)
+MULTI_TEST(ENABLE_JITTER_TESTS, IncreasingJitter1, true)
-MULTI_TEST(ENABLE_JITTER_TESTS, IncreasingJitter2)
+MULTI_TEST(ENABLE_JITTER_TESTS, IncreasingJitter2, true)
-MULTI_TEST(ENABLE_REORDER_TESTS, SteadyReorder)
+MULTI_TEST(ENABLE_REORDER_TESTS, SteadyReorder, true)
-MULTI_TEST(ENABLE_REORDER_TESTS, IncreasingReorder1)
+MULTI_TEST(ENABLE_REORDER_TESTS, IncreasingReorder1, true)
-MULTI_TEST(ENABLE_CHOKE_TESTS, SteadyChoke)
+MULTI_TEST(ENABLE_CHOKE_TESTS, SteadyChoke, true)
-MULTI_TEST(ENABLE_CHOKE_TESTS, IncreasingChoke1)
+MULTI_TEST(ENABLE_CHOKE_TESTS, IncreasingChoke1, true)
-MULTI_TEST(ENABLE_CHOKE_TESTS, IncreasingChoke2)
+MULTI_TEST(ENABLE_CHOKE_TESTS, IncreasingChoke2, true)
-MULTI_TEST(ENABLE_MULTI_TESTS, Multi1)
+MULTI_TEST(ENABLE_MULTI_TESTS, Multi1, true)
-MULTI_TEST(ENABLE_MULTI_TESTS, Multi2)
+MULTI_TEST(ENABLE_MULTI_TESTS, Multi2, true)
 
 }  // namespace bwe
 }  // namespace testing

webrtc/modules/remote_bitrate_estimator/test/bwe_plot.sh

@@ -0,0 +1,44 @@
+#!/bin/bash
+
+# Copyright (c) 2013 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.
+
+# To set up in e.g. Eclipse, run a separate shell and pipe the output from the
+# test into this script.
+#
+# In Eclipse, that amounts to creating a Run Configuration which starts
+# "/bin/bash" with the arguments "-c [trunk_path]/out/Debug/modules_unittests
+# --gtest_filter=*Estimators* | [trunk_path]/webrtc/modules/
+# remote_bitrate_estimator/bwe_plot.sh"
+
+log=$(</dev/stdin)
+
+function gen_gnuplot_input {
+  colors=(a7001f 0a60c2 b2582b 21a66c d6604d 4393c3 f4a582 92c5de edcbb7 b1c5d0)
+  data_sets=$(echo "$log" | grep "^PLOT" | cut -f 2 | sort | uniq)
+  echo -n "reset; "
+  echo -n "set terminal wxt size 1440,900 font \"Arial,9\"; "
+  echo -n "set xtics 60; set xlabel \"Seconds\"; "
+  echo -n "plot "
+  i=0
+  for set in $data_sets ; do
+    (( i++ )) && echo -n ","
+    echo -n "'-' with "
+    echo -n "linespoints "
+    echo -n "ps 0.5 "
+    echo -n "lc rgbcolor \"#${colors[$(($i % 10))]}\" "
+    echo -n "title \"$set\" "
+  done
+  echo
+  for set in $data_sets ; do
+    echo "$log" | grep "^PLOT.$set" | cut -f 3,4
+    echo "e"
+  done
+}
+
+gen_gnuplot_input "$log" | gnuplot -persist

webrtc/modules/remote_bitrate_estimator/test/bwe_test_framework.cc

@@ -8,7 +8,7 @@
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
-#include "webrtc/modules/remote_bitrate_estimator/bwe_test_framework.h"
+#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_framework.h"
 
 namespace webrtc {
 namespace testing {
@@ -24,7 +24,6 @@ bool IsTimeSorted(const Packets& packets) {
   }
   return true;
 }
-
 }  // namespace bwe
 }  // namespace testing
 }  // namespace webrtc

webrtc/modules/remote_bitrate_estimator/test/bwe_test_framework.h

@@ -8,20 +8,19 @@
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
-#ifndef WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_BWE_TEST_FRAMEWORK_H_
+#ifndef WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_TEST_BWE_TEST_FRAMEWORK_H_
-#define WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_BWE_TEST_FRAMEWORK_H_
+#define WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_TEST_BWE_TEST_FRAMEWORK_H_
 
 #include <algorithm>
 #include <cassert>
 #include <cmath>
-#include <cstdio>
 #include <list>
 #include <numeric>
 #include <string>
 #include <vector>
 
 #include "webrtc/modules/interface/module_common_types.h"
-#include "webrtc/system_wrappers/interface/constructor_magic.h"
+#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h"
 
 namespace webrtc {
 namespace testing {
@@ -119,7 +118,7 @@ template<typename T> class Stats {
   }
 
   void Log(const std::string& units) {
-    printf("%f %s\t+/-%f\t[%f,%f]",
+    BWE_TEST_LOGGING_LOG5("", "%f %s\t+/-%f\t[%f,%f]",
         GetMean(), units.c_str(), GetStdDev(), GetMin(), GetMax());
   }
 
@@ -290,12 +289,9 @@ class RateCounterFilter : public PacketProcessorInterface {
   uint32_t bits_per_second() const { return bytes_per_second_ * 8; }
 
   void LogStats() {
-    printf("RateCounterFilter ");
+    BWE_TEST_LOGGING_CONTEXT("RateCounterFilter");
     pps_stats_.Log("pps");
-    printf("\n");
-    printf("RateCounterFilter ");
     kbps_stats_.Log("kbps");
-    printf("\n");
   }
 
   virtual void RunFor(int64_t /*time_ms*/, Packets* in_out) {
@@ -339,6 +335,8 @@ class LossFilter : public PacketProcessorInterface {
   virtual ~LossFilter() {}
 
   void SetLoss(float loss_percent) {
+    BWE_TEST_LOGGING_ENABLE(false);
+    BWE_TEST_LOGGING_LOG1("Loss", "%f%%", loss_percent);
     assert(loss_percent >= 0.0f);
     assert(loss_percent <= 100.0f);
     loss_fraction_ = loss_percent * 0.01f;
@@ -368,6 +366,8 @@ class DelayFilter : public PacketProcessorInterface {
   virtual ~DelayFilter() {}
 
   void SetDelay(int64_t delay_ms) {
+    BWE_TEST_LOGGING_ENABLE(false);
+    BWE_TEST_LOGGING_LOG1("Delay", "%d ms", static_cast<int>(delay_ms));
     assert(delay_ms >= 0);
     delay_us_ = delay_ms * 1000;
   }
@@ -398,6 +398,9 @@ class JitterFilter : public PacketProcessorInterface {
   virtual ~JitterFilter() {}
 
   void SetJitter(int64_t stddev_jitter_ms) {
+    BWE_TEST_LOGGING_ENABLE(false);
+    BWE_TEST_LOGGING_LOG1("Jitter", "%d ms",
+                          static_cast<int>(stddev_jitter_ms));
     assert(stddev_jitter_ms >= 0);
     stddev_jitter_us_ = stddev_jitter_ms * 1000;
   }
@@ -426,6 +429,8 @@ class ReorderFilter : public PacketProcessorInterface {
   virtual ~ReorderFilter() {}
 
   void SetReorder(float reorder_percent) {
+    BWE_TEST_LOGGING_ENABLE(false);
+    BWE_TEST_LOGGING_LOG1("Reordering", "%f%%", reorder_percent);
     assert(reorder_percent >= 0.0f);
     assert(reorder_percent <= 100.0f);
     reorder_fraction_ = reorder_percent * 0.01f;
@@ -463,6 +468,8 @@ class ChokeFilter : public PacketProcessorInterface {
   virtual ~ChokeFilter() {}
 
   void SetCapacity(uint32_t kbps) {
+    BWE_TEST_LOGGING_ENABLE(false);
+    BWE_TEST_LOGGING_LOG1("BitrateChoke", "%d kbps", kbps);
     kbps_ = kbps;
   }
 
@@ -486,4 +493,4 @@ class ChokeFilter : public PacketProcessorInterface {
 }  // namespace testing
 }  // namespace webrtc
 
-#endif  // WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_BWE_TEST_FRAMEWORK_H_
+#endif  // WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_TEST_BWE_TEST_FRAMEWORK_H_

webrtc/modules/remote_bitrate_estimator/test/bwe_test_framework_unittest.cc

@@ -8,7 +8,7 @@
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
-#include "webrtc/modules/remote_bitrate_estimator/bwe_test_framework.h"
+#include "webrtc/modules/remote_bitrate_estimator/test/bwe_test_framework.h"
 
 #include <numeric>
 

webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.cc

@@ -0,0 +1,128 @@
+/*
+ *  Copyright (c) 2013 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 "webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h"
+
+#if BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
+
+#include <algorithm>
+#include <cstdarg>
+#include <cstdio>
+
+#include "webrtc/system_wrappers/interface/critical_section_wrapper.h"
+#include "webrtc/system_wrappers/interface/thread_wrapper.h"
+
+namespace webrtc {
+namespace testing {
+namespace bwe {
+
+Logging Logging::g_Logging;
+
+Logging::Context::Context(uint32_t name, int64_t timestamp_ms, bool enabled) {
+  const size_t kBufferSize = 16;
+  char string_buffer[kBufferSize] = {0};
+#if defined(_MSC_VER) && defined(_WIN32)
+  _snprintf(string_buffer, kBufferSize - 1, "%08x", name);
+#else
+  snprintf(string_buffer, kBufferSize, "%08x", name);
+#endif
+  Logging::GetInstance()->PushState(string_buffer, timestamp_ms, enabled);
+}
+
+Logging::Context::Context(const std::string& name, int64_t timestamp_ms,
+                          bool enabled) {
+  Logging::GetInstance()->PushState(name.c_str(), timestamp_ms, enabled);
+}
+
+Logging::Context::Context(const char* name, int64_t timestamp_ms,
+                          bool enabled) {
+  Logging::GetInstance()->PushState(name, timestamp_ms, enabled);
+}
+
+Logging::Context::~Context() {
+  Logging::GetInstance()->PopState();
+}
+
+Logging* Logging::GetInstance() {
+  return &g_Logging;
+}
+
+void Logging::Log(const char format[], ...) {
+  CriticalSectionScoped cs(crit_sect_.get());
+  ThreadMap::iterator it = thread_map_.find(ThreadWrapper::GetThreadId());
+  assert(it != thread_map_.end());
+  const State& state = it->second.top();
+  if (state.enabled) {
+    printf("%s\t", state.tag.c_str());
+    va_list args;
+    va_start(args, format);
+    vprintf(format, args);
+    va_end(args);
+    printf("\n");
+  }
+}
+
+void Logging::Plot(double value) {
+  CriticalSectionScoped cs(crit_sect_.get());
+  ThreadMap::iterator it = thread_map_.find(ThreadWrapper::GetThreadId());
+  assert(it != thread_map_.end());
+  const State& state = it->second.top();
+  if (state.enabled) {
+    printf("PLOT\t%s\t%f\t%f\n", state.tag.c_str(), state.timestamp_ms * 0.001,
+           value);
+  }
+}
+
+Logging::Logging()
+    : crit_sect_(CriticalSectionWrapper::CreateCriticalSection()),
+      thread_map_() {
+}
+
+void Logging::PushState(const char append_to_tag[], int64_t timestamp_ms,
+                        bool enabled) {
+  assert(append_to_tag);
+  CriticalSectionScoped cs(crit_sect_.get());
+  std::stack<State>* stack = &thread_map_[ThreadWrapper::GetThreadId()];
+  if (stack->empty()) {
+    State new_state(append_to_tag, std::max(static_cast<int64_t>(0),
+                                            timestamp_ms), enabled);
+    stack->push(new_state);
+  } else {
+    stack->push(stack->top());
+    State* state = &stack->top();
+    if (state->tag != "" && std::string(append_to_tag) != "") {
+      state->tag.append("_");
+    }
+    state->tag.append(append_to_tag);
+    state->timestamp_ms = std::max(timestamp_ms, state->timestamp_ms);
+    state->enabled = enabled && state->enabled;
+  }
+}
+
+void Logging::PopState() {
+  CriticalSectionScoped cs(crit_sect_.get());
+  ThreadMap::iterator it = thread_map_.find(ThreadWrapper::GetThreadId());
+  assert(it != thread_map_.end());
+  int64_t newest_timestamp_ms = it->second.top().timestamp_ms;
+  it->second.pop();
+  if (it->second.empty()) {
+    thread_map_.erase(it);
+  } else {
+    State* state = &it->second.top();
+    // Update time so that next log/plot will use the latest time seen so far
+    // in this call tree.
+    state->timestamp_ms = std::max(state->timestamp_ms, newest_timestamp_ms);
+  }
+}
+}  // namespace bwe
+}  // namespace testing
+}  // namespace webrtc
+
+#endif  // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE

webrtc/modules/remote_bitrate_estimator/test/bwe_test_logging.h

@@ -0,0 +1,197 @@
+/*
+ *  Copyright (c) 2013 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 WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_TEST_BWE_TEST_LOGGING_H_
+#define WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_TEST_BWE_TEST_LOGGING_H_
+
+// To enable BWE logging, run this command from trunk/ :
+// build/gyp_chromium --depth=. webrtc/modules/modules.gyp
+//   -Denable_bwe_test_logging=1
+#ifndef BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
+#define BWE_TEST_LOGGING_COMPILE_TIME_ENABLE 0
+#endif  // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
+
+// BWE logging allows you to insert dynamically named log/plot points in the
+// call tree. E.g. the function:
+//  void f1() {
+//    BWE_TEST_LOGGING_TIME(clock_->TimeInMilliseconds());
+//    BWE_TEST_LOGGING_CONTEXT("stream");
+//    for (uint32_t i=0; i<4; ++i) {
+//      BWE_TEST_LOGGING_ENABLE(i & 1);
+//      BWE_TEST_LOGGING_CONTEXT(i);
+//      BWE_TEST_LOGGING_LOG1("weight", "%f tonnes", weights_[i]);
+//      for (float j=0.0f; j<1.0; j+=0.4f) {
+//        BWE_TEST_LOGGING_PLOT("bps", -1, j);
+//      }
+//    }
+//  }
+//
+// Might produce the output:
+//   stream_00000001_weight 13.000000 tonnes
+//   PLOT  stream_00000001_bps  1.000000  0.000000
+//   PLOT  stream_00000001_bps  1.000000  0.400000
+//   PLOT  stream_00000001_bps  1.000000  0.800000
+//   stream_00000003_weight 39.000000 tonnes
+//   PLOT  stream_00000003_bps  1.000000  0.000000
+//   PLOT  stream_00000003_bps  1.000000  0.400000
+//   PLOT  stream_00000003_bps  1.000000  0.800000
+//
+// Log *contexts* are names concatenated with '_' between them, with the name
+// of the logged/plotted string/value last. Plot *time* is inherited down the
+// tree. A branch is enabled by default but can be *disabled* to reduce output.
+// The difference between the LOG and PLOT macros is that PLOT prefixes the line
+// so it can be easily filtered, plus it outputs the current time.
+
+#if !(BWE_TEST_LOGGING_COMPILE_TIME_ENABLE)
+
+// Insert a (hierarchical) logging context.
+// |name| is a char*, std::string or uint32_t to name the context.
+#define BWE_TEST_LOGGING_CONTEXT(name)
+
+// Allow/disallow logging down the call tree from this point. Logging must be
+// enabled all the way to the root of the call tree to take place.
+// |enable| is expected to be a bool.
+#define BWE_TEST_LOGGING_ENABLE(enabled)
+
+// Set current time (only affects PLOT output). Down the call tree, the latest
+// time set always takes precedence.
+// |time| is an int64_t time in ms, or -1 to inherit time from previous context.
+#define BWE_TEST_LOGGING_TIME(time)
+
+// Print to stdout, e.g.:
+//   Context1_Context2_Name  printf-formated-string
+// |name| is a char*, std::string or uint32_t to name the log line.
+// |format| is a printf format string.
+// |_1...| are arguments for printf.
+#define BWE_TEST_LOGGING_LOG1(name, format, _1)
+#define BWE_TEST_LOGGING_LOG2(name, format, _1, _2)
+#define BWE_TEST_LOGGING_LOG3(name, format, _1, _2, _3)
+#define BWE_TEST_LOGGING_LOG4(name, format, _1, _2, _3, _4)
+#define BWE_TEST_LOGGING_LOG5(name, format, _1, _2, _3, _4, _5)
+
+// Print to stdout in tab-separated format suitable for plotting, e.g.:
+//   PLOT  Context1_Context2_Name  time  value
+// |name| is a char*, std::string or uint32_t to name the plotted value.
+// |time| is an int64_t time in ms, or -1 to inherit time from previous context.
+// |value| is a double precision float to be plotted.
+#define BWE_TEST_LOGGING_PLOT(name, time, value)
+
+#else  // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
+
+#include <map>
+#include <stack>
+#include <string>
+
+#include "webrtc/common_types.h"
+#include "webrtc/system_wrappers/interface/constructor_magic.h"
+#include "webrtc/system_wrappers/interface/scoped_ptr.h"
+
+#define __BWE_TEST_LOGGING_CONTEXT_NAME(ctx, line) ctx ## line
+#define __BWE_TEST_LOGGING_CONTEXT_DECLARE(ctx, line, name, time, enabled) \
+    webrtc::testing::bwe::Logging::Context \
+        __BWE_TEST_LOGGING_CONTEXT_NAME(ctx, line)(name, time, enabled)
+
+#define BWE_TEST_LOGGING_CONTEXT(name) \
+    __BWE_TEST_LOGGING_CONTEXT_DECLARE(__bwe_log_, __LINE__, name, -1, true)
+#define BWE_TEST_LOGGING_ENABLE(enabled) \
+    __BWE_TEST_LOGGING_CONTEXT_DECLARE(__bwe_log_, __LINE__, "", -1, \
+                                       static_cast<bool>(enabled))
+#define BWE_TEST_LOGGING_TIME(time) \
+    __BWE_TEST_LOGGING_CONTEXT_DECLARE(__bwe_log_, __LINE__, "", \
+                                       static_cast<int64_t>(time), true)
+
+#define BWE_TEST_LOGGING_LOG1(name, format, _1) \
+    do { \
+      BWE_TEST_LOGGING_CONTEXT(name); \
+      webrtc::testing::bwe::Logging::GetInstance()->Log(format, _1); \
+    } while (0);
+#define BWE_TEST_LOGGING_LOG2(name, format, _1, _2) \
+    do { \
+      BWE_TEST_LOGGING_CONTEXT(name); \
+      webrtc::testing::bwe::Logging::GetInstance()->Log(format, _1, _2); \
+    } while (0);
+#define BWE_TEST_LOGGING_LOG3(name, format, _1, _2, _3) \
+    do { \
+      BWE_TEST_LOGGING_CONTEXT(name); \
+      webrtc::testing::bwe::Logging::GetInstance()->Log(format, _1, _2, _3); \
+    } while (0);
+#define BWE_TEST_LOGGING_LOG4(name, format, _1, _2, _3, _4) \
+    do { \
+      BWE_TEST_LOGGING_CONTEXT(name); \
+      webrtc::testing::bwe::Logging::GetInstance()->Log(format, _1, _2, _3, \
+                                                        _4); \
+    } while (0);
+#define BWE_TEST_LOGGING_LOG5(name, format, _1, _2, _3, _4, _5) \
+    do {\
+      BWE_TEST_LOGGING_CONTEXT(name); \
+      webrtc::testing::bwe::Logging::GetInstance()->Log(format, _1, _2, _3, \
+                                                        _4, _5); \
+    } while (0);
+
+#define BWE_TEST_LOGGING_PLOT(name, time, value)\
+    do { \
+      __BWE_TEST_LOGGING_CONTEXT_DECLARE(__bwe_log_, __LINE__, name, \
+                                         static_cast<int64_t>(time), true); \
+      webrtc::testing::bwe::Logging::GetInstance()->Plot(value); \
+    } while (0);
+
+namespace webrtc {
+
+class CriticalSectionWrapper;
+
+namespace testing {
+namespace bwe {
+
+class Logging {
+ public:
+  class Context {
+   public:
+    Context(uint32_t name, int64_t timestamp_ms, bool enabled);
+    Context(const std::string& name, int64_t timestamp_ms, bool enabled);
+    Context(const char* name, int64_t timestamp_ms, bool enabled);
+    ~Context();
+   private:
+    DISALLOW_IMPLICIT_CONSTRUCTORS(Context);
+  };
+
+  static Logging* GetInstance();
+  void Log(const char format[], ...);
+  void Plot(double value);
+
+ private:
+  struct State {
+    State(const char new_tag[], int64_t timestamp_ms, bool enabled)
+        : tag(new_tag),
+          timestamp_ms(timestamp_ms),
+          enabled(enabled) {
+    }
+    std::string tag;
+    int64_t timestamp_ms;
+    bool enabled;
+  };
+  typedef std::map<uint32_t, std::stack<State> > ThreadMap;
+
+  Logging();
+  void PushState(const char append_to_tag[], int64_t timestamp_ms,
+                 bool enabled);
+  void PopState();
+
+  static Logging g_Logging;
+  scoped_ptr<CriticalSectionWrapper> crit_sect_;
+  ThreadMap thread_map_;
+
+  DISALLOW_COPY_AND_ASSIGN(Logging);
+};
+}  // namespace bwe
+}  // namespace testing
+}  // namespace webrtc
+
+#endif  // BWE_TEST_LOGGING_COMPILE_TIME_ENABLE
+#endif  // WEBRTC_MODULES_REMOTE_BITRATE_ESTIMATOR_TEST_BWE_TEST_LOGGING_H_