[calligra/calligra/2.9] krita: Added built-in performance logging into Krita
Dmitry Kazakov
dimula73 at gmail.com
Tue May 26 15:56:06 UTC 2015
Git commit 9ccc6c018a5548fe53597acef2a1d6f50a21dbd1 by Dmitry Kazakov.
Committed on 26/05/2015 at 15:55.
Pushed by dkazakov into branch 'calligra/2.9'.
Added built-in performance logging into Krita
Brief instructions:
1) Add 'enablePerfLog=true' into your kritarc
2) Start/restart Krita to enable it
3) Choose your problematic image/preset
4) Do as many strokes as you can. Of different speed and size
5) You will get './log/' folder where the preset and the log are stored
6) Run krita/sdk/plot_strokes_statistics to visualize the data
Still TODO:
1) Measure how much time is spent on openGL loading and updating part
of pipeline.
2) Write a detailed manual for users about how to generate this log
3) Dump some hardware info, like CPU, GPU, dirver version and so on.
CCMAIL:kimageshop at kde.org
M +1 -0 krita/image/CMakeLists.txt
M +6 -0 krita/image/kis_image.cc
M +5 -0 krita/image/kis_image_config.cpp
M +1 -0 krita/image/kis_image_config.h
A +252 -0 krita/image/kis_update_time_monitor.cpp [License: GPL (v2+)]
A +56 -0 krita/image/kis_update_time_monitor.h [License: GPL (v2+)]
M +28 -0 krita/image/tests/kis_update_scheduler_test.cpp
M +2 -0 krita/image/tests/kis_update_scheduler_test.h
A +31 -0 krita/sdk/plot_strokes_statistics
M +4 -0 krita/ui/tool/kis_tool_freehand_helper.cpp
M +13 -1 krita/ui/tool/strokes/freehand_stroke.cpp
M +2 -0 krita/ui/tool/strokes/freehand_stroke.h
http://commits.kde.org/calligra/9ccc6c018a5548fe53597acef2a1d6f50a21dbd1
diff --git a/krita/image/CMakeLists.txt b/krita/image/CMakeLists.txt
index c0227ec..a351780 100644
--- a/krita/image/CMakeLists.txt
+++ b/krita/image/CMakeLists.txt
@@ -162,6 +162,7 @@ set(kritaimage_LIB_SRCS
kis_update_scheduler.cpp
kis_queues_progress_updater.cpp
kis_composite_progress_proxy.cpp
+ kis_update_time_monitor.cpp
kis_group_layer.cc
kis_count_visitor.cpp
kis_histogram.cc
diff --git a/krita/image/kis_image.cc b/krita/image/kis_image.cc
index 00338c9..35ecf9d 100644
--- a/krita/image/kis_image.cc
+++ b/krita/image/kis_image.cc
@@ -81,6 +81,8 @@
#include "kis_layer_projection_plane.h"
+#include "kis_update_time_monitor.h"
+
// #define SANITY_CHECKS
@@ -1343,6 +1345,8 @@ KisNodeSP KisImage::isolatedModeRoot() const
void KisImage::addJob(KisStrokeId id, KisStrokeJobData *data)
{
+ KisUpdateTimeMonitor::instance()->reportJobStarted(data);
+
if (m_d->scheduler) {
m_d->scheduler->addJob(id, data);
}
@@ -1472,6 +1476,8 @@ void KisImage::enableUIUpdates()
void KisImage::notifyProjectionUpdated(const QRect &rc)
{
+ KisUpdateTimeMonitor::instance()->reportUpdateFinished(rc);
+
if (!m_d->disableUIUpdateSignals) {
emit sigImageUpdated(rc);
}
diff --git a/krita/image/kis_image_config.cpp b/krita/image/kis_image_config.cpp
index 3c32449..7d9c378 100644
--- a/krita/image/kis_image_config.cpp
+++ b/krita/image/kis_image_config.cpp
@@ -42,6 +42,11 @@ KisImageConfig::~KisImageConfig()
m_config.sync();
}
+bool KisImageConfig::enablePerfLog() const
+{
+ return m_config.readEntry("enablePerfLog", false);
+}
+
qreal KisImageConfig::transformMaskOffBoundsReadArea() const
{
return m_config.readEntry("transformMaskOffBoundsReadArea", 0.5);
diff --git a/krita/image/kis_image_config.h b/krita/image/kis_image_config.h
index f228d7a..dd595c9 100644
--- a/krita/image/kis_image_config.h
+++ b/krita/image/kis_image_config.h
@@ -29,6 +29,7 @@ public:
KisImageConfig();
~KisImageConfig();
+ bool enablePerfLog() const;
qreal transformMaskOffBoundsReadArea() const;
int updatePatchHeight() const;
diff --git a/krita/image/kis_update_time_monitor.cpp b/krita/image/kis_update_time_monitor.cpp
new file mode 100644
index 0000000..384be68
--- /dev/null
+++ b/krita/image/kis_update_time_monitor.cpp
@@ -0,0 +1,252 @@
+/*
+ * Copyright (c) 2011 Dmitry Kazakov <dimula73 at gmail.com>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ */
+
+#include "kis_update_time_monitor.h"
+
+#include <kglobal.h>
+#include <QHash>
+#include <QSet>
+#include <QMutex>
+#include <QMutexLocker>
+#include <QPointF>
+#include <QRect>
+#include <QRegion>
+#include <QFile>
+#include <QDir>
+
+#include <QElapsedTimer>
+#include <QFileInfo>
+
+#include "kis_debug.h"
+#include "kis_global.h"
+#include "kis_image_config.h"
+
+
+#include "kis_paintop_preset.h"
+
+
+struct StrokeTicket
+{
+ StrokeTicket() : m_jobTime(0), m_updateTime(0) {}
+
+ QRegion dirtyRegion;
+
+ void start() {
+ m_timer.start();
+ }
+
+ void jobCompleted() {
+ m_jobTime = m_timer.restart();
+ }
+
+ void updateCompleted() {
+ m_updateTime = m_timer.restart();
+ }
+
+ qint64 jobTime() const {
+ return m_jobTime;
+ }
+
+ qint64 updateTime() const {
+ return m_updateTime;
+ }
+
+private:
+ QElapsedTimer m_timer;
+ qint64 m_jobTime;
+ qint64 m_updateTime;
+};
+
+struct KisUpdateTimeMonitor::Private
+{
+ Private()
+ : jobsTime(0),
+ responseTime(0),
+ numTickets(0),
+ numUpdates(0),
+ mousePath(0.0),
+ loggingEnabled(false)
+ {
+ loggingEnabled = KisImageConfig().enablePerfLog();
+ }
+
+ QHash<void*, StrokeTicket*> preliminaryTickets;
+ QSet<StrokeTicket*> finishedTickets;
+
+ qint64 jobsTime;
+ qint64 responseTime;
+ qint32 numTickets;
+ qint32 numUpdates;
+ QMutex mutex;
+
+ qreal mousePath;
+ QPointF lastMousePos;
+
+ QElapsedTimer strokeTime;
+ KisPaintOpPresetSP preset;
+
+ bool loggingEnabled;
+};
+
+KisUpdateTimeMonitor::KisUpdateTimeMonitor()
+ : m_d(new Private)
+{
+ if (m_d->loggingEnabled) {
+ QDir dir;
+ if (dir.exists("log")) {
+ dir.remove("log");
+ }
+ dir.mkdir("log");
+ }
+}
+
+KisUpdateTimeMonitor::~KisUpdateTimeMonitor()
+{
+ delete m_d;
+}
+
+KisUpdateTimeMonitor* KisUpdateTimeMonitor::instance()
+{
+ K_GLOBAL_STATIC(KisUpdateTimeMonitor, s_instance);
+ return s_instance;
+}
+
+void KisUpdateTimeMonitor::startStrokeMeasure()
+{
+ if (!m_d->loggingEnabled) return;
+
+ QMutexLocker locker(&m_d->mutex);
+
+ m_d->jobsTime = 0;
+ m_d->responseTime = 0;
+ m_d->numTickets = 0;
+ m_d->numUpdates = 0;
+ m_d->mousePath = 0;
+
+ m_d->lastMousePos = QPointF();
+ m_d->preset = 0;
+
+ m_d->strokeTime.start();
+}
+
+void KisUpdateTimeMonitor::endStrokeMeasure()
+{
+ if (!m_d->loggingEnabled) return;
+
+ QMutexLocker locker(&m_d->mutex);
+
+ if(m_d->numTickets) {
+ printValues();
+ }
+}
+
+void KisUpdateTimeMonitor::reportPaintOpPreset(KisPaintOpPresetSP preset)
+{
+ if (!m_d->loggingEnabled) return;
+
+ m_d->preset = preset;
+}
+
+void KisUpdateTimeMonitor::reportMouseMove(const QPointF &pos)
+{
+ if (!m_d->loggingEnabled) return;
+
+ QMutexLocker locker(&m_d->mutex);
+
+ if (!m_d->lastMousePos.isNull()) {
+ qreal distance = kisDistance(m_d->lastMousePos, pos);
+ m_d->mousePath += distance;
+ }
+
+ m_d->lastMousePos = pos;
+}
+
+void KisUpdateTimeMonitor::printValues()
+{
+ qint64 strokeTime = m_d->strokeTime.elapsed();
+ qreal responseTime = qreal(m_d->responseTime) / m_d->numTickets;
+ qreal nonUpdateTime = qreal(m_d->jobsTime) / m_d->numTickets;
+ qreal jobsPerUpdate = qreal(m_d->numTickets) / m_d->numUpdates;
+ qreal mouseSpeed = qreal(m_d->mousePath) / strokeTime;
+
+ QString prefix;
+
+ if (m_d->preset) {
+ KisPaintOpPresetSP preset = m_d->preset->clone();
+ prefix = QString("%1.").arg(preset->name());
+ preset->setFilename(QString("log/%1.kpp").arg(preset->name()));
+ preset->save();
+ }
+
+ QFile logFile(QString("log/%1stroke.rdata").arg(prefix));
+ logFile.open(QIODevice::Append);
+ QTextStream stream(&logFile);
+ stream << mouseSpeed << "\t"
+ << jobsPerUpdate << "\t"
+ << nonUpdateTime << "\t"
+ << responseTime << "\n";
+ logFile.close();
+}
+
+void KisUpdateTimeMonitor::reportJobStarted(void *key)
+{
+ if (!m_d->loggingEnabled) return;
+
+ QMutexLocker locker(&m_d->mutex);
+
+ StrokeTicket *ticket = new StrokeTicket();
+ ticket->start();
+
+ m_d->preliminaryTickets.insert(key, ticket);
+}
+
+void KisUpdateTimeMonitor::reportJobFinished(void *key, const QVector<QRect> &rects)
+{
+ if (!m_d->loggingEnabled) return;
+
+ QMutexLocker locker(&m_d->mutex);
+
+ StrokeTicket *ticket = m_d->preliminaryTickets.take(key);
+ ticket->jobCompleted();
+
+ foreach(const QRect &rect, rects) {
+ ticket->dirtyRegion += rect;
+ }
+ m_d->finishedTickets.insert(ticket);
+}
+
+void KisUpdateTimeMonitor::reportUpdateFinished(const QRect &rect)
+{
+ if (!m_d->loggingEnabled) return;
+
+ QMutexLocker locker(&m_d->mutex);
+
+ foreach(StrokeTicket *ticket, m_d->finishedTickets) {
+ ticket->dirtyRegion -= rect;
+ if(ticket->dirtyRegion.isEmpty()) {
+ ticket->updateCompleted();
+ m_d->jobsTime += ticket->jobTime();
+ m_d->responseTime += ticket->jobTime() + ticket->updateTime();
+ m_d->numTickets++;
+
+ m_d->finishedTickets.remove(ticket);
+ delete ticket;
+ }
+ }
+ m_d->numUpdates++;
+}
diff --git a/krita/image/kis_update_time_monitor.h b/krita/image/kis_update_time_monitor.h
new file mode 100644
index 0000000..b56930a
--- /dev/null
+++ b/krita/image/kis_update_time_monitor.h
@@ -0,0 +1,56 @@
+/*
+ * Copyright (c) 2011 Dmitry Kazakov <dimula73 at gmail.com>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ */
+
+#ifndef __KIS_UPDATE_TIME_MONITOR_H
+#define __KIS_UPDATE_TIME_MONITOR_H
+
+#include "krita_export.h"
+#include "kis_types.h"
+
+
+#include <QVector>
+class QPointF;
+class QRect;
+
+
+class KRITAIMAGE_EXPORT KisUpdateTimeMonitor
+{
+public:
+ static KisUpdateTimeMonitor* instance();
+ ~KisUpdateTimeMonitor();
+
+ void startStrokeMeasure();
+ void endStrokeMeasure();
+ void reportPaintOpPreset(KisPaintOpPresetSP preset);
+
+ void reportMouseMove(const QPointF &pos);
+ void printValues();
+
+ void reportJobStarted(void *key);
+ void reportJobFinished(void *key, const QVector<QRect> &rects);
+ void reportUpdateFinished(const QRect &rect);
+
+private:
+ KisUpdateTimeMonitor();
+
+private:
+ struct Private;
+ Private * const m_d;
+};
+
+#endif /* __KIS_UPDATE_TIME_MONITOR_H */
diff --git a/krita/image/tests/kis_update_scheduler_test.cpp b/krita/image/tests/kis_update_scheduler_test.cpp
index 90e0e2a..600d318 100644
--- a/krita/image/tests/kis_update_scheduler_test.cpp
+++ b/krita/image/tests/kis_update_scheduler_test.cpp
@@ -382,6 +382,34 @@ void KisUpdateSchedulerTest::testBlockUpdates()
threadPool.waitForDone();
}
+#include "kis_update_time_monitor.h"
+
+void KisUpdateSchedulerTest::testTimeMonitor()
+{
+ QVector<QRect> dirtyRects;
+
+ KisUpdateTimeMonitor::instance()->startStrokeMeasure();
+ KisUpdateTimeMonitor::instance()->reportMouseMove(QPointF(100, 0));
+
+ KisUpdateTimeMonitor::instance()->reportJobStarted((void*) 10);
+ QTest::qSleep(300);
+ KisUpdateTimeMonitor::instance()->reportJobStarted((void*) 20);
+ QTest::qSleep(100);
+ dirtyRects << QRect(10,10,10,10);
+ KisUpdateTimeMonitor::instance()->reportJobFinished((void*) 10, dirtyRects);
+ QTest::qSleep(100);
+ dirtyRects.clear();
+ dirtyRects << QRect(30,30,10,10);
+ KisUpdateTimeMonitor::instance()->reportJobFinished((void*) 20, dirtyRects);
+ QTest::qSleep(500);
+ KisUpdateTimeMonitor::instance()->reportUpdateFinished(QRect(10,10,10,10));
+ QTest::qSleep(300);
+ KisUpdateTimeMonitor::instance()->reportUpdateFinished(QRect(30,30,10,10));
+
+ KisUpdateTimeMonitor::instance()->reportMouseMove(QPointF(130, 0));
+
+ KisUpdateTimeMonitor::instance()->endStrokeMeasure();
+}
QTEST_KDEMAIN(KisUpdateSchedulerTest, NoGUI)
#include "kis_update_scheduler_test.moc"
diff --git a/krita/image/tests/kis_update_scheduler_test.h b/krita/image/tests/kis_update_scheduler_test.h
index d076187..41e5552 100644
--- a/krita/image/tests/kis_update_scheduler_test.h
+++ b/krita/image/tests/kis_update_scheduler_test.h
@@ -38,6 +38,8 @@ private Q_SLOTS:
void testEmptyStroke();
void testLazyWaitCondition();
void testBlockUpdates();
+
+ void testTimeMonitor();
};
#endif /* KIS_UPDATE_SCHEDULER_TEST_H */
diff --git a/krita/sdk/plot_strokes_statistics b/krita/sdk/plot_strokes_statistics
new file mode 100755
index 0000000..f1159ba
--- /dev/null
+++ b/krita/sdk/plot_strokes_statistics
@@ -0,0 +1,31 @@
+#!/bin/sh
+gnuplot -p << EOF
+
+set size 1,1
+set origin 0,0
+
+set multiplot
+
+set grid
+set key bottom right
+set key box
+unset title
+set xlabel "Mouse speed, px/msec"
+set ylabel "Response time, msec"
+
+set size 1,0.5
+set origin 0,0.5
+plot '< sort -n -t \t $1' using 1:4 title "Total response time" with linespoints pointtype 2, \
+ '< sort -n -t \t $1' using 1:3 title "Jobs running time" with linespoints pointtype 10
+
+set grid
+set key top right
+set key box
+unset title
+set xlabel "Mouse speed, px/msec"
+set ylabel "Stroke jobs per update"
+
+set size 1,0.5
+set origin 0,0
+plot '< sort -n -t \t $1' using 1:2 title "Jobs per update" with linespoints pointtype 2
+EOF
\ No newline at end of file
diff --git a/krita/ui/tool/kis_tool_freehand_helper.cpp b/krita/ui/tool/kis_tool_freehand_helper.cpp
index d74c465..66f91d9 100644
--- a/krita/ui/tool/kis_tool_freehand_helper.cpp
+++ b/krita/ui/tool/kis_tool_freehand_helper.cpp
@@ -35,6 +35,8 @@
#include "kis_paintop_preset.h"
#include "kis_paintop_utils.h"
+#include "kis_update_time_monitor.h"
+
#include <math.h>
@@ -331,6 +333,8 @@ void KisToolFreehandHelper::paint(KoPointerEvent *event)
m_d->infoBuilder->continueStroke(event,
elapsedStrokeTime());
+ KisUpdateTimeMonitor::instance()->reportMouseMove(info.pos());
+
/**
* Smooth the coordinates out using the history and the
* distance. This is a heavily modified version of an algo used in
diff --git a/krita/ui/tool/strokes/freehand_stroke.cpp b/krita/ui/tool/strokes/freehand_stroke.cpp
index 2c0ec39..49436a6 100644
--- a/krita/ui/tool/strokes/freehand_stroke.cpp
+++ b/krita/ui/tool/strokes/freehand_stroke.cpp
@@ -23,6 +23,7 @@
#include "kis_paintop_settings.h"
#include "kis_painter.h"
+#include "kis_update_time_monitor.h"
FreehandStrokeStrategy::FreehandStrokeStrategy(bool needsIndirectPainting,
@@ -54,6 +55,13 @@ void FreehandStrokeStrategy::init(bool needsIndirectPainting,
setIndirectPaintingCompositeOp(indirectPaintingCompositeOp);
setSupportsWrapAroundMode(true);
enableJob(KisSimpleStrokeStrategy::JOB_DOSTROKE);
+
+ KisUpdateTimeMonitor::instance()->startStrokeMeasure();
+}
+
+FreehandStrokeStrategy::~FreehandStrokeStrategy()
+{
+ KisUpdateTimeMonitor::instance()->endStrokeMeasure();
}
void FreehandStrokeStrategy::doStrokeCallback(KisStrokeJobData *data)
@@ -61,6 +69,8 @@ void FreehandStrokeStrategy::doStrokeCallback(KisStrokeJobData *data)
Data *d = dynamic_cast<Data*>(data);
PainterInfo *info = d->painterInfo;
+ KisUpdateTimeMonitor::instance()->reportPaintOpPreset(info->painter->preset());
+
switch(d->type) {
case Data::POINT:
info->painter->paintAt(d->pi1, info->dragDistance);
@@ -91,5 +101,7 @@ void FreehandStrokeStrategy::doStrokeCallback(KisStrokeJobData *data)
info->painter->paintPainterPath(d->path);
};
- d->node->setDirty(info->painter->takeDirtyRegion());
+ QVector<QRect> dirtyRects = info->painter->takeDirtyRegion();
+ KisUpdateTimeMonitor::instance()->reportJobFinished(data, dirtyRects);
+ d->node->setDirty(dirtyRects);
}
diff --git a/krita/ui/tool/strokes/freehand_stroke.h b/krita/ui/tool/strokes/freehand_stroke.h
index 1293878..c52baac 100644
--- a/krita/ui/tool/strokes/freehand_stroke.h
+++ b/krita/ui/tool/strokes/freehand_stroke.h
@@ -117,6 +117,8 @@ public:
QVector<PainterInfo*> painterInfos,
const KUndo2MagicString &name);
+ ~FreehandStrokeStrategy();
+
void doStrokeCallback(KisStrokeJobData *data);
private:
More information about the kimageshop
mailing list