Created attachment 63387 [details] 1000 lines of 559MB strace file (and strace was run only for part of hang time!) Version: 4.7 (using Devel) OS: Linux In kmail when I try to attach a file, file picker opens, I start witting file name and file picker hangs. Strace reveals that it repeatly opens and reads /etc/localtime file. After like 20-30s file picker is responsive again. If I try to attach another file then there is no such hang. But if I exit kmail, start it again and try to attach file then hangs occurs. Bug it is not new, it happened in 4.6.x, too. Reproducible: Always Steps to Reproduce: Run kmail, create new mail, try to attach some file and start typing file name in filelicer form. Actual Results: Filepicker hangs doing /etc/localtime reads. Expected Results: No hang. kmail filepicker hanging and it did read /etc/localtime only 500 thousand times: [arekm@t400 ~]$ grep /etc/localtime WYNIK|wc -l 465539 In my $HOME where filepicker opens by default I have 1k files. [arekm@t400 ~]$ ls -1 | wc -l 1090
gdb trace looks like this: 0x0000003a0d0d9bad in lseek64 () from /lib64/libc.so.6 (gdb) bt #0 0x0000003a0d0d9bad in lseek64 () from /lib64/libc.so.6 #1 0x0000003a0d070c69 in _IO_file_seekoff () from /lib64/libc.so.6 #2 0x0000003a0d06dce2 in fseek () from /lib64/libc.so.6 #3 0x0000003a0d09af65 in ?? () from /lib64/libc.so.6 #4 0x0000003a0d09a7c3 in ?? () from /lib64/libc.so.6 #5 0x0000003a0d09a9f0 in tzset () from /lib64/libc.so.6 #6 0x00007fc996219a48 in offsetAtZoneTime (this=<value optimized out>, caller=<value optimized out>, zoneDateTime=..., secondOffset=0x7fffb313096c) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/ksystemtimezone.cpp:573 #7 KSystemTimeZoneBackend::offsetAtZoneTime (this=<value optimized out>, caller=<value optimized out>, zoneDateTime=..., secondOffset=0x7fffb313096c) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/ksystemtimezone.cpp:561 #8 0x00007fc9961fde84 in timeZoneOffset (this=0x5a15a90) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/kdatetime.cpp:606 #9 KDateTimePrivate::timeZoneOffset (this=0x5a15a90) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/kdatetime.cpp:592 #10 0x00007fc9961fe1a4 in KDateTimePrivate::toUtc (this=0x5a15a90, local=...) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/kdatetime.cpp:693 #11 0x00007fc996203cd7 in KDateTime::secsTo_long (this=0x7fffb3130bd0, t2=...) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/kdatetime.cpp:1188 #12 0x00007fc996203f59 in KDateTime::secsTo (this=<value optimized out>, t2=<value optimized out>) at /usr/src/debug/kdelibs-4.7.1/kdecore/date/kdatetime.cpp:1161 #13 0x00007fc99630234b in KLocalePrivate::formatDateTime (this=0x1d5b050, dateTime=..., format=KLocale::ShortDate, options=...) at /usr/src/debug/kdelibs-4.7.1/kdecore/localization/klocale_kde.cpp:2556 #14 0x00007fc9962fc8b4 in KLocale::formatDateTime (this=<value optimized out>, dateTime=<value optimized out>, format=<value optimized out>, options=<value optimized out>) at /usr/src/debug/kdelibs-4.7.1/kdecore/localization/klocale.cpp:463 #15 0x00007fc994f56c2c in KDirModel::data (this=0x538df50, index=<value optimized out>, role=<value optimized out>) at /usr/src/debug/kdelibs-4.7.1/kio/kio/kdirmodel.cpp:665 #16 0x00007fc995da0d4c in QSortFilterProxyModel::data(QModelIndex const&, int) const () from /usr/lib64/libQtGui.so.4 #17 0x00007fc994f785be in data (this=0x5579c80, index=...) at /usr/include/qt4/QtCore/qabstractitemmodel.h:398 #18 KFileItemDelegate::Private::display (this=0x5579c80, index=...) at /usr/src/debug/kdelibs-4.7.1/kio/kio/kfileitemdelegate.cpp:980 #19 0x00007fc994f78ea9 in KFileItemDelegate::Private::initStyleOption (this=0x5579c80, option=0x7fffb3131110, index=...) at /usr/src/debug/kdelibs-4.7.1/kio/kio/kfileitemdelegate.cpp:857 #20 0x00007fc994f7c83b in KFileItemDelegate::sizeHint (this=0x5573540, option=..., index=...) at /usr/src/debug/kdelibs-4.7.1/kio/kio/kfileitemdelegate.cpp:949 #21 0x00007fc995d5e5c3 in QTreeView::sizeHintForColumn(int) const () from /usr/lib64/libQtGui.so.4 #22 0x00007fc995d326ef in ?? () from /usr/lib64/libQtGui.so.4 #23 0x00007fc986d2a4ed in KDirOperatorDetailView::slotLayoutChanged (this=0x53b32f0) at /usr/src/debug/kdelibs-4.7.1/kfile/kdiroperatordetailview.cpp:168 #24 0x00007fc986d194bc in KDirOperatorDetailView::qt_metacall (this=0x53b32f0, _c=QMetaObject::InvokeMetaMethod, _id=<value optimized out>, _a=<value optimized out>) at /usr/src/debug/kdelibs-4.7.1/build/kfile/moc_kdiroperatordetailview_p.cpp:77 #25 0x00007fc995541eaa in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/libQtCore.so.4 #26 0x00007fc995da8044 in ?? () from /usr/lib64/libQtGui.so.4 #27 0x00007fc995da948b in QSortFilterProxyModel::qt_metacall(QMetaObject::Call, int, void**) () from /usr/lib64/libQtGui.so.4 #28 0x00007fc986d2d8f8 in KDirSortFilterProxyModel::qt_metacall (this=0x538f170, _c=QMetaObject::InvokeMetaMethod, _id=<value optimized out>, _a=<value optimized out>) at /usr/src/debug/kdelibs-4.7.1/build/kfile/kdirsortfilterproxymodel.moc:68 #29 0x00007fc995541eaa in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/libQtCore.so.4 #30 0x00007fc99558aa67 in QAbstractItemModel::dataChanged(QModelIndex const&, QModelIndex const&) () from /usr/lib64/libQtCore.so.4 #31 0x00007fc994f57094 in KDirModel::itemChanged (this=0x538df50, index=...) at /usr/src/debug/kdelibs-4.7.1/kio/kio/kdirmodel.cpp:640 #32 0x00007fc986d53430 in KFilePreviewGenerator::Private::dispatchIconUpdateQueue (this=0x539a680) at /usr/src/debug/kdelibs-4.7.1/kfile/kfilepreviewgenerator.cpp:760 #33 0x00007fc986d53594 in KFilePreviewGenerator::Private::resolveMimeType (this=0x539a680) at /usr/src/debug/kdelibs-4.7.1/kfile/kfilepreviewgenerator.cpp:872 #34 0x00007fc986d5511d in KFilePreviewGenerator::qt_metacall (this=0x53cb160, _c=QMetaObject::InvokeMetaMethod, _id=<value optimized out>, _a=0x575f150) at /usr/src/debug/kdelibs-4.7.1/build/kfile/kfilepreviewgenerator.moc:101 #35 0x00007fc995545a4e in QObject::event(QEvent*) () from /usr/lib64/libQtCore.so.4 ---Type <return> to continue, or q <return> to quit--- #36 0x00007fc99581bda4 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /usr/lib64/libQtGui.so.4 #37 0x00007fc995820c23 in QApplication::notify(QObject*, QEvent*) () from /usr/lib64/libQtGui.so.4 #38 0x00007fc99669a626 in KApplication::notify (this=0x7fffb3133a60, receiver=0x53cb160, event=0x59f8c10) at /usr/src/debug/kdelibs-4.7.1/kdeui/kernel/kapplication.cpp:311 #39 0x00007fc99552f37c in QCoreApplication::notifyInternal(QObject*, QEvent*) () from /usr/lib64/libQtCore.so.4 #40 0x00007fc9955326ef in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () from /usr/lib64/libQtCore.so.4 #41 0x00007fc99555a103 in ?? () from /usr/lib64/libQtCore.so.4 #42 0x0000003a0ea4227d in g_main_context_dispatch () from /usr/lib64/libglib-2.0.so.0 #43 0x0000003a0ea42a58 in ?? () from /usr/lib64/libglib-2.0.so.0 #44 0x0000003a0ea42ce9 in g_main_context_iteration () from /usr/lib64/libglib-2.0.so.0 #45 0x00007fc99555a566 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4 #46 0x00007fc9958bec7e in ?? () from /usr/lib64/libQtGui.so.4 #47 0x00007fc99552e572 in QEventLoop::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4 #48 0x00007fc99552e777 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4 #49 0x00007fc995cca896 in QDialog::exec() () from /usr/lib64/libQtGui.so.4 #50 0x0000003a28582f10 in ?? () from /usr/lib64/libkmailprivate.so.4 #51 0x0000003a2859474a in ?? () from /usr/lib64/libkmailprivate.so.4 #52 0x00007fc995541eaa in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/libQtCore.so.4 #53 0x00007fc995815782 in QAction::triggered(bool) () from /usr/lib64/libQtGui.so.4 #54 0x00007fc99581596f in QAction::activate(QAction::ActionEvent) () from /usr/lib64/libQtGui.so.4 #55 0x00007fc995bcc8ea in ?? () from /usr/lib64/libQtGui.so.4 #56 0x00007fc995bccb9c in QAbstractButton::mouseReleaseEvent(QMouseEvent*) () from /usr/lib64/libQtGui.so.4 #57 0x00007fc995c88e0a in QToolButton::mouseReleaseEvent(QMouseEvent*) () from /usr/lib64/libQtGui.so.4 #58 0x00007fc99586c240 in QWidget::event(QEvent*) () from /usr/lib64/libQtGui.so.4 #59 0x00007fc99581bda4 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /usr/lib64/libQtGui.so.4 #60 0x00007fc995821574 in QApplication::notify(QObject*, QEvent*) () from /usr/lib64/libQtGui.so.4 #61 0x00007fc99669a626 in KApplication::notify (this=0x7fffb3133a60, receiver=0x5317df0, event=0x7fffb3132dd0) at /usr/src/debug/kdelibs-4.7.1/kdeui/kernel/kapplication.cpp:311 #62 0x00007fc99552f37c in QCoreApplication::notifyInternal(QObject*, QEvent*) () from /usr/lib64/libQtCore.so.4 #63 0x00007fc99581cd72 in QApplicationPrivate::sendMouseEvent(QWidget*, QMouseEvent*, QWidget*, QWidget*, QWidget**, QPointer<QWidget>&, bool) () from /usr/lib64/libQtGui.so.4 #64 0x00007fc9958988f1 in ?? () from /usr/lib64/libQtGui.so.4 #65 0x00007fc99589769a in QApplication::x11ProcessEvent(_XEvent*) () from /usr/lib64/libQtGui.so.4 #66 0x00007fc9958bf002 in ?? () from /usr/lib64/libQtGui.so.4 #67 0x0000003a0ea4227d in g_main_context_dispatch () from /usr/lib64/libglib-2.0.so.0 #68 0x0000003a0ea42a58 in ?? () from /usr/lib64/libglib-2.0.so.0 #69 0x0000003a0ea42ce9 in g_main_context_iteration () from /usr/lib64/libglib-2.0.so.0 #70 0x00007fc99555a566 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4 #71 0x00007fc9958bec7e in ?? () from /usr/lib64/libQtGui.so.4 #72 0x00007fc99552e572 in QEventLoop::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4 #73 0x00007fc99552e777 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4 #74 0x00007fc99553296b in QCoreApplication::exec() () from /usr/lib64/libQtCore.so.4 #75 0x00000000004030db in _start ()
It looks as if some optimisation in KSystemTimeZoneBackend::offsetAtZoneTime() would help, so that for times near to each other, the time zone offset doesn't have to be recalculated unnecessarily. I'll look into that. However, KLocale::formatDateTime(), which calls that function, must be being called a very large number of times itself. KDirModel seems to be responsible - is it evaluating the display width too frequently? Perhaps it needs optimisation too.
Hmm, there have to be some bug there. I use "detailed view" in filepicker and home dir (which is opened by default when filepicker is displayed) contains ~1k files. More than 500k timezone related calls looks like far too much for 1k files.
btw. Quick test seems to indicate that "short view" doesn't have this kind of problem.
Could this be the same as bug 278899 ? Please test the fix from that bug.
I'm trying to reproduce for last 15 minutes in 4.8.2 and the issue in filepicker seems gone BUT there is similar problem in okteta. It hangs accessing timezone data over and over (according to strace and gdb). Could anyone familiar look if there is something similar used in okteta?
KSystemTimeZone functions use libc functions to obtain time zone data. If data is required for a time zone which is not the current system time zone, it's necessary to call tzset() first to specify the time zone to use, and then tzset() again on exit to restore the current system time zone. It seems that tzset() reads the time zone definition file each time it's called. So for each offsetAtZoneTime() call, time zone files are read twice. In the case of multiple successive calls for data from the same time zone, there will be many reads of the same time zone file, which is plainly very time consuming and wasteful. To fix this, I think KSystemTimeZone needs to use KTzfileTimeZone instead of using libc functions. This should make it possible to only read each time zone file a single time. I'll look at implementing this.
Git commit 332a3c15ab3f871e4c61e95719e0bba9e86b677f by David Jarvie. Committed on 11/04/2012 at 23:42. Pushed by djarvie into branch 'KDE/4.8'. Use KTzfileTimeZone instead of KSystemTimeZone on UNIX Use KTzfileTimeZone in preference to KSystemTimeZone on UNIX systems, since use of the standard system libraries by KSystemTimeZone requires the use of tzset() in several methods. That function reads and parses the local system time zone definition file every time it is called, and this has been observed to make applications hang for many seconds when a large number of KSystemTimeZone calls are made in succession. M +5 -2 kdecore/date/ksystemtimezone.cpp M +11 -11 kdecore/date/ksystemtimezone.h M +2 -2 kdecore/date/ktzfiletimezone.cpp A +288 -0 kdecore/tests/Berlin.zdump A +374 -0 kdecore/tests/Los_Angeles.zdump M +36 -4 kdecore/tests/ktimezonestest.cpp M +1 -0 kdecore/tests/ktimezonestest.h http://commits.kde.org/kdelibs/332a3c15ab3f871e4c61e95719e0bba9e86b677f
It helped a bit with okteta case (bug #297214) but didn't solve the issue fully (or maybe okteta filepicker is doing something more than "pure" filepicker)
This wasn't fixed as far as I can tell. I'm using KDE 4.13.1 (Kubuntu 14.04 clean install) and seeing this bug, not just with Kmail and the file picker, but also when starting up applications such as Kile, Kate and Dolphin.