Bug 297214 - okteta "hangs" at start doing timezone related operations over and over
Summary: okteta "hangs" at start doing timezone related operations over and over
Status: RESOLVED WORKSFORME
Alias: None
Product: kdelibs
Classification: Frameworks and Libraries
Component: kdecore (show other bugs)
Version: unspecified
Platform: unspecified Linux
: NOR normal
Target Milestone: ---
Assignee: kdelibs bugs
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-03-31 20:57 UTC by Arkadiusz Miskiewicz
Modified: 2023-02-04 04:58 UTC (History)
3 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Arkadiusz Miskiewicz 2012-03-31 20:57:15 UTC
okteta (kde 4.8.1, 4.8.2) starts, GUI is shown, immediately becomes unusable and okteta then
does tons of timezone related operations:

[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000014>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000017>
[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000016>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000018>
[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000019>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000017>
[pid  2818] 22:51:09 open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 25 <0.000015>
[pid  2818] 22:51:09 open("/usr/share/zoneinfo/Europe/Warsaw", O_RDONLY|O_CLOEXEC) = 25 <0.000016>

There are n * thousands of these. After few minutes GUI becomes usable.

I guess it could be similar problem as found previously in filepicker (#278899).

gdb trace:
Program received signal SIGINT, Interrupt.
0x00007fdeb545ded9 in timelocal () from /lib64/libc.so.6
(gdb) bt
#0  0x00007fdeb545ded9 in timelocal () from /lib64/libc.so.6
#1  0x00007fdeb603b1bc in KSystemTimeZoneBackend::offsetAtZoneTime(KTimeZone const*, QDateTime const&, int*) const () from /usr/lib64/libkdecore.so.5
#2  0x00007fdeb601f584 in ?? () from /usr/lib64/libkdecore.so.5
#3  0x00007fdeb601f8a4 in ?? () from /usr/lib64/libkdecore.so.5
#4  0x00007fdeb6025507 in KDateTime::secsTo_long(KDateTime const&) const () from /usr/lib64/libkdecore.so.5
#5  0x00007fdeb6025789 in KDateTime::secsTo(KDateTime const&) const () from /usr/lib64/libkdecore.so.5
#6  0x00007fdeb612401b in ?? () from /usr/lib64/libkdecore.so.5
#7  0x00007fdeb611e5c4 in KLocale::formatDateTime(KDateTime const&, KLocale::DateFormat, QFlags<KLocale::DateTimeFormatOption>) const ()
   from /usr/lib64/libkdecore.so.5
#8  0x00007fdeb4b95584 in KDirModel::data(QModelIndex const&, int) const () from /usr/lib64/libkio.so.5
#9  0x00007fdeb6b9b4dc in QSortFilterProxyModel::data(QModelIndex const&, int) const () from /usr/lib64/libQtGui.so.4
#10 0x00007fdeb4bb715e in KFileItemDelegate::Private::display(QModelIndex const&) const () from /usr/lib64/libkio.so.5
#11 0x00007fdeb4bb7a49 in KFileItemDelegate::Private::initStyleOption(QStyleOptionViewItemV4*, QModelIndex const&) const () from /usr/lib64/libkio.so.5
#12 0x00007fdeb4bbb3bb in KFileItemDelegate::sizeHint(QStyleOptionViewItem const&, QModelIndex const&) const () from /usr/lib64/libkio.so.5
#13 0x00007fdeb6b58b4b in QTreeView::sizeHintForColumn(int) const () from /usr/lib64/libQtGui.so.4
#14 0x00007fdeb6b2a0cf in ?? () from /usr/lib64/libQtGui.so.4
#15 0x00007fdeb39e32ed in ?? () from /usr/lib64/libkfile.so.4
#16 0x00007fdeb5bebb15 in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/libQtCore.so.4
#17 0x00007fdeb6ba27c4 in ?? () from /usr/lib64/libQtGui.so.4
#18 0x00007fdeb5bebb15 in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/libQtCore.so.4
#19 0x00007fdeb5c380f7 in QAbstractItemModel::dataChanged(QModelIndex const&, QModelIndex const&) () from /usr/lib64/libQtCore.so.4
#20 0x00007fdeb4b95a04 in KDirModel::itemChanged(QModelIndex const&) () from /usr/lib64/libkio.so.5
#21 0x00007fdeb3a0d610 in KFilePreviewGenerator::Private::dispatchIconUpdateQueue() () from /usr/lib64/libkfile.so.4
#22 0x00007fdeb3a0d774 in KFilePreviewGenerator::Private::resolveMimeType() () from /usr/lib64/libkfile.so.4
#23 0x00007fdeb5bf0cf6 in QObject::event(QEvent*) () from /usr/lib64/libQtCore.so.4
#24 0x00007fdeb65f8924 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /usr/lib64/libQtGui.so.4
#25 0x00007fdeb65fd7a5 in QApplication::notify(QObject*, QEvent*) () from /usr/lib64/libQtGui.so.4
#26 0x00007fdeb7361916 in KApplication::notify(QObject*, QEvent*) () from /usr/lib64/libkdeui.so.5
---Type <return> to continue, or q <return> to quit---
#27 0x00007fdeb5bd7e1c in QCoreApplication::notifyInternal(QObject*, QEvent*) () from /usr/lib64/libQtCore.so.4
#28 0x00007fdeb5bdb597 in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () from /usr/lib64/libQtCore.so.4
#29 0x00007fdeb5c06f13 in ?? () from /usr/lib64/libQtCore.so.4
#30 0x00007fdeb0dd742a in g_main_context_dispatch () from /usr/lib64/libglib-2.0.so.0
#31 0x00007fdeb0dd77f0 in ?? () from /usr/lib64/libglib-2.0.so.0
#32 0x00007fdeb0dd78b4 in g_main_context_iteration () from /usr/lib64/libglib-2.0.so.0
#33 0x00007fdeb5c07346 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4
#34 0x00007fdeb669b49e in ?? () from /usr/lib64/libQtGui.so.4
#35 0x00007fdeb5bd6be2 in QEventLoop::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4
#36 0x00007fdeb5bd6e37 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/libQtCore.so.4
#37 0x00007fdeb5bdba19 in QCoreApplication::exec() () from /usr/lib64/libQtCore.so.4
#38 0x00000000004097a1 in _start ()
Comment 1 Friedrich W. H. Kossebau 2012-04-02 19:29:22 UTC
Thanks for reporting. While Okteta ideally could also help with this problem by only creating the KDirModel if needed, this would only work-around the real problem, which seems KSystemTimeZoneBackend doing something that results in reading /etc/localtime and the zoneinfo file again and again, instead of caching the timezone or whatever could be done here. So pushing this bug over there.

Perhaps KDirModel/KFileItemDelegate could also be improved, as from the backtrace given KLocale::formatDateTime is only called on a new icon to be set due to the mimetype of a file being resolved.
Comment 2 Arkadiusz Miskiewicz 2012-04-02 20:05:09 UTC
David at #281360 is looking at optimizing KSystemTimeZone, so one approach is on the way.
Comment 3 Arkadiusz Miskiewicz 2012-04-12 08:23:40 UTC
Applied fix from bug #281360 but okteta still "hangs"  doing bunch of:


[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
[pid  4515] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
Comment 4 Michael Pyne 2012-04-12 20:00:07 UTC
Honestly I think it's as simple as having to go through the very slow path of KSystemTimeZoneBackend::offsetAtZoneTime(). By "very slow path" I mean KDateTime trying to display a formatted time in a different time zone than the time zone the program is running in.

POSIX does not give a good way to translate times between different time zones, so their documentation recommends changing the TZ environment variable and re-running the tzset() function. According to the tzzset documentation, it will typically read the /etc/localtime file if the TZ environment variable is set to ":" or if TZ is left unset.

Since KSystemTimeZone has to reset TZ to its original value (set or unset) after determining the offset to the requested time zone, it is possible that all the /etc/localtime stat() calls are due to unsetting TZ and then running tzset().

It might be possible to confirm this by running okteta from a shell:

$ export TZ=:Europe/Warsaw
$ okteta

(with TZ set to a colon (:) followed by whatever your time zone actually is).

If it turns out this is the problem the solution is either to not do the work (i.e. don't convert timezones just to show a date, which means look at the Locale settings to ensure your normal date format doesn't show any timezone or UTC offset info), or to do less work (perhaps this function doesn't need to be called at all for displaying a date, but I'm not able to follow the backtrace fully).

You may also want to look at your system timezone setting to make sure it matches the time zone setting you have set in your KDE Locale settings.
Comment 5 Arkadiusz Miskiewicz 2012-04-12 20:38:36 UTC
I'm using Europe/Warsaw timezone, "Country" is set to "Poland", "Languages" -> "American English", date format is "WEEKDAY DD MONTH YYYY" for long date and "DD/MM/YYYY" for short date. I'm not installing/using any l10n kde packages. Timezone setting in kde is "Europe/Warsaw (CEST)" which is consistent with what I have in /etc/localtime.

TZ=:Europe/Warsaw makes okteta no longer read /etc/localtime but it still takes like 30s to get GUI responsible (so it's A LOT faster than without such TZ setting but seems there is additional issue hidding here).
Comment 6 David Jarvie 2012-04-13 13:48:48 UTC
KSystemTimeZones has been changed so that it now returns KTzfileTimeZone instances, not KSystemTimeZone instances (see comments in bug 281360 for details). So comment #5 is not relevant - tzset() is no longer used by KDE classes. (Note that /etc/localtime isn't being opened multiple times any longer - it's only being stat()'ed - so it can't be tzset() which is responsible.)

If the /etc/localtime accesses are from KDateTime, I suspect that the culprit may be QDateTime::currentDateTime(), or even the libc time() function, which are called by KDateTime::currentDateTime(), currentLocalDateTime() and currentUtcDateTime(). Alternatively, the accesses may not be from KDateTime at all (I haven't looked at the Okteta code, so I don't know).

One change which could make a significant improvement would be to minimise the number of times the current date/time is fetched, by whatever method. If it is needed more than once inside a function, or if it is used in multiple functions which are called from one another, it's a good idea to fetch it only once and save its value in a variable, passing it to other functions where possible.
Comment 7 Christoph Feck 2012-05-19 03:15:13 UTC
When I compile kdelibs in debug mode, simply starting okteta results in hundreds of lines "-> No cache" and "-> Using cache". I guess either the cache isn't effective (it should only show the "No cache" once), or okteta is somehow querying different data all the time, so that the cached values are not of any use.
Comment 8 David Jarvie 2012-05-20 21:57:30 UTC
The "No cache" and "Using cache" messages indicate whether the cached value in a time zone instance is being used or not. When a date/time value is converted to/from UTC, the cached time zone transition information is used (i.e. "Using cache") if the value is in the same year and summer/winter time state as the last value converted. This saves significant processing. If they are in different years or different summer/winter-time state, the time zone offset must be recalculated (i.e. "No cache").
Comment 9 Andrew Crouthamel 2018-11-09 01:04:28 UTC
Dear Bug Submitter,

This bug has been stagnant for a long time. Could you help us out and re-test if the bug is valid in the latest version? I am setting the status to NEEDSINFO pending your response, please change the Status back to REPORTED when you respond.

Thank you for helping us make KDE software even better for everyone!
Comment 10 Andrew Crouthamel 2018-11-20 04:08:30 UTC
Dear Bug Submitter,

This is a reminder that this bug has been stagnant for a long time. Could you help us out and re-test if the bug is valid in the latest version? This bug will be moved back to REPORTED Status for manual review later, which may take a while. If you are able to, please lend us a hand.

Thank you for helping us make KDE software even better for everyone!
Comment 11 Justin Zobel 2023-01-02 02:04:21 UTC
Thank you for reporting this issue in KDE software. As it has been a while since this issue was reported, can we please ask you to see if you can reproduce the issue with a recent software version?

If you can reproduce the issue, please change the status to "REPORTED" when replying. Thank you!
Comment 12 David Jarvie 2023-01-05 17:39:09 UTC
As far as I can see, since the time this bug was reported okteta has had no direct calls to KDateTime or KTimeZone, and the dependency on these classes was via KDirModel in kio. On the assumption that frameworks/kio no longer links to kdelibs4support, okteta will no longer use KDateTime directly or indirectly, so this bug will not occur any more.
Comment 13 Bug Janitor Service 2023-01-20 05:07:47 UTC
Dear Bug Submitter,

This bug has been in NEEDSINFO status with no change for at least
15 days. Please provide the requested information as soon as
possible and set the bug status as REPORTED. Due to regular bug
tracker maintenance, if the bug is still in NEEDSINFO status with
no change in 30 days the bug will be closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

If you have already provided the requested information, please
mark the bug as REPORTED so that the KDE team knows that the bug is
ready to be confirmed.

Thank you for helping us make KDE software even better for everyone!
Comment 14 Bug Janitor Service 2023-02-04 04:58:55 UTC
This bug has been in NEEDSINFO status with no change for at least
30 days. The bug is now closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

Thank you for helping us make KDE software even better for everyone!