I've been using the "System Load Viewer" widget with an update interval of 500ms (showing all cores), and noticed it causes the plasma-desktop process to have a constant ~2% cpu, whereas without this widget it's usually at 0, and with a larger interval such as 3000ms it's at ~0.7% cpu. strace shows that the plasma-desktop process is wasting most of its time in the stat system call on the file /etc/localtime. A bit more digging shows the stack trace pasted below. It looks like the data container's timeSinceLastUpdate calls QTime::elapsed, which internally does a timezone lookup that does the stat, which is a whole lot of overhead for measuring an elapsed time (which is done often). A quick search shows that QT has a QElapsedTime class as a quick replacement for QTime's elapsed functionality, which uses a monotonic clock rather than the system time, so it doesn't deal with this timezone overhead, and should be much more efficient. As an added bonus, it doesn't reset every 24 hours like QTime::elapsed (which can potentially cause subtle bugs), is immune to timezone changes and system time changes, etc. (see its docs) so it should be much safer and more appropriate in measuring an elapsed time between data engine polls. It sounds like it would be a better choice, and probably fix this performance hog. There may be other performance issues, but this is the first one that stood out. Here is the stack trace: #0 0x00007f3bc5490035 in __GI___xstat (vers=<optimized out>, name=0x7f3bc55230da "/etc/localtime", buf=0x7fff721e5e50) at ../sysdeps/unix/sysv/linux/wordsize-64/xstat.c:35 resultvar = 18446744073709551578 #1 0x00007f3bc5457b5d in __tzfile_read (file=file@entry=0x7f3bc55230da "/etc/localtime", extra=extra@entry=0, extrap=extrap@entry=0x0) at tzfile.c:161 default_tzdir = "/usr/share/zoneinfo" num_isstd = <optimized out> num_isgmt = <optimized out> f = <optimized out> tzhead = {tzh_magic = "`_\036r", tzh_version = "\377", tzh_reserved = "\177\000\000\360uB\305;\177\000\000\030\000\000", tzh_ttisgmtcnt = "\000\000\000", tzh_ttisstdcnt = "\r\000\000", tzh_leapcnt = "\000\000\000", tzh_timecnt = "\r\000\000", tzh_typecnt = "\000\000\000", tzh_charcnt = "&\271\367\301"} chars = <optimized out> i = <optimized out> total_size = <optimized out> types_idx = <optimized out> leaps_idx = <optimized out> was_using_tzfile = 1 trans_width = 4 tzspec_len = <optimized out> new = 0x0 st = {st_dev = 140735107981184, st_ino = 99187242, st_nlink = 140735107981296, st_mode = 3254258449, st_uid = 32571, st_gid = 99187248, __pad0 = 0, st_rdev = 139893110894019, st_size = 140735107980944, st_blksize = 4311194416, st_blocks = 68633392, st_atim = {tv_sec = 140735107981296, tv_nsec = 140733193388032}, st_mtim = { tv_sec = 139894692656992, tv_nsec = 15}, st_ctim = {tv_sec = 20152577, tv_nsec = 139894684633696}, __glibc_reserved = {6, 0, 139894689265136}} __PRETTY_FUNCTION__ = "__tzfile_read" #2 0x00007f3bc5456eb4 in tzset_internal (always=always@entry=1, explicit=explicit@entry=1) at tzset.c:447 is_initialized = 1 tz = 0x7f3bc55230da "/etc/localtime" #3 0x00007f3bc54577b0 in __tzset () at tzset.c:600 No locals. #4 0x00007f3bc1f46910 in QTime::currentTime () at tools/qdatetime.cpp:3116 tv = {tv_sec = 1403364091, tv_usec = 769201} ltime = 1403364091 ct = {mds = -1} t = 0x0 res = {tm_sec = 99187216, tm_min = 0, tm_hour = -1039948579, tm_mday = 32571, tm_mon = 112568816, tm_year = 0, tm_wday = 1919, tm_yday = 37, tm_isdst = 61719552, tm_gmtoff = 133755200, tm_zone = 0x7fff721e5f8f ""} #5 0x00007f3bc1f469dd in QTime::elapsed (this=0x21d28e0) at tools/qdatetime.cpp:2005 n = -38 #6 0x00007f3bc4fb92ed in Plasma::DataContainer::timeSinceLastUpdate (this=this@entry=0x1b740e0) at ../../plasma/datacontainer.cpp:320 No locals. #7 0x00007f3bc4fbae8f in Plasma::DataEnginePrivate::internalUpdateSource (this=0x21d3080, source=0x1b740e0) at ../../plasma/dataengine.cpp:570 No locals. #8 0x00007f3bc4fbc9c0 in Plasma::DataEngine::qt_static_metacall (_o=0x7f3bc55230da, _id=1914592848, _a=0x7fff721e6170, _c=<optimized out>) at ./dataengine.moc:107 No locals. #9 0x00007f3bc204e87a in QMetaObject::activate (sender=0x1b740e0, m=m@entry=0x7f3bc538e980 <Plasma::DataContainer::staticMetaObject>, local_signal_index=local_signal_index@entry=2, argv=argv@entry=0x7fff721e6170) at kernel/qobject.cpp:3539 receiverInSameThread = true previousSender = 0x0 callFunction = 0x7f3bc4fbca60 <Plasma::DataEngine::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)> receiver = 0x219b850 currentSender = {sender = 0x1b740e0, signal = 6, ref = 1} ---Type <return> to continue, or q <return> to quit--- method_relative = 6 c = 0x21d2b50 last = 0x21d2b50 methodOffset = <optimized out> signal_absolute_index = 6 empty_argv = {0x0} locker = {val = 20687936} connectionLists = 0x21d2ba0 list = 0x21d2c20 signalOffset = <optimized out> signal_index = <optimized out> currentThreadId = 139894697121728 #10 0x00007f3bc4fb93c2 in Plasma::DataContainer::updateRequested (this=<optimized out>, _t1=0x1b740e0) at ./datacontainer.moc:139 _a = {0x0, 0x7fff721e6168} #11 0x00007f3bc4feeb40 in Plasma::SignalRelay::timerEvent (this=0x21222c0, event=<optimized out>) at ../../plasma/private/datacontainer_p.cpp:154 event = <optimized out> this = 0x21222c0 #12 0x00007f3bc2052a31 in QObject::event (this=0x21222c0, e=<optimized out>) at kernel/qobject.cpp:1156 No locals. #13 0x00007f3bc13d3e2c in QApplicationPrivate::notify_helper (this=this@entry=0x1338130, receiver=receiver@entry=0x21222c0, e=e@entry=0x7fff721e6540) at kernel/qapplication.cpp:4567 consumed = <optimized out> #14 0x00007f3bc13da4a0 in QApplication::notify (this=this@entry=0x13101b0, receiver=receiver@entry=0x21222c0, e=e@entry=0x7fff721e6540) at kernel/qapplication.cpp:4353 w = 0x21222c0 extra = <optimized out> isProxyWidget = <optimized out> d = 0x1338130 res = false #15 0x00007f3bc2cffd1a in KApplication::notify (this=0x13101b0, receiver=0x21222c0, event=0x7fff721e6540) at ../../kdeui/kernel/kapplication.cpp:311 No locals. #16 0x00007f3bc203a4dd in QCoreApplication::notifyInternal (this=0x13101b0, receiver=0x21222c0, event=0x7fff721e6540) at kernel/qcoreapplication.cpp:953 threadData = 0x126b1f0 returnValue = <optimized out> result = false cbdata = {0x21222c0, 0x7fff721e6540, 0x7fff721e64af} d = <optimized out> #17 0x00007f3bc206a323 in sendEvent (event=<optimized out>, receiver=<optimized out>) at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:231 No locals. #18 QTimerInfoList::activateTimers (this=0x13392e0) at kernel/qeventdispatcher_unix.cpp:621 e = {<QEvent> = {_vptr.QEvent = 0x7f3bc239b9f0 <vtable for QTimerEvent+16>, static staticMetaObject = {d = { superdata = 0x0, stringdata = 0x7f3bc212a9c0 <qt_meta_stringdata_QEvent> "QEvent", data = 0x7f3bc212b3c0 <qt_meta_data_QEvent>, extradata = 0x0}}, d = 0x0, t = 1, posted = 0, spont = 0, m_accept = 1, reserved = 3651}, id = 1107296358} currentTimerInfo = 0x215b9c0 n_act = 54 maxCount = 56 #19 0x00007f3bc20675f1 in timerSourceDispatch (source=<optimized out>) at kernel/qeventdispatcher_glib.cpp:193 timerSource = <optimized out> #20 0x00007f3bb89ece04 in g_main_dispatch (context=0x1338610) at /build/buildd/glib2.0-2.40.0/./glib/gmain.c:3064 dispatch = 0x7f3bc20675d0 <timerSourceDispatch(GSource*, GSourceFunc, gpointer)> prev_source = 0x0 was_in_call = 0 user_data = 0x0 ---Type <return> to continue, or q <return> to quit--- callback = 0x0 cb_funcs = <optimized out> cb_data = 0x0 need_destroy = <optimized out> source = 0x1339280 current = 0x1275f90 i = 2 #21 g_main_context_dispatch (context=context@entry=0x1338610) at /build/buildd/glib2.0-2.40.0/./glib/gmain.c:3663 No locals. #22 0x00007f3bb89ed048 in g_main_context_iterate (context=context@entry=0x1338610, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at /build/buildd/glib2.0-2.40.0/./glib/gmain.c:3734 max_priority = 0 timeout = 0 some_ready = 1 nfds = <optimized out> allocated_nfds = 18 fds = 0x3c77da0 #23 0x00007f3bb89ed0ec in g_main_context_iteration (context=0x1338610, may_block=1) at /build/buildd/glib2.0-2.40.0/./glib/gmain.c:3795 retval = <optimized out> #24 0x00007f3bc20677a1 in QEventDispatcherGlib::processEvents (this=0x126caf0, flags=...) at kernel/qeventdispatcher_glib.cpp:434 d = 0x1338540 canWait = <optimized out> savedFlags = {i = 0} result = <optimized out> #25 0x00007f3bc1475bb6 in QGuiEventDispatcherGlib::processEvents (this=<optimized out>, flags=...) at kernel/qguieventdispatcher_glib.cpp:204 d = 0x1338540 saved_flags = {i = 0} returnValue = 218 #26 0x00007f3bc20390af in QEventLoop::processEvents (this=this@entry=0x7fff721e67b0, flags=...) at kernel/qeventloop.cpp:149 d = 0x1477b00 #27 0x00007f3bc20393a5 in QEventLoop::exec (this=this@entry=0x7fff721e67b0, flags=...) at kernel/qeventloop.cpp:204 d = 0x1477b00 locker = {val = 19313448} #28 0x00007f3bc203eb79 in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1225 threadData = 0x126b1f0 eventLoop = {<QObject> = {_vptr.QObject = 0x7f3bc239e710 <vtable for QEventLoop+16>, static staticMetaObject = {d = { superdata = 0x0, stringdata = 0x7f3bc2117ca0 <qt_meta_stringdata_QObject> "QObject", data = 0x7f3bc2117d40 <qt_meta_data_QObject>, extradata = 0x7f3bc239bc60 <QObject::staticMetaObjectExtraData>}}, static staticMetaObjectExtraData = { objects = 0x0, static_metacall = 0x7f3bc2053ae0 <QObject::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>}, d_ptr = {d = 0x1477b00}, static staticQtMetaObject = {d = {superdata = 0x0, stringdata = 0x7f3bc2120be0 <qt_meta_stringdata_Qt> "Qt", data = 0x7f3bc2124500 <qt_meta_data_Qt>, extradata = 0x0}}}, static staticMetaObject = {d = {superdata = 0x7f3bc239bc40 <QObject::staticMetaObject>, stringdata = 0x7f3bc212a7c0 <qt_meta_stringdata_QEventLoop> "QEventLoop", data = 0x7f3bc212a7e0 <qt_meta_data_QEventLoop>, extradata = 0x7f3bc239e7a0 <QEventLoop::staticMetaObjectExtraData>}}, static staticMetaObjectExtraData = { objects = 0x0, static_metacall = 0x7f3bc2098df0 <QEventLoop::qt_static_metacall(QObject*, QMetaObject::Call, int, void**)>}} returnCode = <optimized out> #29 0x00007f3bc13d237c in QApplication::exec () at kernel/qapplication.cpp:3828 No locals. #30 0x00007f3bc57a667c in kdemain (argc=1, argv=0x7fff721e6a08) at ../../../../plasma/desktop/shell/main.cpp:126 __PRETTY_FUNCTION__ = "int kdemain(int, char**)" associatedScreen = <optimized out> aboutData = {d = 0x1310630} ---Type <return> to continue, or q <return> to quit--- app = 0x13101b0 appName = {static shared_null = {ref = {_q_value = 11650}, alloc = 0, size = 0, data = 0x7f3bc23a07d8 <QByteArray::shared_null+24> "", array = ""}, static shared_empty = {ref = { _q_value = 497}, alloc = 0, size = 0, data = 0x7f3bc23a07b8 <QByteArray::shared_empty+24> "", array = ""}, d = 0x12d8990} rc = <optimized out> #31 0x00007f3bc53c5ec5 in __libc_start_main (main=0x4006e0 <main(int, char**)>, argc=1, argv=0x7fff721e6a08, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff721e69f8) at libc-start.c:287 result = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, 166257367395818701, 4196069, 140735107983872, 0, 0, -166547368227152691, -272150802962752307}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x4007e0 <__libc_csu_init>, 0x7fff721e6a08}, data = {prev = 0x0, cleanup = 0x0, canceltype = 4196320}}} not_first_call = <optimized out> #32 0x000000000040070e in _start () Reproducible: Always Steps to Reproduce: 1. Add the System Load Viewer widget to the panel. 2. Configure it to show all processors 3. Configure its update interval to 500ms 4. Watch the plasma-desktop process cpu usage. Actual Results: plasma-desktop takes up a constant 2% of cpu resources. Expected Results: There should be no such cpu resource usage for a simple 2Hz resource monitor. Using KDE 4.13.2 on Kubuntu 14.04.
Thanks for the good analysis. I created a review request to test at https://git.reviewboard.kde.org/r/118869/
Ok, trying to run it a bit with the patch on. By the way, this probably should be done in both kde4 and plasma5 I guess
Git commit ac5d3d2f916c0a461121d4d033642227bd743edb by Christoph Feck. Committed on 23/06/2014 at 11:02. Pushed by cfeck into branch 'master'. Use QElapsedTimer for data engines REVIEW: 118869 M +3 -5 plasma/datacontainer.cpp M +3 -3 plasma/dataengine.cpp M +2 -2 plasma/private/datacontainer_p.h M +2 -4 plasma/private/dataengine_p.h http://commits.kde.org/kdelibs/ac5d3d2f916c0a461121d4d033642227bd743edb
Git commit fec57bdaa2622efbab88061e3d84fda03a806376 by Christoph Feck. Committed on 23/06/2014 at 11:03. Pushed by cfeck into branch 'master'. Use QElapsedTimer for data engines forward port of http://commits.kde.org/kdelibs/ac5d3d2f916c0a461121d4d033642227bd743edb REVIEW: 118869 M +3 -5 src/plasma/datacontainer.cpp M +3 -3 src/plasma/dataengine.cpp M +2 -2 src/plasma/private/datacontainer_p.h M +2 -4 src/plasma/private/dataengine_p.h http://commits.kde.org/plasma-framework/fec57bdaa2622efbab88061e3d84fda03a806376
Can someone running 14.4 say how the cpu usage look in this scenario after the fix?
Can someone running 4.14 say how the cpu usage looks in this scenario after the fix?
While showing CPU load of 4 cores plus total, plasma-desktop shows between 0.25 and 0.75% CPU usage on a intel Q6660 when the window is minimum size and 0.5s update rate. If I make the window somewhat bigger it the cpu usage is around 1.25 to 1.50%. KDE 4.14
*** Bug 273214 has been marked as a duplicate of this bug. ***