From 85d04cf60d5203cf08a8d11fcca4d727f647b5cc Mon Sep 17 00:00:00 2001 From: David Edmundson Date: Mon, 7 Sep 2020 09:11:47 +0100 Subject: [PATCH] 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 | 1 + autotests/CMakeLists.txt | 12 ++++ autotests/test_ftrace.cpp | 72 ++++++++++++++++++++++ composite.cpp | 4 ++ ftrace.cpp | 122 ++++++++++++++++++++++++++++++++++++++ ftrace.h | 106 +++++++++++++++++++++++++++++++++ 6 files changed, 317 insertions(+) create mode 100644 autotests/test_ftrace.cpp create mode 100644 ftrace.cpp create mode 100644 ftrace.h diff --git a/CMakeLists.txt b/CMakeLists.txt index 5087803c91..c299347a56 100644 --- a/CMakeLists.txt +++ b/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 diff --git a/autotests/CMakeLists.txt b/autotests/CMakeLists.txt index b75c5b8954..7035114709 100644 --- a/autotests/CMakeLists.txt +++ b/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) diff --git a/autotests/test_ftrace.cpp b/autotests/test_ftrace.cpp new file mode 100644 index 0000000000..d460e4b2a9 --- /dev/null +++ b/autotests/test_ftrace.cpp @@ -0,0 +1,72 @@ +/* + KWin - the KDE window manager + This file is part of the KDE project. + + SPDX-FileCopyrightText: 2021 David Edmundson + + SPDX-License-Identifier: LGPL-2.0-or-later +*/ + +#include +#include +#include + +#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" diff --git a/composite.cpp b/composite.cpp index c0a433f656..03edaf731a 100644 --- a/composite.cpp +++ b/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 windows = Workspace::self()->xStackingOrder(); QList damaged; diff --git a/ftrace.cpp b/ftrace.cpp new file mode 100644 index 0000000000..3bf7f35625 --- /dev/null +++ b/ftrace.cpp @@ -0,0 +1,122 @@ +/* + KWin - the KDE window manager + This file is part of the KDE project. + + SPDX-FileCopyrightText: 2021 David Edmundson + SPDX-FileCopyrightText: 2020 Roman Gilg + + SPDX-License-Identifier: LGPL-2.0-or-later +*/ + +#include "ftrace.h" + +#include +#include +#include +#include +#include +#include + +#include + +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); +} + +} diff --git a/ftrace.h b/ftrace.h new file mode 100644 index 0000000000..743a8ba20c --- /dev/null +++ b/ftrace.h @@ -0,0 +1,106 @@ +/* + KWin - the KDE window manager + This file is part of the KDE project. + + SPDX-FileCopyrightText: 2021 David Edmundson + + SPDX-License-Identifier: LGPL-2.0-or-later +*/ + +#pragma once + +#include +#include +#include +#include +#include + +#include + +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 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 FTraceDuration(Args... args) + { + static QAtomicInteger 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 _duration(KWin::FTraceLogger::self()->isEnabled() ? new KWin::FTraceDuration(__VA_ARGS__) : nullptr);