From 49f910a56badd05ef7451a2e0d69796d897581f2 Mon Sep 17 00:00:00 2001 From: Megamouse Date: Wed, 15 Nov 2023 23:58:21 +0100 Subject: [PATCH] recording: improve pts accuracy and consistency Also clean up some logging --- rpcs3/Emu/Cell/Modules/cellRec.cpp | 12 ------------ rpcs3/util/media_utils.cpp | 23 ++++++++++++++++++----- rpcs3/util/video_sink.h | 14 +++++++------- 3 files changed, 25 insertions(+), 24 deletions(-) diff --git a/rpcs3/Emu/Cell/Modules/cellRec.cpp b/rpcs3/Emu/Cell/Modules/cellRec.cpp index d527065d1f..7c9a5043a1 100644 --- a/rpcs3/Emu/Cell/Modules/cellRec.cpp +++ b/rpcs3/Emu/Cell/Modules/cellRec.cpp @@ -821,12 +821,7 @@ void rec_info::stop_video_provider(bool flush) const usz audio_start_offset = audio_ring_block_count < audio_ringbuffer.size() ? 0 : audio_ring_block_count; const s64 audio_start_pts = audio_ringbuffer.empty() ? 0 : audio_ringbuffer[audio_start_offset % audio_ringbuffer.size()].pts; - cellRec.error("Flushing video ringbuffer: frame_count=%d, video_ringbuffer.size=%d", frame_count, video_ringbuffer.size()); - cellRec.error("Flushing video ringbuffer: block_count=%d, audio_ringbuffer.size=%d", block_count, audio_ringbuffer.size()); - cellRec.error("Flushing video ringbuffer: video_start_pts=%d, audio_start_pts=%d", video_start_pts, audio_start_pts); - // Try to add the frames and samples in proper order - s64 last_pts = -1; for (usz sync_timestamp_us = 0, frame = 0, block = 0; frame < frame_count || block < block_count; frame++) { // Add one frame @@ -854,13 +849,6 @@ void rec_info::stop_video_provider(bool flush) break; } - if (sample_block.pts <= last_pts) - { - cellRec.error("Flushing video ringbuffer: last_pts=%d, sample_block.pts=%d", last_pts, sample_block.pts); - } - - last_pts = sample_block.pts; - encoder->add_audio_samples(sample_block.block.data(), CELL_REC_AUDIO_BLOCK_SAMPLES, channels, timestamp_us); block++; } diff --git a/rpcs3/util/media_utils.cpp b/rpcs3/util/media_utils.cpp index 52f7ec8b1e..afbf91b34c 100644 --- a/rpcs3/util/media_utils.cpp +++ b/rpcs3/util/media_utils.cpp @@ -767,6 +767,11 @@ namespace utils av_log_set_callback([](void* avcl, int level, const char* fmt, va_list vl) -> void { + if (level > av_log_get_level()) + { + return; + } + constexpr int line_size = 1024; char line[line_size]{}; int print_prefix = 1; @@ -777,9 +782,17 @@ namespace utils return; } - media_log.error("av_log: %s", line); // TODO: decrease log level + std::string msg = line; + fmt::trim_back(msg, "\n\r\t "); + + if (level <= AV_LOG_ERROR) + media_log.error("av_log: %s", msg); + else if (level <= AV_LOG_WARNING) + media_log.warning("av_log: %s", msg); + else + media_log.notice("av_log: %s", msg); }); - av_log_set_level(AV_LOG_TRACE); + av_log_set_level(AV_LOG_ERROR); // Reset variables at all costs scoped_av av; @@ -1198,11 +1211,11 @@ namespace utils // We need to skip this frame if it has the same timestamp. if (pts <= last_video_pts) { - media_log.trace("video_encoder: skipping frame. last_pts=%d, pts=%d", last_video_pts, pts); + media_log.trace("video_encoder: skipping frame. last_pts=%d, pts=%d, timestamp_ms=%d", last_video_pts, pts, frame_data.timestamp_ms); } else if (av.video.context) { - media_log.trace("video_encoder: adding new frame. timestamp=%d", frame_data.timestamp_ms); + media_log.trace("video_encoder: adding new frame. timestamp_ms=%d", frame_data.timestamp_ms); if (int err = av_frame_make_writable(av.video.frame); err < 0) { @@ -1289,7 +1302,7 @@ namespace utils // We need to skip this frame if it has the same timestamp. if (pts <= last_audio_pts) { - media_log.error("video_encoder: skipping sample. last_pts=%d, pts=%d", last_audio_pts, pts); + media_log.trace("video_encoder: skipping sample. last_pts=%d, pts=%d, timestamp_us=%d", last_audio_pts, pts, sample_data.timestamp_us); } else if (av.audio.context) { diff --git a/rpcs3/util/video_sink.h b/rpcs3/util/video_sink.h index a7b5f05021..5b33c3b8e5 100644 --- a/rpcs3/util/video_sink.h +++ b/rpcs3/util/video_sink.h @@ -39,25 +39,25 @@ namespace utils s64 get_pts(usz timestamp_ms) const { - return static_cast(std::round((timestamp_ms * m_framerate) / 1000.f)); + return static_cast(std::round((timestamp_ms * m_framerate) / 1000.0)); } s64 get_audio_pts(usz timestamp_us) const { - static constexpr f32 us_per_sec = 1000000.0f; - const f32 us_per_block = us_per_sec / (m_sample_rate / static_cast(m_samples_per_block)); - return static_cast(std::ceil(timestamp_us / us_per_block)); + static constexpr f64 us_per_sec = 1000000.0; + const f64 us_per_block = us_per_sec / (m_sample_rate / static_cast(m_samples_per_block)); + return static_cast(std::round(timestamp_us / us_per_block)); } usz get_timestamp_ms(s64 pts) const { - return static_cast(std::round((pts * 1000) / static_cast(m_framerate))); + return static_cast(std::round((pts * 1000) / static_cast(m_framerate))); } usz get_audio_timestamp_us(s64 pts) const { - static constexpr f32 us_per_sec = 1000000.0f; - const f32 us_per_block = us_per_sec / (m_sample_rate / static_cast(m_samples_per_block)); + static constexpr f64 us_per_sec = 1000000.0; + const f64 us_per_block = us_per_sec / (m_sample_rate / static_cast(m_samples_per_block)); return static_cast(pts * us_per_block); }