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

@@ -64,10 +64,10 @@ void OutputFrame::addFeedback(std::unique_ptr<PresentationFeedback> &&feedback)
     m_feedbacks.push_back(std::move(feedback));
 }
 
-std::optional<std::chrono::nanoseconds> OutputFrame::queryRenderTime() const
+std::optional<RenderTimeSpan> 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<std::chrono::nanoseconds> OutputFrame::queryRenderTime() const
         }
         ret = ret | *opt;
     }
-    return ret.end - ret.start;
+    return ret;
 }
 
 void OutputFrame::presented(std::chrono::nanoseconds timestamp, PresentationMode mode)
 {
-    std::optional<std::chrono::nanoseconds> 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)
 {

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<RenderTimeQuery> &&query);
 
     std::chrono::steady_clock::time_point targetPageflipTime() const;
+    std::chrono::nanoseconds refreshDuration() const;
 
 private:
-    std::optional<std::chrono::nanoseconds> queryRenderTime() const;
+    std::optional<RenderTimeSpan> queryRenderTime() const;
 
     const QPointer<RenderLoop> m_loop;
     const std::chrono::nanoseconds m_refreshDuration;

src/core/renderloop.cpp

@@ -12,6 +12,8 @@
 #include "window.h"
 #include "workspace.h"
 
+#include <filesystem>
+
 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<std::chrono::nanoseconds> renderTime, PresentationMode mode)
+void RenderLoopPrivate::notifyFrameCompleted(std::chrono::nanoseconds timestamp, std::optional<RenderTimeSpan> 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

src/core/renderloop_p.h

@@ -6,17 +6,20 @@
 
 #pragma once
 
+#include "renderbackend.h"
 #include "renderjournal.h"
 #include "renderloop.h"
 
 #include <QTimer>
 
+#include <fstream>
 #include <optional>
 
 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<std::chrono::nanoseconds> renderTime, PresentationMode mode = PresentationMode::VSync);
+    void notifyFrameCompleted(std::chrono::nanoseconds timestamp, std::optional<RenderTimeSpan> renderTime, PresentationMode mode, OutputFrame *frame);
     void notifyVblank(std::chrono::nanoseconds timestamp);
 
     RenderLoop *const q;
     Output *const output;
+    std::optional<std::fstream> m_debugOutput;
     std::chrono::nanoseconds lastPresentationTimestamp = std::chrono::nanoseconds::zero();
     std::chrono::nanoseconds nextPresentationTimestamp = std::chrono::nanoseconds::zero();
     QTimer compositeTimer;