Add ftrace markers

This logs to a tracefs filesystem which can be viewed in tools such as
gpuvis to see precise timings of activities in relation to other trace
markers in X or graphic drivers.

This patch is loosely based on D23114. Though modified with thread
safety, support for string building, and a RAII pattern for durations.
Ultimately that expanded it somewhat.

CMakeLists.txt

@@ -464,6 +464,7 @@ set(kwin_SRCS
     egl_context_attribute_builder.cpp
     events.cpp
     focuschain.cpp
+    ftrace.cpp
     geometrytip.cpp
     gestures.cpp
     globalshortcuts.cpp

autotests/CMakeLists.txt

@@ -388,3 +388,15 @@ target_link_libraries(testVirtualKeyboardDBus
 )
 add_test(NAME kwin-testVirtualKeyboardDBus COMMAND testVirtualKeyboardDBus)
 ecm_mark_as_test(testVirtualKeyboardDBus)
+
+
+########################################################
+# Test FTrace
+########################################################
+add_executable(testFtrace test_ftrace.cpp)
+target_link_libraries(testFtrace
+    Qt5::Test
+    kwin
+)
+add_test(NAME kwin-testFtrace COMMAND testFtrace)
+ecm_mark_as_test(testFtrace)

autotests/test_ftrace.cpp

+/*
+    KWin - the KDE window manager
+    This file is part of the KDE project.
+
+    SPDX-FileCopyrightText: 2021 David Edmundson <davidedmundson@kde.org>
+
+    SPDX-License-Identifier: LGPL-2.0-or-later
+*/
+
+#include <QObject>
+#include <QTemporaryFile>
+#include <QTest>
+
+#include "ftrace.h"
+
+class TestFTrace : public QObject
+{
+    Q_OBJECT
+public:
+    TestFTrace();
+private Q_SLOTS:
+    void benchmarkTraceOff();
+    void benchmarkTraceDurationOff();
+    void enable();
+
+private:
+    QTemporaryFile m_tempFile;
+};
+
+TestFTrace::TestFTrace()
+{
+    m_tempFile.open();
+    qputenv("KWIN_PERF_FTRACE_FILE", m_tempFile.fileName().toLatin1());
+
+    KWin::FTraceLogger::create();
+}
+
+void TestFTrace::benchmarkTraceOff()
+{
+    // this macro should no-op, so take no time at all
+    QBENCHMARK {
+        fTrace("BENCH", 123, "foo");
+    }
+}
+
+void TestFTrace::benchmarkTraceDurationOff()
+{
+    QBENCHMARK {
+        fTraceDuration("BENCH", 123, "foo");
+    }
+}
+
+void TestFTrace::enable()
+{
+    KWin::FTraceLogger::self()->setEnabled(true);
+    QVERIFY(KWin::FTraceLogger::self()->isEnabled());
+
+    {
+        fTrace("TEST", 123, "foo");
+        fTraceDuration("TEST_DURATION", "boo");
+        fTrace("TEST", 123, "foo");
+    }
+
+    QCOMPARE(m_tempFile.readLine(), "TEST123foo\n");
+    QCOMPARE(m_tempFile.readLine(), "TEST_DURATIONboo begin_ctx=1\n");
+    QCOMPARE(m_tempFile.readLine(), "TEST123foo\n");
+    QCOMPARE(m_tempFile.readLine(), "TEST_DURATIONboo end_ctx=1\n");
+}
+
+QTEST_MAIN(TestFTrace)
+
+#include "test_ftrace.moc"

composite.cpp

@@ -13,6 +13,7 @@
 #include "decorations/decoratedclient.h"
 #include "deleted.h"
 #include "effects.h"
+#include "ftrace.h"
 #include "internal_client.h"
 #include "overlaywindow.h"
 #include "platform.h"
@@ -148,6 +149,7 @@ Compositor::Compositor(QObject* workspace)
 
     // register DBus
     new CompositorDBusInterface(this);
+    FTraceLogger::create();
 }
 
 Compositor::~Compositor()
@@ -594,6 +596,8 @@ void Compositor::handleFrameRequested(RenderLoop *renderLoop)
 
     const int screenId = screenForRenderLoop(renderLoop);
 
+    fTraceDuration("Paint (", screens()->name(screenId), ")");
+
     // Create a list of all windows in the stacking order
     QList<Toplevel *> windows = Workspace::self()->xStackingOrder();
     QList<Toplevel *> damaged;

ftrace.cpp

+/*
+    KWin - the KDE window manager
+    This file is part of the KDE project.
+
+    SPDX-FileCopyrightText: 2021 David Edmundson <davidedmundson@kde.org>
+    SPDX-FileCopyrightText: 2020 Roman Gilg <subdiff@gmail.com>
+
+    SPDX-License-Identifier: LGPL-2.0-or-later
+*/
+
+#include "ftrace.h"
+
+#include <QDebug>
+#include <QDir>
+#include <QFile>
+#include <QFileInfo>
+#include <QScopeGuard>
+#include <QTextStream>
+
+#include <QDBusConnection>
+
+namespace KWin
+{
+KWIN_SINGLETON_FACTORY(KWin::FTraceLogger)
+
+FTraceLogger::FTraceLogger(QObject *parent)
+    : QObject(parent)
+{
+    if (qEnvironmentVariableIsSet("KWIN_PERF_FTRACE")) {
+        setEnabled(true);
+    } else {
+        QDBusConnection::sessionBus().registerObject(QStringLiteral("/FTrace"), this, QDBusConnection::ExportScriptableContents);
+    }
+}
+
+bool FTraceLogger::isEnabled()
+{
+    return m_file.isOpen();
+}
+
+void FTraceLogger::setEnabled(bool enabled)
+{
+    QMutexLocker lock(&m_mutex);
+    if (enabled == isEnabled()) {
+        return;
+    }
+
+    if (enabled) {
+        open();
+    } else {
+        m_file.close();
+    }
+    emit enabledChanged();
+}
+
+bool FTraceLogger::open()
+{
+    const QString path = filePath();
+    if (path.isEmpty()) {
+        return false;
+    }
+
+    m_file.setFileName(path);
+    if (!m_file.open(QIODevice::WriteOnly)) {
+        qWarning() << "No access to trace marker file at:" << path;
+    }
+    return true;
+}
+
+QString FTraceLogger::filePath()
+{
+    if (qEnvironmentVariableIsSet("KWIN_PERF_FTRACE_FILE")) {
+        return qgetenv("KWIN_PERF_FTRACE_FILE");
+    }
+
+    QFile mountsFile("/proc/mounts");
+    if (!mountsFile.open(QIODevice::ReadOnly | QIODevice::Text)) {
+        qWarning() << "No access to mounts file. Can not determine trace marker file location.";
+        return QString();
+    }
+
+    auto lineInfo = [](const QString &line) {
+        const int start = line.indexOf(' ') + 1;
+        const int end = line.indexOf(' ', start);
+        const QString dirPath(line.mid(start, end - start));
+        if (dirPath.isEmpty() || !QFileInfo(dirPath).exists()) {
+            return QFileInfo();
+        }
+        return QFileInfo(QDir(dirPath), QStringLiteral("trace_marker"));
+    };
+    QFileInfo markerFileInfo;
+    QTextStream mountsIn(&mountsFile);
+    QString mountsLine = mountsIn.readLine();
+
+    while (!mountsLine.isNull()) {
+        if (mountsLine.startsWith("tracefs")) {
+            const auto info = lineInfo(mountsLine);
+            if (info.exists()) {
+                markerFileInfo = info;
+                break;
+            }
+        }
+        if (mountsLine.startsWith("debugfs")) {
+            markerFileInfo = lineInfo(mountsLine);
+        }
+        mountsLine = mountsIn.readLine();
+    }
+    mountsFile.close();
+    if (!markerFileInfo.exists()) {
+        qWarning() << "Could not determine trace marker file location from mounts.";
+        return QString();
+    }
+
+    return markerFileInfo.absoluteFilePath();
+}
+
+FTraceDuration::~FTraceDuration()
+{
+    FTraceLogger::self()->trace(m_message, " end_ctx=", m_context);
+}
+
+}

ftrace.h

+/*
+    KWin - the KDE window manager
+    This file is part of the KDE project.
+
+    SPDX-FileCopyrightText: 2021 David Edmundson <davidedmundson@kde.org>
+
+    SPDX-License-Identifier: LGPL-2.0-or-later
+*/
+
+#pragma once
+
+#include <QFile>
+#include <QMutex>
+#include <QMutexLocker>
+#include <QObject>
+#include <QTextStream>
+
+#include <kwinglobals.h>
+
+namespace KWin
+{
+/**
+ * FTraceLogger is a singleton utility for writing log messages using ftrace
+ *
+ * Usage: Either:
+ *  Set the KWIN_PERF_FTRACE environment variable before starting the application
+ *  Calling on DBus /FTrace org.kde.kwin.FTrace.setEnabled true
+ * After having created the ftrace mount
+ */
+class KWIN_EXPORT FTraceLogger : public QObject
+{
+    Q_OBJECT
+    Q_CLASSINFO("D-Bus Interface", "org.kde.kwin.FTrace");
+    Q_PROPERTY(bool isEnabled READ isEnabled NOTIFY enabledChanged)
+public:
+    ~FTraceLogger() = default;
+
+    /**
+     * Enabled through DBus and logging has started
+     */
+    bool isEnabled();
+
+    /**
+     * Main log function
+     * Takes any number of arguments that can be written into QTextStream
+     */
+    template<typename... Args> void trace(Args... args)
+    {
+        Q_ASSERT(isEnabled());
+        QMutexLocker lock(&m_mutex);
+        if (!m_file.isOpen()) {
+            return;
+        }
+        QTextStream stream(&m_file);
+        (stream << ... << args) << Qt::endl;
+    }
+
+Q_SIGNALS:
+    void enabledChanged();
+
+public Q_SLOTS:
+    Q_SCRIPTABLE void setEnabled(bool enabled);
+
+private:
+    static QString filePath();
+    bool open();
+    QFile m_file;
+    QMutex m_mutex;
+    KWIN_SINGLETON(FTraceLogger)
+};
+
+class KWIN_EXPORT FTraceDuration
+{
+public:
+    template<typename... Args> FTraceDuration(Args... args)
+    {
+        static QAtomicInteger<qulonglong> s_context = 0;
+        QTextStream stream(&m_message);
+        (stream << ... << args);
+        stream.flush();
+        m_context = ++s_context;
+        FTraceLogger::self()->trace(m_message, " begin_ctx=", m_context);
+    }
+
+    ~FTraceDuration();
+
+private:
+    QByteArray m_message;
+    qulonglong m_context;
+};
+
+} // namespace KWin
+
+/**
+ * Optimised macro, arguments are only copied if tracing is enabled
+ */
+#define fTrace(...)                                                                                                                                            \
+    if (KWin::FTraceLogger::self()->isEnabled())                                                                                                               \
+        KWin::FTraceLogger::self()->trace(__VA_ARGS__);
+
+/**
+ * Will insert two markers into the log. Once when called, and the second at the end of the relevant block
+ * In GPUVis this will appear as a timed block with begin_ctx and end_ctx markers
+ */
+#define fTraceDuration(...)                                                                                                                                    \
+    QScopedPointer<KWin::FTraceDuration> _duration(KWin::FTraceLogger::self()->isEnabled() ? new KWin::FTraceDuration(__VA_ARGS__) : nullptr);