Add verbose level logging for mp4 muxer.

Adds verboselevel=1 logging with captured video
and audio frame information, and created mp4 blob
info such as timescale, duration, fragment counts.

Bug: 1497009
Change-Id: Ie786bc8a71597aead9bf913bb89d301bb6fe3d5b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4986221
Commit-Queue: Sunggook Chue <sunggch@microsoft.com>
Reviewed-by: Dale Curtis <dalecurtis@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1216623}

media/muxers/mp4_muxer.cc

@@ -7,8 +7,8 @@
 #include <algorithm>
 #include <memory>
 
+#include "base/logging.h"
 #include "base/time/time.h"
-
 namespace media {
 
 namespace {
@@ -30,6 +30,9 @@ Mp4Muxer::Mp4Muxer(AudioCodec audio_codec,
   CHECK(has_video_ || has_audio_);
   CHECK(!has_audio || audio_codec == AudioCodec::kAAC);
 
+  DVLOG(1) << __func__ << ", Max output interval in seconds: "
+           << max_data_output_interval_.InSeconds();
+
   // Creation can be done on a different sequence than main activities.
   DETACH_FROM_SEQUENCE(sequence_checker_);
 }
@@ -94,8 +97,10 @@ void Mp4Muxer::MaybeForceFlush() {
 
 bool Mp4Muxer::Flush() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
+  DVLOG(1) << __func__ << ", Flush called ";
 
   if (!mp4_muxer_delegate_->Flush()) {
+    DVLOG(1) << __func__ << ", Flush failed ";
     return false;
   }
 

media/muxers/mp4_muxer_delegate.cc

@@ -4,6 +4,7 @@
 
 #include "media/muxers/mp4_muxer_delegate.h"
 
+#include "base/logging.h"
 #include "components/version_info/version_info.h"
 #include "media/base/audio_parameters.h"
 #include "media/formats/mp4/avc.h"
@@ -342,6 +343,8 @@ void Mp4MuxerDelegate::AddVideoFrame(
     base::TimeTicks timestamp,
     bool is_key_frame) {
   if (!video_track_index_.has_value()) {
+    DVLOG(1) << __func__ << ", " << params.AsHumanReadableString();
+
     CHECK(codec_description.has_value());
     CHECK(is_key_frame);
     CHECK(start_video_time_.is_null());
@@ -353,8 +356,12 @@ void Mp4MuxerDelegate::AddVideoFrame(
     video_frame_rate_ = params.frame_rate;
 
     video_track_index_ = GetNextTrackIndex();
+    DVLOG(1) << __func__
+             << ", video track index:" << video_track_index_.value();
+
     uint32_t timescale = video_frame_rate_ * kMillisecondsTimeScale;
     context_->SetVideoTrack({video_track_index_.value(), timescale});
+    DVLOG(1) << __func__ << ", video track timescale:" << timescale;
 
     mp4::writable_boxes::Track track;
     moov_->tracks.emplace_back(std::move(track));
@@ -415,6 +422,8 @@ void Mp4MuxerDelegate::BuildVideoTrackWithKeyframe(
   // `vmhd`
   mp4::writable_boxes::VideoMediaHeader video_header = {};
   video_track.media.information.video_header = std::move(video_header);
+
+  DVLOG(1) << __func__ << ", video track created";
 }
 
 void Mp4MuxerDelegate::BuildVideoFragment(std::string encoded_data,
@@ -427,7 +436,7 @@ void Mp4MuxerDelegate::BuildVideoFragment(std::string encoded_data,
 
   Fragment* fragment = fragments_.back().get();
   if (!fragment) {
-    // Don't add if the first frame does not have SPS/PPS.
+    DVLOG(1) << __func__ << ", no valid video fragment exists";
     return;
   }
 
@@ -461,6 +470,8 @@ void Mp4MuxerDelegate::AddAudioFrame(
     absl::optional<AudioEncoder::CodecDescription> codec_description,
     base::TimeTicks timestamp) {
   if (!audio_track_index_.has_value()) {
+    DVLOG(1) << __func__ << ", " << params.AsHumanReadableString();
+
     CHECK(codec_description.has_value());
     CHECK(start_audio_time_.is_null());
 
@@ -517,6 +528,7 @@ void Mp4MuxerDelegate::BuildAudioTrack(
   // `smhd`
   mp4::writable_boxes::SoundMediaHeader sound_header = {};
   audio_track.media.information.sound_header = std::move(sound_header);
+  DVLOG(1) << __func__ << ", audio track created";
 }
 
 void Mp4MuxerDelegate::BuildAudioFragment(std::string encoded_data) {
@@ -528,7 +540,7 @@ void Mp4MuxerDelegate::BuildAudioFragment(std::string encoded_data) {
 
   Fragment* fragment = fragments_.back().get();
   if (!fragment) {
-    // Don't add if the first frame does not have SPS/PPS.
+    DVLOG(1) << __func__ << ", no valid audio fragment exists";
     return;
   }
 
@@ -572,6 +584,9 @@ bool Mp4MuxerDelegate::Flush() {
   // Finish movie box and write.
   BuildMovieBox();
 
+  // Log blob info.
+  LogBoxInfo();
+
   // Write `moov` box and its children.
   Mp4MovieBoxWriter movie_box_writer(*context_, *moov_);
   written_offset += movie_box_writer.WriteAndFlush();
@@ -769,6 +784,31 @@ int Mp4MuxerDelegate::GetNextTrackIndex() {
   return next_track_index_++;
 }
 
+void Mp4MuxerDelegate::LogBoxInfo() const {
+  std::ostringstream s;
+
+  s << "movie timescale:" << moov_->header.timescale
+    << ", duration in seconds:" << moov_->header.duration.InSeconds();
+  if (video_track_index_.has_value()) {
+    mp4::writable_boxes::Track& track = moov_->tracks[*video_track_index_];
+    s << ", video track index:" << *video_track_index_
+      << ", video track timescale:"
+      << context_->GetVideoTrack().value().timescale
+      << ", video track duration:" << track.header.duration;
+  }
+
+  if (audio_track_index_.has_value()) {
+    mp4::writable_boxes::Track& track = moov_->tracks[*audio_track_index_];
+    s << ", audio track index:" << *audio_track_index_
+      << ", audio track timescale:"
+      << context_->GetAudioTrack().value().timescale
+      << ", audio track duration:" << track.header.duration;
+  }
+  s << ", Fragment counts:" << fragments_.size();
+
+  DVLOG(1) << __func__ << ", " << s.str();
+}
+
 Mp4MuxerDelegate::Fragment::Fragment() = default;
 
 }  // namespace media.

media/muxers/mp4_muxer_delegate.h

@@ -106,6 +106,7 @@ class MEDIA_EXPORT Mp4MuxerDelegate : public Mp4MuxerDelegateInterface {
   int GetNextTrackIndex();
   void EnsureInitialized();
   void Reset();
+  void LogBoxInfo() const;
 
   std::unique_ptr<Mp4MuxerContext> context_;
   Muxer::WriteDataCB write_callback_;

media/muxers/muxer.cc

@@ -32,6 +32,14 @@ Muxer::VideoParameters::VideoParameters(const VideoParameters&) = default;
 
 Muxer::VideoParameters::~VideoParameters() = default;
 
+std::string Muxer::VideoParameters::AsHumanReadableString() const {
+  std::ostringstream s;
+  s << "size: width (" << visible_rect_size.width() << ") height ("
+    << visible_rect_size.height() << ")"
+    << ", frame_rate: " << frame_rate << ", video_codec: " << codec;
+  return s.str();
+}
+
 Muxer::EncodedFrame::EncodedFrame() = default;
 Muxer::EncodedFrame::EncodedFrame(
     absl::variant<AudioParameters, VideoParameters> params,

media/muxers/muxer.h

@@ -40,6 +40,10 @@ class MEDIA_EXPORT Muxer {
                     absl::optional<gfx::ColorSpace> color_space);
     VideoParameters(const VideoParameters&);
     ~VideoParameters();
+    // Returns a human-readable string describing `*this`.
+    // For debugging & test output only.
+    std::string AsHumanReadableString() const;
+
     gfx::Size visible_rect_size;
     double frame_rate;
     VideoCodec codec;