[Cast] Repair receiver playout time calculations and frame skip logic.

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>
@@ skipping 406 matching lines @@
 #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.";
+      VLOG(1) << "VideoFrame[" << num_video_frames_processed_
+              << " (dt=" << (video_playout_queue_.front().first -
+                             last_popped_video_playout_time_).InMicroseconds()
+              << " usec)]: Skipped.";
     } else {
-      VLOG(1) << "VideoFrame[" << num_video_frames_processed_ << "]: Playing "
+      VLOG(1) << "VideoFrame[" << num_video_frames_processed_
+              << " (dt=" << (video_playout_queue_.front().first -
+                             last_popped_video_playout_time_).InMicroseconds()
+              << " usec)]: Playing "
               << (cast_env()->Clock()->NowTicks() -
                       video_playout_queue_.front().first).InMicroseconds()
               << " usec later than intended.";
     }
 
+    last_popped_video_playout_time_ = video_playout_queue_.front().first;
     const scoped_refptr<VideoFrame> ret = video_playout_queue_.front().second;
     video_playout_queue_.pop_front();
     ++num_video_frames_processed_;
     return ret;
   }
 
   scoped_ptr<AudioBus> PopOneAudioFrame(bool was_skipped) {
     audio_lock_.AssertAcquired();
 
     if (was_skipped) {
-      VLOG(1) << "AudioFrame[" << num_audio_frames_processed_ << "]: Skipped";
+      VLOG(1) << "AudioFrame[" << num_audio_frames_processed_
+              << " (dt=" << (audio_playout_queue_.front().first -
+                             last_popped_audio_playout_time_).InMicroseconds()
+              << " usec)]: Skipped.";
     } else {
-      VLOG(1) << "AudioFrame[" << num_audio_frames_processed_ << "]: Playing "
+      VLOG(1) << "AudioFrame[" << num_audio_frames_processed_
+              << " (dt=" << (audio_playout_queue_.front().first -
+                             last_popped_audio_playout_time_).InMicroseconds()
+              << " usec)]: Playing "
               << (cast_env()->Clock()->NowTicks() -
                       audio_playout_queue_.front().first).InMicroseconds()
               << " usec later than intended.";
     }
 
+    last_popped_audio_playout_time_ = audio_playout_queue_.front().first;
     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;
@@ skipping 31 matching lines @@
   // 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_;
+  base::TimeTicks last_popped_video_playout_time_;
   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_;
+  base::TimeTicks last_popped_audio_playout_time_;
   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_;
 };
@@ skipping 54 matching lines @@
                                   audio_config,
                                   video_config,
                                   window_width,
                                   window_height);
   player.Start();
 
   base::MessageLoop().Run();  // Run forever (i.e., until SIGTERM).
   NOTREACHED();
   return 0;
 }