Cast: Print out AV sync in cast receiver if playing test video

media/cast/test/receiver.cc

 // Copyright 2013 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 <algorithm>
 #include <climits>
 #include <cstdarg>
 #include <cstdio>
 #include <deque>
+#include <map>
 #include <string>
 #include <utility>
 
 #include "base/at_exit.h"
 #include "base/command_line.h"
 #include "base/logging.h"
 #include "base/memory/ref_counted.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/synchronization/lock.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/threading/thread.h"
 #include "base/time/default_tick_clock.h"
 #include "base/timer/timer.h"
 #include "media/audio/audio_io.h"
 #include "media/audio/audio_manager.h"
 #include "media/audio/audio_parameters.h"
 #include "media/audio/fake_audio_log_factory.h"
 #include "media/base/audio_bus.h"
 #include "media/base/channel_layout.h"
 #include "media/base/video_frame.h"
 #include "media/cast/cast_config.h"
 #include "media/cast/cast_environment.h"
 #include "media/cast/cast_receiver.h"
 #include "media/cast/logging/logging_defines.h"
+#include "media/cast/test/utility/audio_utility.h"
+#include "media/cast/test/utility/barcode.h"
 #include "media/cast/test/utility/default_config.h"
 #include "media/cast/test/utility/in_process_receiver.h"
 #include "media/cast/test/utility/input_builder.h"
 #include "media/cast/test/utility/standalone_cast_environment.h"
 #include "media/cast/transport/transport/udp_transport.h"
 #include "net/base/net_util.h"
 
 #if defined(OS_LINUX)
 #include "media/cast/test/linux_output_window.h"
 #endif  // OS_LINUX
@@ skipping 218 matching lines @@
   // InProcessReceiver overrides.
 
   virtual void OnVideoFrame(const scoped_refptr<VideoFrame>& video_frame,
                             const base::TimeTicks& playout_time,
                             bool is_continuous) OVERRIDE {
     DCHECK(cast_env()->CurrentlyOn(CastEnvironment::MAIN));
     LOG_IF(WARNING, !is_continuous)
         << "Video: Discontinuity in received frames.";
     video_playout_queue_.push_back(std::make_pair(playout_time, video_frame));
     ScheduleVideoPlayout();
+    uint16 frame_no;
+    if (media::cast::test::DecodeBarcode(video_frame, &frame_no)) {
+      video_play_times_.insert(
+          std::pair<uint16, base::TimeTicks>(frame_no, playout_time));
+    } else {
+      VLOG(2) << "Barcode decode failed!";
+    }
   }
 
   virtual void OnAudioFrame(scoped_ptr<AudioBus> audio_frame,
                             const base::TimeTicks& playout_time,
                             bool is_continuous) OVERRIDE {
     DCHECK(cast_env()->CurrentlyOn(CastEnvironment::MAIN));
     LOG_IF(WARNING, !is_continuous)
         << "Audio: Discontinuity in received frames.";
     base::AutoLock auto_lock(audio_lock_);
+    uint16 frame_no;
+    if (media::cast::DecodeTimestamp(audio_frame->channel(0),
+                                     audio_frame->frames(),
+                                     &frame_no)) {
+      // Since there are lots of audio packets with the same frame_no,
+      // we really want to make sure that we get the playout_time from
+      // the first one. If is_continous is true, then it's possible
+      // that we already missed the first one.
+      if (is_continuous && frame_no == last_audio_frame_no_ + 1) {
+        audio_play_times_.insert(
+            std::pair<uint16, base::TimeTicks>(frame_no, playout_time));
+      }
+      last_audio_frame_no_ = frame_no;
+    } else {
+      VLOG(2) << "Audio decode failed!";
+      last_audio_frame_no_ = -2;
+    }
     audio_playout_queue_.push_back(
         std::make_pair(playout_time, audio_frame.release()));
   }
 
   // End of InProcessReceiver overrides.
   ////////////////////////////////////////////////////////////////////
 
   ////////////////////////////////////////////////////////////////////
   // AudioSourceCallback implementation.
 
@@ skipping 97 matching lines @@
 
   void PlayNextVideoFrame() {
     DCHECK(cast_env()->CurrentlyOn(CastEnvironment::MAIN));
     if (!video_playout_queue_.empty()) {
       const scoped_refptr<VideoFrame> video_frame = PopOneVideoFrame(false);
 #ifdef OS_LINUX
       render_.RenderFrame(video_frame);
 #endif  // OS_LINUX
     }
     ScheduleVideoPlayout();
+    CheckAVSync();
   }
 
   scoped_refptr<VideoFrame> PopOneVideoFrame(bool is_being_skipped) {
     DCHECK(cast_env()->CurrentlyOn(CastEnvironment::MAIN));
 
     if (is_being_skipped) {
       VLOG(1) << "VideoFrame[" << num_video_frames_processed_ << "]: Skipped.";
     } else {
       VLOG(1) << "VideoFrame[" << num_video_frames_processed_ << "]: Playing "
               << (cast_env()->Clock()->NowTicks() -
@@ skipping 18 matching lines @@
                       audio_playout_queue_.front().first).InMicroseconds()
               << " usec later than intended.";
     }
 
     scoped_ptr<AudioBus> ret(audio_playout_queue_.front().second);
     audio_playout_queue_.pop_front();
     ++num_audio_frames_processed_;
     return ret.Pass();
   }
 
+  void CheckAVSync() {
+    if (video_play_times_.size() > 30 &&
+        audio_play_times_.size() > 30) {
+      size_t num_events = 0;
+      base::TimeDelta delta;
+      std::map<uint16, base::TimeTicks>::iterator audio_iter, video_iter;
+      for (video_iter = video_play_times_.begin();
+           video_iter != video_play_times_.end();
+           ++video_iter) {
+        audio_iter = audio_play_times_.find(video_iter->first);
+        if (audio_iter != audio_play_times_.end()) {
+          num_events++;
+          // Positive values means audio is running behind video.
+          delta += audio_iter->second - video_iter->second;
+        }
+      }
+
+      if (num_events > 30) {
+        VLOG(0) << "Audio behind by: "
+                << (delta / num_events).InMilliseconds()
+                << "ms";
+        video_play_times_.clear();
+        audio_play_times_.clear();
+      }
+    } else if (video_play_times_.size() + audio_play_times_.size() > 500) {
+      // We are decoding audio or video timestamps, but not both, clear it out.
+      video_play_times_.clear();
+      audio_play_times_.clear();
+    }
+  }
+
   // Frames in the queue older than this (relative to NowTicks()) will be
   // dropped (i.e., playback is falling behind).
   const base::TimeDelta max_frame_age_;
 
   // Outputs created, started, and destroyed by this NaivePlayer.
 #ifdef OS_LINUX
   test::LinuxOutputWindow render_;
 #endif  // OS_LINUX
   scoped_ptr<AudioOutputStream> audio_output_stream_;
 
   // Video playout queue.
   typedef std::pair<base::TimeTicks, scoped_refptr<VideoFrame> >
       VideoQueueEntry;
   std::deque<VideoQueueEntry> video_playout_queue_;
   int64 num_video_frames_processed_;
 
   base::OneShotTimer<NaivePlayer> video_playout_timer_;
 
   // Audio playout queue, synchronized by |audio_lock_|.
   base::Lock audio_lock_;
   typedef std::pair<base::TimeTicks, AudioBus*> AudioQueueEntry;
   std::deque<AudioQueueEntry> audio_playout_queue_;
   int64 num_audio_frames_processed_;
 
   // These must only be used on the audio thread calling OnMoreData().
   scoped_ptr<AudioBus> currently_playing_audio_frame_;
   int currently_playing_audio_frame_start_;
+
+  std::map<uint16, base::TimeTicks> audio_play_times_;
+  std::map<uint16, base::TimeTicks> video_play_times_;
+  int32 last_audio_frame_no_;
 };
 
 }  // namespace cast
 }  // namespace media
 
 int main(int argc, char** argv) {
   base::AtExitManager at_exit;
   CommandLine::Init(argc, argv);
   InitLogging(logging::LoggingSettings());
 
@@ skipping 45 matching lines @@
                                   audio_config,
                                   video_config,
                                   window_width,
                                   window_height);
   player.Start();
 
   base::MessageLoop().Run();  // Run forever (i.e., until SIGTERM).
   NOTREACHED();
   return 0;
 }