From a169114fee661e61519f06c0567f4daa486dc336 Mon Sep 17 00:00:00 2001 From: Xaver Hugl Date: Wed, 1 May 2024 00:01:59 +0200 Subject: [PATCH] core/renderloop: log frame statistics into a file Data like target vs. actual pageflip time, and render times is often needed for debugging or optimizing render time predictions, so this commit makes KWin print that information to a file in the home directory whenever KWIN_LOG_PERFORMANCE_DATA is set. CCBUG: 488843 --- src/core/renderbackend.cpp | 15 ++++++++++----- src/core/renderbackend.h | 7 ++++--- src/core/renderloop.cpp | 20 ++++++++++++++++++-- src/core/renderloop_p.h | 6 +++++- 4 files changed, 37 insertions(+), 11 deletions(-) diff --git a/src/core/renderbackend.cpp b/src/core/renderbackend.cpp index 5ffa536fda..07ee030dbd 100644 --- a/src/core/renderbackend.cpp +++ b/src/core/renderbackend.cpp @@ -64,10 +64,10 @@ void OutputFrame::addFeedback(std::unique_ptr &&feedback) m_feedbacks.push_back(std::move(feedback)); } -std::optional OutputFrame::queryRenderTime() const +std::optional OutputFrame::queryRenderTime() const { if (m_renderTimeQueries.empty()) { - return std::chrono::nanoseconds::zero(); + return RenderTimeSpan{}; } const auto first = m_renderTimeQueries.front()->query(); if (!first) { @@ -81,14 +81,14 @@ std::optional OutputFrame::queryRenderTime() const } ret = ret | *opt; } - return ret.end - ret.start; + return ret; } void OutputFrame::presented(std::chrono::nanoseconds timestamp, PresentationMode mode) { - std::optional renderTime = queryRenderTime(); + const auto renderTime = queryRenderTime(); if (m_loop) { - RenderLoopPrivate::get(m_loop)->notifyFrameCompleted(timestamp, renderTime, mode); + RenderLoopPrivate::get(m_loop)->notifyFrameCompleted(timestamp, renderTime, mode, this); } m_presented = true; for (const auto &feedback : m_feedbacks) { @@ -136,6 +136,11 @@ std::chrono::steady_clock::time_point OutputFrame::targetPageflipTime() const return m_targetPageflipTime; } +std::chrono::nanoseconds OutputFrame::refreshDuration() const +{ + return m_refreshDuration; +} + RenderBackend::RenderBackend(QObject *parent) : QObject(parent) { diff --git a/src/core/renderbackend.h b/src/core/renderbackend.h index cb8c0e72af..a5745fe155 100644 --- a/src/core/renderbackend.h +++ b/src/core/renderbackend.h @@ -42,8 +42,8 @@ public: struct RenderTimeSpan { - std::chrono::steady_clock::time_point start; - std::chrono::steady_clock::time_point end; + std::chrono::steady_clock::time_point start = std::chrono::steady_clock::time_point{std::chrono::nanoseconds::zero()}; + std::chrono::steady_clock::time_point end = std::chrono::steady_clock::time_point{std::chrono::nanoseconds::zero()}; RenderTimeSpan operator|(const RenderTimeSpan &other) const; }; @@ -93,9 +93,10 @@ public: void addRenderTimeQuery(std::unique_ptr &&query); std::chrono::steady_clock::time_point targetPageflipTime() const; + std::chrono::nanoseconds refreshDuration() const; private: - std::optional queryRenderTime() const; + std::optional queryRenderTime() const; const QPointer m_loop; const std::chrono::nanoseconds m_refreshDuration; diff --git a/src/core/renderloop.cpp b/src/core/renderloop.cpp index be590e7396..b871a3c78d 100644 --- a/src/core/renderloop.cpp +++ b/src/core/renderloop.cpp @@ -12,6 +12,8 @@ #include "window.h" #include "workspace.h" +#include + using namespace std::chrono_literals; namespace KWin @@ -22,6 +24,8 @@ RenderLoopPrivate *RenderLoopPrivate::get(RenderLoop *loop) return loop->d.get(); } +static const bool s_printDebugInfo = qEnvironmentVariableIntValue("KWIN_LOG_PERFORMANCE_DATA") != 0; + RenderLoopPrivate::RenderLoopPrivate(RenderLoop *q, Output *output) : q(q) , output(output) @@ -85,15 +89,27 @@ void RenderLoopPrivate::notifyFrameDropped() } } -void RenderLoopPrivate::notifyFrameCompleted(std::chrono::nanoseconds timestamp, std::optional renderTime, PresentationMode mode) +void RenderLoopPrivate::notifyFrameCompleted(std::chrono::nanoseconds timestamp, std::optional renderTime, PresentationMode mode, OutputFrame *frame) { + if (output && s_printDebugInfo && !m_debugOutput) { + m_debugOutput = std::fstream(qPrintable("kwin perf statistics " + output->name() + ".csv"), std::ios::out); + *m_debugOutput << "target pageflip timestamp,pageflip timestamp,render start,render end,safety margin,refresh duration,vrr,tearing\n"; + } + if (m_debugOutput) { + auto times = renderTime.value_or(RenderTimeSpan{}); + const bool vrr = mode == PresentationMode::AdaptiveSync || mode == PresentationMode::AdaptiveAsync; + const bool tearing = mode == PresentationMode::Async || mode == PresentationMode::AdaptiveAsync; + *m_debugOutput << frame->targetPageflipTime().time_since_epoch().count() << "," << timestamp.count() << "," << times.start.time_since_epoch().count() << "," << times.end.time_since_epoch().count() + << "," << safetyMargin.count() << "," << frame->refreshDuration().count() << "," << (vrr ? 1 : 0) << "," << (tearing ? 1 : 0) << "\n"; + } + Q_ASSERT(pendingFrameCount > 0); pendingFrameCount--; notifyVblank(timestamp); if (renderTime) { - renderJournal.add(*renderTime, timestamp); + renderJournal.add(renderTime->end - renderTime->start, timestamp); } if (compositeTimer.isActive()) { // reschedule to match the new timestamp and render time diff --git a/src/core/renderloop_p.h b/src/core/renderloop_p.h index 7e9a4148fb..dba8a69e44 100644 --- a/src/core/renderloop_p.h +++ b/src/core/renderloop_p.h @@ -6,17 +6,20 @@ #pragma once +#include "renderbackend.h" #include "renderjournal.h" #include "renderloop.h" #include +#include #include namespace KWin { class SurfaceItem; +class OutputFrame; class KWIN_EXPORT RenderLoopPrivate { @@ -32,11 +35,12 @@ public: void scheduleRepaint(std::chrono::nanoseconds lastTargetTimestamp); void notifyFrameDropped(); - void notifyFrameCompleted(std::chrono::nanoseconds timestamp, std::optional renderTime, PresentationMode mode = PresentationMode::VSync); + void notifyFrameCompleted(std::chrono::nanoseconds timestamp, std::optional renderTime, PresentationMode mode, OutputFrame *frame); void notifyVblank(std::chrono::nanoseconds timestamp); RenderLoop *const q; Output *const output; + std::optional m_debugOutput; std::chrono::nanoseconds lastPresentationTimestamp = std::chrono::nanoseconds::zero(); std::chrono::nanoseconds nextPresentationTimestamp = std::chrono::nanoseconds::zero(); QTimer compositeTimer;