Add some profiling logs to lottie player.

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(

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<Core::Launcher*> launcher) {
 	Assert(LogsData == nullptr);
 

Telegram/SourceFiles/logs.h

@@ -19,6 +19,8 @@ namespace Logs {
 void SetDebugEnabled(bool enabled);
 bool DebugEnabled();
 
+QString ProfilePrefix();
+
 void start(not_null<Core::Launcher*> 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);\

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 <QPainter>
+#include <rlottie.h>
 #include <range/v3/algorithm/find.hpp>
 #include <range/v3/algorithm/count_if.hpp>
-#include <QPainter>
 
 namespace Images {
 QImage prepareColored(QColor add, QImage image);
@@ -158,11 +160,30 @@ void FrameRendererObject::remove(not_null<SharedState*> entry) {
 }
 
 void FrameRendererObject::generateFrames() {
-	const auto renderOne = [&](const Entry & entry) {
-		return entry.state->renderNextFrame(entry.request);
+	auto players = base::flat_map<Player*, base::weak_ptr<Player>>();
+	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);

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<crl::time>::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<Player> notify;
+	};
+	[[nodiscard]] RenderResult renderNextFrame(const FrameRequest &request);
 
 	~SharedState();
 

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 <range/v3/algorithm/remove.hpp>
 
@@ -19,7 +20,8 @@ std::shared_ptr<FrameRenderer> MakeFrameRenderer() {
 }
 
 MultiPlayer::MultiPlayer(std::shared_ptr<FrameRenderer> 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<MultiUpdate> 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

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