From 63740e68e3b64728c0b6b7e153e38c0973f689b0 Mon Sep 17 00:00:00 2001 From: Mikhail Pozdnyakov Date: Tue, 11 Jun 2019 12:46:36 +0300 Subject: [core] Log renderer performance metrics --- src/mbgl/renderer/renderer.cpp | 3 +- src/mbgl/renderer/renderer_impl.cpp | 84 ++++++++++++++++++++++++++++++++++++- src/mbgl/renderer/renderer_impl.hpp | 2 +- 3 files changed, 86 insertions(+), 3 deletions(-) diff --git a/src/mbgl/renderer/renderer.cpp b/src/mbgl/renderer/renderer.cpp index 5afbbbd47e..5e92bd4b79 100644 --- a/src/mbgl/renderer/renderer.cpp +++ b/src/mbgl/renderer/renderer.cpp @@ -27,9 +27,10 @@ void Renderer::setObserver(RendererObserver* observer) { void Renderer::render(const std::shared_ptr& updateParameters) { assert(updateParameters); + auto frame_start = Clock::now(); if (auto renderTree = impl->orchestrator.createRenderTree(updateParameters)) { renderTree->prepare(); - impl->render(*renderTree); + impl->render(*renderTree, frame_start); } } diff --git a/src/mbgl/renderer/renderer_impl.cpp b/src/mbgl/renderer/renderer_impl.cpp index 113840d059..6dbc440ef6 100644 --- a/src/mbgl/renderer/renderer_impl.cpp +++ b/src/mbgl/renderer/renderer_impl.cpp @@ -24,6 +24,23 @@ static RendererObserver& nullObserver() { return observer; } +namespace { + +struct { + double totalTime = 0.0; + double orchestrationTime = 0.0; + double orchestrationTimePeak = 0.0; + double orchestrationPercentagePeak = 0.0; + double uploadTime = 0.0; + double uploadTimePeak = 0.0; + double uploadPercentagePeak = 0.0; + std::size_t failedFrames = 0u; + std::size_t totalFrames = 0u; + std::size_t framesSavedWithBackgroundOrchestration = 0u; +} stats; + +} // namespace + Renderer::Impl::Impl(gfx::RendererBackend& backend_, float pixelRatio_, optional localFontFamily_) @@ -35,6 +52,27 @@ Renderer::Impl::Impl(gfx::RendererBackend& backend_, } Renderer::Impl::~Impl() { + Log::Warning(Event::General, + "Overall stats: orchestration took %f ms from %f ms of the total rendering time (%f%%)", + stats.orchestrationTime, + stats.totalTime, + stats.orchestrationTime / stats.totalTime * 100.0); + Log::Warning(Event::General, + "Overall stats: orchestration peak value: %f ms, orchestration peak frame time percentage: %f", + stats.orchestrationTimePeak, + stats.orchestrationPercentagePeak); + Log::Warning(Event::General, + "Overall stats: upload peak value: %f ms, upload peak frame time percentage: %f", + stats.uploadTimePeak, + stats.uploadPercentagePeak); + Log::Warning(Event::General, + "Overall stats: %zu frames out of %zu took > 16.7 ms (%f%%), %zu of them took too long because of " + "orchestration (%f%%)", + stats.failedFrames, + stats.totalFrames, + double(stats.failedFrames) / stats.totalFrames * 100.0, + stats.framesSavedWithBackgroundOrchestration, + double(stats.framesSavedWithBackgroundOrchestration) / stats.failedFrames * 100.0); assert(gfx::BackendScope::exists()); }; @@ -42,7 +80,8 @@ void Renderer::Impl::setObserver(RendererObserver* observer_) { observer = observer_ ? observer_ : &nullObserver(); } -void Renderer::Impl::render(const RenderTree& renderTree) { +void Renderer::Impl::render(const RenderTree& renderTree, TimePoint frame_start) { + auto render_start = Clock::now(); if (renderState == RenderState::Never) { observer->onWillStartRenderingMap(); } @@ -79,6 +118,8 @@ void Renderer::Impl::render(const RenderTree& renderTree) { const auto& sourceRenderItems = renderTree.getSourceRenderItems(); const auto& layerRenderItems = renderTree.getLayerRenderItems(); + auto upload_start = Clock::now(); + // - UPLOAD PASS ------------------------------------------------------------------------------- // Uploads all required buffers and images before we do any actual rendering. { @@ -95,6 +136,7 @@ void Renderer::Impl::render(const RenderTree& renderTree) { renderTree.getLineAtlas().upload(*uploadPass); renderTree.getPatternAtlas().upload(*uploadPass); } + auto upload_end = Clock::now(); // - 3D PASS ------------------------------------------------------------------------------------- // Renders any 3D layers bottom-to-top to unique FBOs with texture attachments, but share the same @@ -220,6 +262,46 @@ void Renderer::Impl::render(const RenderTree& renderTree) { renderState = RenderState::Fully; observer->onDidFinishRenderingMap(); } + + auto frame_end = Clock::now(); + std::chrono::duration frameDuration = frame_end - frame_start; + std::chrono::duration orchDuration = render_start - frame_start; + std::chrono::duration renderDuration = frame_end - render_start; + std::chrono::duration uploadDuration = upload_end - upload_start; + + stats.totalTime += frameDuration.count(); + stats.orchestrationTime += orchDuration.count(); + + double orchestrationPercentage = orchDuration.count() / frameDuration.count() * 100.0; + double uploadPercentage = uploadDuration.count() / frameDuration.count() * 100.0; + + if (stats.orchestrationTimePeak < orchDuration.count()) { + stats.orchestrationTimePeak = orchDuration.count(); + } + if (stats.orchestrationPercentagePeak < orchestrationPercentage) { + stats.orchestrationPercentagePeak = orchestrationPercentage; + } + if (stats.uploadTimePeak < uploadDuration.count()) { + stats.uploadTimePeak = uploadDuration.count(); + } + if (stats.uploadPercentagePeak < uploadPercentage) { + stats.uploadPercentagePeak = uploadPercentage; + } + + constexpr double kMaxFrameDuration = 16.7; // 60 fps + stats.totalFrames++; + if (frameDuration.count() > kMaxFrameDuration) { + stats.failedFrames++; + Log::Warning(Event::General, + "Failed frame stats: total: %f ms, orchestration %f ms, rendering %f ms, upload %f ms", + frameDuration.count(), + orchDuration.count(), + renderDuration.count(), + uploadDuration.count()); + if (frameDuration.count() - orchDuration.count() <= kMaxFrameDuration) { + stats.framesSavedWithBackgroundOrchestration++; + } + } } void Renderer::Impl::reduceMemoryUse() { diff --git a/src/mbgl/renderer/renderer_impl.hpp b/src/mbgl/renderer/renderer_impl.hpp index 5f04bfdfed..5dfa8532c7 100644 --- a/src/mbgl/renderer/renderer_impl.hpp +++ b/src/mbgl/renderer/renderer_impl.hpp @@ -27,7 +27,7 @@ private: void setObserver(RendererObserver*); - void render(const RenderTree&); + void render(const RenderTree&, TimePoint frame_start); void reduceMemoryUse(); -- cgit v1.2.1