From f6bfbbb805916124a9e2290d5e57e1033c0a50ae Mon Sep 17 00:00:00 2001 From: John Preston Date: Sat, 29 Jun 2019 14:24:46 +0200 Subject: [PATCH] Add some profiling logs to lottie player. --- .../chat_helpers/stickers_list_widget.cpp | 2 +- Telegram/SourceFiles/logs.cpp | 5 ++ Telegram/SourceFiles/logs.h | 4 ++ .../lottie/lottie_frame_renderer.cpp | 51 ++++++++++++------ .../lottie/lottie_frame_renderer.h | 9 +++- .../lottie/lottie_multi_player.cpp | 54 +++++++++++++++---- .../lottie/lottie_single_player.cpp | 18 +++++-- 7 files changed, 111 insertions(+), 32 deletions(-) diff --git a/Telegram/SourceFiles/chat_helpers/stickers_list_widget.cpp b/Telegram/SourceFiles/chat_helpers/stickers_list_widget.cpp index 2a0a094dd6..22f212bee3 100644 --- a/Telegram/SourceFiles/chat_helpers/stickers_list_widget.cpp +++ b/Telegram/SourceFiles/chat_helpers/stickers_list_widget.cpp @@ -1383,7 +1383,7 @@ void StickersListWidget::ensureLottiePlayer(Set &set) { set.lottiePlayer->updates( ) | rpl::start_with_next([=] { const auto &sets = shownSets(); - + PROFILE_LOG(("WIDGET REPAINT REQUESTED")); enumerateSections([&](const SectionInfo &info) { if (shownSets()[info.section].lottiePlayer.get() == raw) { update( diff --git a/Telegram/SourceFiles/logs.cpp b/Telegram/SourceFiles/logs.cpp index 3778e69d90..5a3955955a 100644 --- a/Telegram/SourceFiles/logs.cpp +++ b/Telegram/SourceFiles/logs.cpp @@ -319,6 +319,11 @@ bool DebugEnabled() { #endif } +QString ProfilePrefix() { + const auto now = crl::profile(); + return '[' + QString::number(now / 1000., 'f', 3) + "] "; +} + void start(not_null launcher) { Assert(LogsData == nullptr); diff --git a/Telegram/SourceFiles/logs.h b/Telegram/SourceFiles/logs.h index f9279b3bda..14d2d216e4 100644 --- a/Telegram/SourceFiles/logs.h +++ b/Telegram/SourceFiles/logs.h @@ -19,6 +19,8 @@ namespace Logs { void SetDebugEnabled(bool enabled); bool DebugEnabled(); +QString ProfilePrefix(); + void start(not_null launcher); bool started(); void finish(); @@ -71,6 +73,8 @@ inline MemoryBuffer mb(const void *ptr, uint32 size) { #define LOG(msg) (Logs::writeMain(QString msg)) //usage LOG(("log: %1 %2").arg(1).arg(2)) +#define PROFILE_LOG(msg) (Logs::writeMain(Logs::ProfilePrefix() + QString msg)) + #define DEBUG_LOG(msg) {\ if (Logs::DebugEnabled() || !Logs::started()) {\ Logs::writeDebug(SOURCE_FILE_BASENAME, __LINE__, QString msg);\ diff --git a/Telegram/SourceFiles/lottie/lottie_frame_renderer.cpp b/Telegram/SourceFiles/lottie/lottie_frame_renderer.cpp index 760ae48901..95d43c48cc 100644 --- a/Telegram/SourceFiles/lottie/lottie_frame_renderer.cpp +++ b/Telegram/SourceFiles/lottie/lottie_frame_renderer.cpp @@ -10,11 +10,13 @@ https://github.com/telegramdesktop/tdesktop/blob/master/LEGAL #include "lottie/lottie_player.h" #include "lottie/lottie_animation.h" #include "lottie/lottie_cache.h" -#include "rlottie.h" +#include "base/flat_map.h" +#include "logs.h" +#include +#include #include #include -#include namespace Images { QImage prepareColored(QColor add, QImage image); @@ -158,11 +160,30 @@ void FrameRendererObject::remove(not_null entry) { } void FrameRendererObject::generateFrames() { - const auto renderOne = [&](const Entry & entry) { - return entry.state->renderNextFrame(entry.request); + auto players = base::flat_map>(); + const auto renderOne = [&](const Entry &entry) { + const auto result = entry.state->renderNextFrame(entry.request); + if (const auto player = result.notify.get()) { + players.emplace(player, result.notify); + } + return result.rendered; }; - if (ranges::count_if(_entries, renderOne) > 0) { + const auto rendered = ranges::count_if(_entries, renderOne); + if (rendered) { + PROFILE_LOG(("RENDERER: %1, ALL: %2, PLAYERS: %3").arg(rendered).arg(_entries.size()).arg(players.size())); + if (!players.empty()) { + crl::on_main([players = std::move(players)] { + for (const auto &[player, weak] : players) { + if (weak) { + PROFILE_LOG(("RENDERER -- ON MAIN CHECK")); + weak->checkStep(); + } + } + }); + } queueGenerateFrames(); + } else { + PROFILE_LOG(("RENDERER EMPTY")); } } @@ -311,20 +332,21 @@ void SharedState::renderNextFrame( frame->displayed = kTimeUnknown; } -bool SharedState::renderNextFrame(const FrameRequest &request) { - const auto prerender = [&](int index) { +auto SharedState::renderNextFrame(const FrameRequest &request) +-> RenderResult { + const auto prerender = [&](int index) -> RenderResult { const auto frame = getFrame(index); const auto next = getFrame((index + 1) % kFramesCount); if (!IsRendered(frame)) { renderNextFrame(frame, request); - return true; + return { true }; } else if (!IsRendered(next)) { renderNextFrame(next, request); - return true; + return { true }; } - return false; + return { false }; }; - const auto present = [&](int counter, int index) { + const auto present = [&](int counter, int index) -> RenderResult { const auto frame = getFrame(index); if (!IsRendered(frame)) { renderNextFrame(frame, request); @@ -335,10 +357,7 @@ bool SharedState::renderNextFrame(const FrameRequest &request) { _counter.store( (counter + 1) % (2 * kFramesCount), std::memory_order_release); - crl::on_main(_owner, [=] { - _owner->checkStep(); - }); - return true; + return { true, _owner }; }; switch (counter()) { @@ -401,7 +420,7 @@ crl::time SharedState::nextFrameDisplayTime() const { const auto frame = getFrame(index); if (frame->displayed != kTimeUnknown) { // Frame already displayed, but not yet shown. - return kTimeUnknown; + return kFrameDisplayTimeAlreadyDone; } Assert(IsRendered(frame)); Assert(frame->display != kTimeUnknown); diff --git a/Telegram/SourceFiles/lottie/lottie_frame_renderer.h b/Telegram/SourceFiles/lottie/lottie_frame_renderer.h index 79ae0a521c..0d30e07b0b 100644 --- a/Telegram/SourceFiles/lottie/lottie_frame_renderer.h +++ b/Telegram/SourceFiles/lottie/lottie_frame_renderer.h @@ -26,6 +26,8 @@ namespace Lottie { inline constexpr auto kMaxFrameRate = 120; inline constexpr auto kMaxSize = 3096; inline constexpr auto kMaxFramesCount = 600; +inline constexpr auto kFrameDisplayTimeAlreadyDone + = std::numeric_limits::max(); class Player; class Cache; @@ -66,7 +68,12 @@ public: crl::time markFrameShown(); void renderFrame(QImage &image, const FrameRequest &request, int index); - [[nodiscard]] bool renderNextFrame(const FrameRequest &request); + + struct RenderResult { + bool rendered = false; + base::weak_ptr notify; + }; + [[nodiscard]] RenderResult renderNextFrame(const FrameRequest &request); ~SharedState(); diff --git a/Telegram/SourceFiles/lottie/lottie_multi_player.cpp b/Telegram/SourceFiles/lottie/lottie_multi_player.cpp index 03fae88f20..914ba89b11 100644 --- a/Telegram/SourceFiles/lottie/lottie_multi_player.cpp +++ b/Telegram/SourceFiles/lottie/lottie_multi_player.cpp @@ -9,6 +9,7 @@ https://github.com/telegramdesktop/tdesktop/blob/master/LEGAL #include "lottie/lottie_frame_renderer.h" #include "lottie/lottie_animation.h" +#include "logs.h" #include @@ -19,7 +20,8 @@ std::shared_ptr MakeFrameRenderer() { } MultiPlayer::MultiPlayer(std::shared_ptr renderer) -: _renderer(renderer ? std::move(renderer) : FrameRenderer::Instance()) { +: _timer([=] { checkNextFrameRender(); }) +, _renderer(renderer ? std::move(renderer) : FrameRenderer::Instance()) { } MultiPlayer::~MultiPlayer() { @@ -125,7 +127,9 @@ rpl::producer MultiPlayer::updates() const { } void MultiPlayer::checkStep() { - if (_nextFrameTime != kTimeUnknown) { + if (_nextFrameTime == kFrameDisplayTimeAlreadyDone) { + return; + } else if (_nextFrameTime != kTimeUnknown) { checkNextFrameRender(); } else { checkNextFrameAvailability(); @@ -133,6 +137,8 @@ void MultiPlayer::checkStep() { } void MultiPlayer::checkNextFrameAvailability() { + Expects(_nextFrameTime == kTimeUnknown); + if (_active.empty()) { return; } @@ -140,13 +146,25 @@ void MultiPlayer::checkNextFrameAvailability() { for (const auto &[animation, state] : _active) { const auto time = state->nextFrameDisplayTime(); if (time == kTimeUnknown) { + for (const auto &[animation, state] : _active) { + if (state->nextFrameDisplayTime() != kTimeUnknown) { + PROFILE_LOG(("PLAYER -------- SOME READY, BUT NOT ALL")); + break; + } + } return; + } else if (time == kFrameDisplayTimeAlreadyDone) { + continue; } if (next == kTimeUnknown || next > time) { next = time; } } - Assert(next != kTimeUnknown); + if (next == kTimeUnknown) { + PROFILE_LOG(("PLAYER ALL DISPLAYED, WAITING PAINT.")); + return; + } + PROFILE_LOG(("PLAYER NEXT FRAME TIME: %1").arg(next)); _nextFrameTime = next; checkNextFrameRender(); } @@ -157,15 +175,17 @@ void MultiPlayer::checkNextFrameRender() { const auto now = crl::now(); if (now < _nextFrameTime) { if (!_timer.isActive()) { + PROFILE_LOG(("PLAYER TIMER FOR: %1").arg(_nextFrameTime - now)); _timer.callOnce(_nextFrameTime - now); } } else { _timer.cancel(); - const auto exact = std::exchange(_nextFrameTime, kTimeUnknown); + const auto exact = std::exchange( + _nextFrameTime, + kFrameDisplayTimeAlreadyDone); markFrameDisplayed(now, now - exact); _updates.fire({}); - checkStep(); } } @@ -181,23 +201,37 @@ void MultiPlayer::updateFrameRequest( void MultiPlayer::markFrameDisplayed(crl::time now, crl::time delayed) { Expects(!_active.empty()); + auto displayed = 0; + auto waiting = 0; for (const auto &[animation, state] : _active) { const auto time = state->nextFrameDisplayTime(); Assert(time != kTimeUnknown); - if (now >= time) { + if (time == kFrameDisplayTimeAlreadyDone) { + continue; + } else if (now >= time) { + ++displayed; state->markFrameDisplayed(now, delayed); + } else { + ++waiting; } } + PROFILE_LOG(("PLAYER FRAME DISPLAYED AT: %1, DELAYED: %2, (MARKED %3, WAITING %4)").arg(now).arg(delayed).arg(displayed).arg(waiting)); } void MultiPlayer::markFrameShown() { - if (_active.empty()) { - return; + if (_nextFrameTime == kFrameDisplayTimeAlreadyDone) { + _nextFrameTime = kTimeUnknown; } + auto count = 0; for (const auto &[animation, state] : _active) { - state->markFrameShown(); + if (state->markFrameShown() != kTimeUnknown) { + ++count; + } + } + PROFILE_LOG(("PLAYER MARKED SHOWN %1 OF %2").arg(count).arg(_active.size())); + if (count) { + _renderer->frameShown(); } - _renderer->frameShown(); } } // namespace Lottie diff --git a/Telegram/SourceFiles/lottie/lottie_single_player.cpp b/Telegram/SourceFiles/lottie/lottie_single_player.cpp index 7d2edde49f..f91b42e717 100644 --- a/Telegram/SourceFiles/lottie/lottie_single_player.cpp +++ b/Telegram/SourceFiles/lottie/lottie_single_player.cpp @@ -71,7 +71,9 @@ QImage SinglePlayer::frame(const FrameRequest &request) const { } void SinglePlayer::checkStep() { - if (_nextFrameTime != kTimeUnknown) { + if (_nextFrameTime == kFrameDisplayTimeAlreadyDone) { + return; + } else if (_nextFrameTime != kTimeUnknown) { checkNextFrameRender(); } else { checkNextFrameAvailability(); @@ -80,8 +82,10 @@ void SinglePlayer::checkStep() { void SinglePlayer::checkNextFrameAvailability() { Expects(_state != nullptr); + Expects(_nextFrameTime == kTimeUnknown); _nextFrameTime = _state->nextFrameDisplayTime(); + Assert(_nextFrameTime != kFrameDisplayTimeAlreadyDone); if (_nextFrameTime != kTimeUnknown) { checkNextFrameRender(); } @@ -98,7 +102,9 @@ void SinglePlayer::checkNextFrameRender() { } else { _timer.cancel(); - const auto exact = std::exchange(_nextFrameTime, kTimeUnknown); + const auto exact = std::exchange( + _nextFrameTime, + kFrameDisplayTimeAlreadyDone); const auto position = _state->markFrameDisplayed(now, now - exact); _updates.fire({ DisplayFrameRequest{ position } }); } @@ -116,8 +122,12 @@ void SinglePlayer::updateFrameRequest( void SinglePlayer::markFrameShown() { Expects(_state != nullptr); - _state->markFrameShown(); - _renderer->frameShown(); + if (_nextFrameTime == kFrameDisplayTimeAlreadyDone) { + _nextFrameTime = kTimeUnknown; + } + if (_state->markFrameShown() != kTimeUnknown) { + _renderer->frameShown(); + } } } // namespace Lottie