Added logging of average power levels to AudioOutputController.

media/audio/audio_output_controller.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "media/audio/audio_output_controller.h"
 
 #include <stdint.h>
 
 #include <algorithm>
 #include <limits>
 
 #include "base/bind.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/numerics/safe_conversions.h"
 #include "base/strings/stringprintf.h"
 #include "base/task_runner_util.h"
 #include "base/threading/platform_thread.h"
 #include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "media/base/audio_timestamp_helper.h"
 
 using base::TimeDelta;
 
 namespace media {
+namespace {
+// Time in seconds between two successive measurements of audio power levels.
+constexpr int kPowerMonitorLogIntervalSeconds = 15;
+}  // namespace
 
 AudioOutputController::AudioOutputController(
     AudioManager* audio_manager,
     EventHandler* handler,
     const AudioParameters& params,
     const std::string& output_device_id,
     SyncReader* sync_reader)
     : audio_manager_(audio_manager),
       params_(params),
       handler_(handler),
@@ skipping 123 matching lines @@
 
   // We can start from created or paused state.
   if (state_ != kCreated && state_ != kPaused)
     return;
 
   // Ask for first packet.
   sync_reader_->RequestMoreData(base::TimeDelta(), base::TimeTicks(), 0);
 
   state_ = kPlaying;
 
+  if (will_monitor_audio_levels()) {
+    last_audio_level_log_time_ = base::TimeTicks::Now();
+  }
+
   stream_->Start(this);
 
   // For UMA tracking purposes, start the wedge detection timer.  This allows us
   // to record statistics about the number of wedged playbacks in the field.
   //
   // WedgeCheck() will look to see if |on_more_io_data_called_| is true after
   // the timeout expires.  Care must be taken to ensure the wedge check delay is
   // large enough that the value isn't queried while OnMoreDataIO() is setting
   // it.
   //
   // Timer self-manages its lifetime and WedgeCheck() will only record the UMA
   // statistic if state is still kPlaying.  Additional Start() calls will
   // invalidate the previous timer.
   wedge_timer_.reset(new base::OneShotTimer());
   wedge_timer_->Start(
       FROM_HERE, TimeDelta::FromSeconds(5), this,
       &AudioOutputController::WedgeCheck);
 
   handler_->OnControllerPlaying();
 }
 
 void AudioOutputController::StopStream() {
   DCHECK(message_loop_->BelongsToCurrentThread());
 
   if (state_ == kPlaying) {
     wedge_timer_.reset();
     stream_->Stop();
 
+    if (will_monitor_audio_levels()) {
+      LogAudioPowerLevel("StopStream");
+    }
+
     // A stopped stream is silent, and power_montior_.Scan() is no longer being
     // called; so we must reset the power monitor.
     power_monitor_.Reset();
 
     state_ = kPaused;
   }
 }
 
 void AudioOutputController::DoPause() {
   DCHECK(message_loop_->BelongsToCurrentThread());
@@ skipping 75 matching lines @@
     const base::TimeTicks reference_time = delay_timestamp + delay;
     std::unique_ptr<AudioBus> copy(AudioBus::Create(params_));
     dest->CopyTo(copy.get());
     message_loop_->PostTask(
         FROM_HERE,
         base::BindOnce(
             &AudioOutputController::BroadcastDataToDuplicationTargets, this,
             std::move(copy), reference_time));
   }
 
-  if (will_monitor_audio_levels())
+  if (will_monitor_audio_levels()) {
     power_monitor_.Scan(*dest, frames);
 
+    const auto now = base::TimeTicks::Now();
+    if ((now - last_audio_level_log_time_).InSeconds() >
+        kPowerMonitorLogIntervalSeconds) {
+      LogAudioPowerLevel("OnMoreData");
+      last_audio_level_log_time_ = now;
+    }
+  }
+
   return frames;
 }
 
 void AudioOutputController::BroadcastDataToDuplicationTargets(
     std::unique_ptr<AudioBus> audio_bus,
     base::TimeTicks reference_time) {
   DCHECK(message_loop_->BelongsToCurrentThread());
   if (state_ != kPlaying || duplication_targets_.empty())
     return;
 
   // Note: Do not need to acquire lock since this is running on the same thread
   // as where the set is modified.
   for (auto target = std::next(duplication_targets_.begin(), 1);
        target != duplication_targets_.end(); ++target) {
     std::unique_ptr<AudioBus> copy(AudioBus::Create(params_));
     audio_bus->CopyTo(copy.get());
     (*target)->OnData(std::move(copy), reference_time);
   }
 
   (*duplication_targets_.begin())->OnData(std::move(audio_bus), reference_time);
 }
 
+void AudioOutputController::LogAudioPowerLevel(const std::string& call_name) {
+  std::pair<float, bool> power_and_clip =
+      power_monitor_.ReadCurrentPowerAndClip();
+  handler_->OnLog(base::StringPrintf("AOC::%s: average audio level=%.2f dBFS",
+                                     call_name.c_str(), power_and_clip.first));
+}
+
 void AudioOutputController::OnError() {
   {
     base::AutoLock auto_lock(error_lock_);
     if (ignore_errors_during_stop_close_)
       return;
   }
 
   // Handle error on the audio controller thread.
   message_loop_->PostTask(
       FROM_HERE, base::BindOnce(&AudioOutputController::DoReportError, this));
@@ skipping 164 matching lines @@
   DCHECK(message_loop_->BelongsToCurrentThread());
 
   // If we should be playing and we haven't, that's a wedge.
   if (state_ == kPlaying) {
     UMA_HISTOGRAM_BOOLEAN("Media.AudioOutputControllerPlaybackStartupSuccess",
                           base::AtomicRefCountIsOne(&on_more_io_data_called_));
   }
 }
 
 }  // namespace media