Commit 78bb7ed3 authored by Dmitry Kazakov's avatar Dmitry Kazakov
Browse files

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@kde.org
parent 1e33bab5
......@@ -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
......
......@@ -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);
}
......
......@@ -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);
......
......@@ -29,6 +29,7 @@ public:
KisImageConfig();
~KisImageConfig();
bool enablePerfLog() const;
qreal transformMaskOffBoundsReadArea() const;
int updatePatchHeight() const;
......
/*
* Copyright (c) 2011 Dmitry Kazakov <dimula73@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++;
}
/*
* Copyright (c) 2011 Dmitry Kazakov <dimula73@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 */
......@@ -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"
......
......@@ -38,6 +38,8 @@ private Q_SLOTS:
void testEmptyStroke();
void testLazyWaitCondition();
void testBlockUpdates();
void testTimeMonitor();
};
#endif /* KIS_UPDATE_SCHEDULER_TEST_H */
......
#!/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
......@@ -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
......
......@@ -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);
}
......@@ -117,6 +117,8 @@ public:
QVector<PainterInfo*> painterInfos,
const KUndo2MagicString &name);
~FreehandStrokeStrategy();
void doStrokeCallback(KisStrokeJobData *data);
private:
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment