Added new feature to print a text log to neteq_rtpplay

This will print out the major events during a NetEq simulation.

Bug: b/116685514
Change-Id: Iab172e9a9115695b42c67628d5523c727359bb89
Reviewed-on: https://webrtc-review.googlesource.com/c/114320
Commit-Queue: Ivo Creusen <ivoc@webrtc.org>
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Reviewed-by: Henrik Lundin <henrik.lundin@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#26019}

modules/audio_coding/BUILD.gn

@@ -1096,6 +1096,7 @@ rtc_source_set("neteq_tools_minimal") {
     "../../rtc_base:checks",
     "../../rtc_base:rtc_base_approved",
     "../rtp_rtcp",
+    "../rtp_rtcp:rtp_rtcp_format",
     "//third_party/abseil-cpp/absl/types:optional",
   ]
   defines = audio_codec_defines

modules/audio_coding/neteq/include/neteq.h

@@ -85,6 +85,8 @@ struct NetEqOperationsAndState {
   uint64_t accelerate_samples = 0;
   // Count of the number of buffer flushes.
   uint64_t packet_buffer_flushes = 0;
+  // The number of primary packets that were discarded.
+  uint64_t discarded_primary_packets = 0;
   // The statistics below are not cumulative.
   // The waiting time of the last decoded packet.
   uint64_t last_waiting_time_ms = 0;

modules/audio_coding/neteq/neteq_decoder_plc_unittest.cc

@@ -185,7 +185,7 @@ NetEqNetworkStatistics RunTest(int loss_cadence, std::string* checksum) {
   // No callback objects.
   NetEqTest::Callbacks callbacks;
 
-  NetEqTest neteq_test(config, decoders, external_decoders,
+  NetEqTest neteq_test(config, decoders, external_decoders, nullptr,
                        std::move(lossy_input), std::move(output), callbacks);
   EXPECT_LE(kRunTimeMs, neteq_test.Run());
 

modules/audio_coding/neteq/neteq_unittest.cc

@@ -1726,8 +1726,8 @@ TEST(NetEqNoTimeStretchingMode, RunTest) {
       new TimeLimitedNetEqInput(std::move(input), 20000));
   std::unique_ptr<AudioSink> output(new VoidAudioSink);
   NetEqTest::Callbacks callbacks;
-  NetEqTest test(config, codecs, ext_codecs, std::move(input_time_limit),
+  NetEqTest test(config, codecs, ext_codecs, nullptr,
-                 std::move(output), callbacks);
+                 std::move(input_time_limit), std::move(output), callbacks);
   test.Run();
   const auto stats = test.SimulationStats();
   EXPECT_EQ(0, stats.accelerate_rate);

modules/audio_coding/neteq/statistics_calculator.cc

@@ -216,7 +216,7 @@ void StatisticsCalculator::AddZeros(size_t num_samples) {
 }
 
 void StatisticsCalculator::PacketsDiscarded(size_t num_packets) {
-  discarded_packets_ += num_packets;
+  operations_and_state_.discarded_primary_packets += num_packets;
 }
 
 void StatisticsCalculator::SecondaryPacketsDiscarded(size_t num_packets) {

modules/audio_coding/neteq/tools/neteq_test.cc

@@ -10,9 +10,11 @@
 
 #include "modules/audio_coding/neteq/tools/neteq_test.h"
 
+#include <iomanip>
 #include <iostream>
 
 #include "api/audio_codecs/builtin_audio_decoder_factory.h"
+#include "modules/rtp_rtcp/source/byte_io.h"
 
 namespace webrtc {
 namespace test {
@@ -52,6 +54,7 @@ void DefaultNetEqTestErrorCallback::OnGetAudioError() {
 NetEqTest::NetEqTest(const NetEq::Config& config,
                      const DecoderMap& codecs,
                      const ExtDecoderMap& ext_codecs,
+                     std::unique_ptr<std::ofstream> text_log,
                      std::unique_ptr<NetEqInput> input,
                      std::unique_ptr<AudioSink> output,
                      Callbacks callbacks)
@@ -59,7 +62,8 @@ NetEqTest::NetEqTest(const NetEq::Config& config,
       input_(std::move(input)),
       output_(std::move(output)),
       callbacks_(callbacks),
-      sample_rate_hz_(config.sample_rate_hz) {
+      sample_rate_hz_(config.sample_rate_hz),
+      text_log_(std::move(text_log)) {
   RTC_CHECK(!config.enable_muted_state)
       << "The code does not handle enable_muted_state";
   RegisterDecoders(codecs);
@@ -117,7 +121,35 @@ NetEqTest::SimulationStepResult NetEqTest::RunToNextGetAudio() {
         current_state_.packet_iat_ms.push_back(time_now_ms -
                                                *last_packet_time_ms_);
       }
+      if (text_log_) {
+        const auto ops_state = neteq_->GetOperationsAndState();
+        const auto delta_wallclock =
+            last_packet_time_ms_ ? (time_now_ms - *last_packet_time_ms_) : -1;
+        const auto delta_timestamp =
+            last_packet_timestamp_
+                ? (static_cast<int64_t>(packet_data->header.timestamp) -
+                   *last_packet_timestamp_) *
+                      1000 / sample_rate_hz_
+                : -1;
+        const auto packet_size_bytes =
+            packet_data->payload.size() == 12
+                ? ByteReader<uint32_t>::ReadLittleEndian(
+                      &packet_data->payload[8])
+                : -1;
+        *text_log_ << "Packet   - wallclock: " << std::setw(5) << time_now_ms
+                   << ", delta wc: " << std::setw(4) << delta_wallclock
+                   << ", timestamp: " << std::setw(10)
+                   << packet_data->header.timestamp
+                   << ", delta ts: " << std::setw(4) << delta_timestamp
+                   << ", size: " << std::setw(5) << packet_size_bytes
+                   << ", frame size: " << std::setw(3)
+                   << ops_state.current_frame_size_ms
+                   << ", buffer size: " << std::setw(4)
+                   << ops_state.current_buffer_size_ms << std::endl;
+      }
       last_packet_time_ms_ = absl::make_optional<int>(time_now_ms);
+      last_packet_timestamp_ =
+          absl::make_optional<uint32_t>(packet_data->header.timestamp);
     }
 
     // Check if it is time to get output audio.
@@ -186,6 +218,39 @@ NetEqTest::SimulationStepResult NetEqTest::RunToNextGetAudio() {
         // Consider the whole frame to be the result of normal playout.
         result.action_times_ms[Action::kNormal] = 10;
       }
+      auto lifetime_stats = LifetimeStats();
+      if (text_log_) {
+        const bool plc =
+            (out_frame.speech_type_ == AudioFrame::SpeechType::kPLC) ||
+            (out_frame.speech_type_ == AudioFrame::SpeechType::kPLCCNG);
+        const bool cng = out_frame.speech_type_ == AudioFrame::SpeechType::kCNG;
+        const bool voice_concealed =
+            lifetime_stats.voice_concealed_samples >
+            prev_lifetime_stats_.voice_concealed_samples;
+        *text_log_ << "GetAudio - wallclock: " << std::setw(5) << time_now_ms
+                   << ", delta wc: " << std::setw(4)
+                   << (input_->NextEventTime().value_or(time_now_ms) -
+                       start_time_ms)
+                   << ", CNG: " << cng << ", PLC: " << plc
+                   << ", voice concealed: " << voice_concealed
+                   << ", buffer size: " << std::setw(4)
+                   << current_state_.current_delay_ms << std::endl;
+        if (operations_state.discarded_primary_packets >
+            prev_ops_state_.discarded_primary_packets) {
+          *text_log_ << "Discarded "
+                     << (operations_state.discarded_primary_packets -
+                         prev_ops_state_.discarded_primary_packets)
+                     << " primary packets." << std::endl;
+        }
+        if (operations_state.packet_buffer_flushes >
+            prev_ops_state_.packet_buffer_flushes) {
+          *text_log_ << "Flushed packet buffer "
+                     << (operations_state.packet_buffer_flushes -
+                         prev_ops_state_.packet_buffer_flushes)
+                     << " times." << std::endl;
+        }
+      }
+      prev_lifetime_stats_ = lifetime_stats;
       result.is_simulation_finished = input_->ended();
       prev_ops_state_ = operations_state;
       return result;

modules/audio_coding/neteq/tools/neteq_test.h

@@ -11,6 +11,7 @@
 #ifndef MODULES_AUDIO_CODING_NETEQ_TOOLS_NETEQ_TEST_H_
 #define MODULES_AUDIO_CODING_NETEQ_TOOLS_NETEQ_TEST_H_
 
+#include <fstream>
 #include <map>
 #include <memory>
 #include <string>
@@ -87,6 +88,7 @@ class NetEqTest : public NetEqSimulator {
   NetEqTest(const NetEq::Config& config,
             const DecoderMap& codecs,
             const ExtDecoderMap& ext_codecs,
+            std::unique_ptr<std::ofstream> text_log,
             std::unique_ptr<NetEqInput> input,
             std::unique_ptr<AudioSink> output,
             Callbacks callbacks);
@@ -121,6 +123,9 @@ class NetEqTest : public NetEqSimulator {
   int sample_rate_hz_;
   NetEqState current_state_;
   NetEqOperationsAndState prev_ops_state_;
+  NetEqLifetimeStatistics prev_lifetime_stats_;
+  absl::optional<uint32_t> last_packet_timestamp_;
+  std::unique_ptr<std::ofstream> text_log_;
 };
 
 }  // namespace test

modules/audio_coding/neteq/tools/neteq_test_factory.cc

@@ -14,6 +14,7 @@
 #include <limits.h>  // For ULONG_MAX returned by strtoul.
 #include <stdio.h>
 #include <stdlib.h>  // For strtoul.
+#include <fstream>
 #include <iostream>
 #include <memory>
 #include <set>
@@ -138,6 +139,10 @@ WEBRTC_DEFINE_bool(matlabplot,
 WEBRTC_DEFINE_bool(pythonplot,
                    false,
                    "Generates a python script for plotting the delay profile");
+WEBRTC_DEFINE_bool(textlog,
+                   false,
+                   "Generates a text log describing the simulation on a "
+                   "step-by-step basis.");
 WEBRTC_DEFINE_bool(concealment_events, false, "Prints concealment events");
 WEBRTC_DEFINE_int(max_nr_packets_in_buffer,
                   50,
@@ -460,6 +465,13 @@ std::unique_ptr<NetEqTest> NetEqTestFactory::InitializeTest(
     ext_codecs_[replacement_pt] = ext_dec_info;
   }
 
+  // Create a text log file if needed.
+  std::unique_ptr<std::ofstream> text_log;
+  if (FLAG_textlog) {
+    text_log =
+        absl::make_unique<std::ofstream>(output_file_name + ".text_log.txt");
+  }
+
   NetEqTest::Callbacks callbacks;
   stats_plotter_.reset(new NetEqStatsPlotter(FLAG_matlabplot, FLAG_pythonplot,
                                              FLAG_concealment_events,
@@ -475,8 +487,8 @@ std::unique_ptr<NetEqTest> NetEqTestFactory::InitializeTest(
   config.max_packets_in_buffer = FLAG_max_nr_packets_in_buffer;
   config.enable_fast_accelerate = FLAG_enable_fast_accelerate;
   return absl::make_unique<NetEqTest>(config, codecs, ext_codecs_,
-                                      std::move(input), std::move(output),
+                                      std::move(text_log), std::move(input),
-                                      callbacks);
+                                      std::move(output), callbacks);
 }
 
 }  // namespace test

rtc_tools/event_log_visualizer/analyzer.cc

@@ -1735,7 +1735,7 @@ std::unique_ptr<test::NetEqStatsGetter> CreateNetEqTestAndRun(
   callbacks.post_insert_packet = neteq_stats_getter->delay_analyzer();
   callbacks.get_audio_callback = neteq_stats_getter.get();
 
-  test::NetEqTest test(config, codecs, ext_codecs, std::move(input),
+  test::NetEqTest test(config, codecs, ext_codecs, nullptr, std::move(input),
                        std::move(output), callbacks);
   test.Run();
   return neteq_stats_getter;

test/fuzzers/neteq_rtp_fuzzer.cc

@@ -138,7 +138,7 @@ void FuzzOneInputTest(const uint8_t* data, size_t size) {
 
   NetEqTest::ExtDecoderMap ext_codecs;
 
-  NetEqTest test(config, codecs, ext_codecs, std::move(input),
+  NetEqTest test(config, codecs, ext_codecs, nullptr, std::move(input),
                  std::move(output), callbacks);
   test.Run();
 }

test/fuzzers/neteq_signal_fuzzer.cc

@@ -183,7 +183,7 @@ void FuzzOneInputTest(const uint8_t* data, size_t size) {
 
   NetEqTest::ExtDecoderMap ext_codecs;
 
-  NetEqTest test(config, codecs, ext_codecs, std::move(input),
+  NetEqTest test(config, codecs, ext_codecs, nullptr, std::move(input),
                  std::move(output), callbacks);
   test.Run();
 }