Bug 430173

Summary:	Consecutive screenshots degrade performance considerably
Product:	[Applications] Spectacle	Reporter:	irchaika
Component:	General	Assignee:	Boudhayan Gupta <me>
Status:	RESOLVED FIXED
Severity:	major	CC:	fabian, kde, nate
Priority:	NOR
Version:	20.08.3
Target Milestone:	---
Platform:	Arch Linux
OS:	Linux
Latest Commit:	https://invent.kde.org/graphics/spectacle/commit/647583a395195f60cf10de8bd1a6b77bc9447d6e	Version Fixed In:	20.12.1

Description irchaika 2020-12-09 04:52:44 UTC

SUMMARY
When taking consecutive screenshots, performance degrades

STEPS TO REPRODUCE
1. take a screenshot
2. as soon as screenshot is taken, take another one

OBSERVED RESULT
using commands like time and hyperfine I can see that the initial screenshot takes 0.7-0.8 seconds, but if consecutive screenshots are taken, the others take over 4 seconds

EXPECTED RESULT
all screenshots taking roughly the same amount of time to complete

SOFTWARE/OS VERSIONS
Linux/KDE Plasma: 5.9.12 / 5.20.4 
KDE Frameworks Version: 5.76.0
Qt Version: 5.15.2

ADDITIONAL INFORMATION
If it matters, my screenshots are saved as webp.

For the screenshot testing I used the b and n flags, so that the process could exit as soon as the screenshot is taken (otherwise you'll have to close the interface / wait for the notification to end).


The same issue could be observed when using the git version as well.

Comment 1 Nate Graham 2020-12-09 16:08:36 UTC

Works for me with git version. Can you clarify how you're taking the screenshots? What mode? What settings? How are you triggering it? The the button in the window? The PrintScreen key? etc.

Comment 2 irchaika 2020-12-09 20:05:20 UTC

as I said in the comment I'm using it with the b and n flags as I run mine in the background normally, and having a notification show has the process running until the notification is gone. Having both flags ensures that the process ends as soon as the screenshot is taken.

Whether I run it from a keyboard shortcut or from terminal the result is the same: degraded performance from the second consecutive screenshot. To measure the impact I did it with two programs, with the simple time and with hyperfine.

Just running "time spectacle -bn" consecutively shows the degradation which is:
1. running "time spectacle -bn" the first time
2. as soon as the process finishes run it a second time
3. see how that point onward it takes a lot more time to finish execution

waiting for a little while, like say, 10 seconds, will make the next execution be fast again.

The other, more controlled method, is using hyperfine https://github.com/sharkdp/hyperfine and just doing the following command:

1. hyperfine 'spectacle -bn'

from which my results are:
  Time (mean ± σ):      4.915 s ±  1.491 s    [User: 417.8 ms, System: 67.4 ms]
  Range (min … max):    0.673 s …  5.443 s    10 runs

Comment 3 Nate Graham 2020-12-09 21:07:19 UTC

Thanks for the information.

Comment 4 David Redondo 2020-12-10 09:13:59 UTC

I can confirm it on master

Comment 5 David Redondo 2020-12-10 15:51:47 UTC

Git commit 647583a395195f60cf10de8bd1a6b77bc9447d6e by David Redondo.
Committed on 10/12/2020 at 12:04.
Pushed by davidre into branch 'release/20.12'.

We do not need progress info when checking if a file exists

I debugged the time loss of
to be inbetween when org.kde.JobViewServer.requestView is called inside
KJobWidgets and the DBus adaptor on plasmashell is notified of that.
Unfortunately our methods are implemented in a blocking way as is the call in
KUiServerJobTracker::registerJob. So a simple fix is to disable job tracking.
Furthermore if the job would take long enough to display progress, it would
display an error to the user if the file doesn't exist, which is clearly not
what we want.
FIXED-IN:20.12.1

M  +1    -1    src/ExportManager.cpp

https://invent.kde.org/graphics/spectacle/commit/647583a395195f60cf10de8bd1a6b77bc9447d6e

Comment 6 irchaika 2020-12-10 19:23:48 UTC

Thank you, david, I tried with current master and the times are a lot more consistent now!

  Time (mean ± σ):     717.6 ms ±  46.1 ms    [User: 442.8 ms, System: 70.2 ms]
  Range (min … max):   675.3 ms … 822.8 ms    10 runs

Comment 7 Fabian Vogt 2020-12-14 13:10:50 UTC

When spectacle is stuck for 3s, this is the bt of plasmashell's main thread:

#0  0x00007f7bdbb4e9d8 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f7bdc9b9d74 in QWaitCondition::wait(QMutex*, QDeadlineTimer) () from /usr/lib64/libQt5Core.so.5
#2  0x00007f7bdc9b9e77 in QWaitCondition::wait(QMutex*, unsigned long) () from /usr/lib64/libQt5Core.so.5
#3  0x00007f7bd8408f73 in ?? () from /usr/lib64/libQt5XcbQpa.so.5
#4  0x00007f7bd83e22c0 in ?? () from /usr/lib64/libQt5XcbQpa.so.5
#5  0x00007f7bd83e2909 in ?? () from /usr/lib64/libQt5XcbQpa.so.5
#6  0x00007f7bd83e41c8 in ?? () from /usr/lib64/libQt5XcbQpa.so.5
#7  0x00007f7bdd1034a8 in QInternalMimeData::formats() const () from /usr/lib64/libQt5Gui.so.5
#8  0x00007f7bd83e4531 in ?? () from /usr/lib64/libQt5XcbQpa.so.5
#9  0x00007f7bdd103804 in QInternalMimeData::retrieveData(QString const&, QVariant::Type) const () from /usr/lib64/libQt5Gui.so.5
#10 0x00007f7bdcbb8ef0 in ?? () from /usr/lib64/libQt5Core.so.5
#11 0x00007f7bdcbb9e2e in QMimeData::data(QString const&) const () from /usr/lib64/libQt5Core.so.5
#12 0x00007f7bdc38bb42 in KIO::isClipboardDataCut(QMimeData const*) () from /usr/lib64/libKF5KIOWidgets.so.5
#13 0x00007f7bd79cd9d1 in ?? () from /usr/lib64/libKF5KIOFileWidgets.so.5
#14 0x00007f7bd79cf404 in ?? () from /usr/lib64/libKF5KIOFileWidgets.so.5
#15 0x00007f7bdcbc9b40 in ?? () from /usr/lib64/libQt5Core.so.5
#16 0x00007f7bdd0f3e45 in QClipboard::emitChanged(QClipboard::Mode) () from /usr/lib64/libQt5Gui.so.5
#17 0x00007f7bd83e6204 in QXcbConnection::handleXcbEvent(xcb_generic_event_t*) () from /usr/lib64/libQt5XcbQpa.so.5
#18 0x00007f7bd83e7636 in QXcbConnection::processXcbEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQt5XcbQpa.so.5
#19 0x00007f7bd8409e13 in ?? () from /usr/lib64/libQt5XcbQpa.so.5
#20 0x00007f7bdafc3ca7 in g_main_context_dispatch () from /usr/lib64/libglib-2.0.so.0
#21 0x00007f7bdafc4028 in ?? () from /usr/lib64/libglib-2.0.so.0
#22 0x00007f7bdafc40df in g_main_context_iteration () from /usr/lib64/libglib-2.0.so.0
#23 0x00007f7bdcbeaa6f in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQt5Core.so.5
#24 0x00007f7bdcb91edb in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQt5Core.so.5
#25 0x00007f7bdcb9a150 in QCoreApplication::exec() () from /usr/lib64/libQt5Core.so.5
#26 0x00005585eab3b214 in ?? ()
#27 0x00007f7bdc53b152 in __libc_start_main () from /lib64/libc.so.6
#28 0x00005585eab3b5ce in ?? ()

It seems like it's calling back into spectacle to get clipboard data, which causes a deadlock (presumably with a ~3s timeout). This also explains why this issue only happens in an X11 session.