significant performance regression in 1.9.0 DOM access

[smemsh]

I have a script that computes how long I've been doing a contiguous interval (of different tasks). I have this bound to a key in my window manager to display a total, so I can see "how long since my last break?" It goes back looking at dom.tracked.N.start and .end until it finds a break. Then it does a sum of dom.tracked.{1..<break>}.duration.

This (and several other scripts I have) are now taking much longer with 1.9.0, here seen with just the last 10 intervals:

 $ for binary in timew1{8,9}0
   do echo $binary:; time -p $binary get \
     dom.tracked.{1..10}.{start,end,duration} \
   >/dev/null; echo; done

timew180:
real 0.89
user 0.85
sys 0.01

timew190:
real 8.14
user 2.97
sys 5.13

Yikes... 4x user time and 513x increase in kernel time! These were built with CMAKE_BUILD_TYPE=relwithdebinfo build flags which appear to be -g -O2 -DNDEBUG.

I'm frequently switching tasks through key-bound actions and menus, and getting sums for day, week, certain tags, etc and while in some cases I'm computing this myself from an export, in other cases I'm relying on the DOM access calculations. So, this has quite a deleterious/laggy effect on workflow...

Looks like the problem is I/O changes, here syscall time for above commands, anything over 1%:

180:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 20.05    0.000230           0       267         2 access
 19.09    0.000219           1       189        36 newfstatat
 16.04    0.000184           1       176           read
 15.17    0.000174           4        40           fdatasync
  9.33    0.000107           0       134        44 openat
  6.54    0.000075           0        90           close
  6.54    0.000075          15         5           munmap
  2.62    0.000030           1        30           brk
  2.35    0.000027           6         4           getdents64
  1.31    0.000015           0        26           mmap

190:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 36.51    5.648562           1   3341889        36 newfstatat
 23.04    3.564769           1   2227976           read
 19.09    2.953615           2   1114034        44 openat
 11.79    1.823148           1   1113990           close
  9.55    1.477241           1   1113901           lseek

Amazing, millions of I/Os in the new DOM code! I think it's a bug ;-)

[smemsh]

hmm, thought these opens would be the db files but it's timezone stuff:

 $ strace -fe newfstatat,openat timew190 get dom.tracked.1.start \
   |& field -P \" 2 | sort | uniq -c | sort -nrk 1,2 | head
  37211 /etc/localtime
  37130 /usr/share/zoneinfo/UTC
      3 /home/scott/.task/timewarrior.cfg
      3 /home/scott/.task/data/2025-08.data
      3 /home/scott/.task/data/2025-07.data
      3 /home/scott/.task/data/2025-06.data
      3 /home/scott/.task/data/2025-05.data
      3 /home/scott/.task/data/2025-04.data
      3 /home/scott/.task/data/2025-03.data
      3 /home/scott/.task/data/2025-02.data

[smemsh]

The regression is in libshared, this commit:

5cb49e6 Move timegm implementation out of Taskwarrior into libshared (#99)

the UTC timezone paths were what hinted me, I follow those libshared commits (asynchronously, when I can catch up...) and remembered seeing something about a gmtime...

Building 1.9.0 with the prior libshared commit 8ad3646 just before that patch restores timewarrior performance. So it's not your DOM code @lauft ;-)

[smemsh]

Summarizing from over there in GothenburgBitFactory/libshared#104:

Need to make the libshared build use system timegm() rather than slow fallback in codebase. Cmake needs to define HAVE_TIMEGM in a way that's actually used by the libshared build within Timewarrior. Doing it in src/libshared/CMakeLists.txt is ignored and doing it in timewarrior CMakeLists.txt -- while it works and is recognized and put into timewarrior cmake.h -- is not carried into build of the libshared submodule.

Doing it manually with a -DHAVE_TIMEGM in CXXFLAGS does work, and fixes the performance regression.

So, need help from someone with some cmake-fu, I could not get it to work...

[tobiolo]

Hello @smemsh
Thanks for your investigation into this issue.
In my opinion, libshared should be configured and built as a CMake subproject. I proposed a Pull Request.
Now I also get the messages during the CMake configuration that indicate that the system functions are checked.
#704

[smemsh]

@tobiolo I tried your branch, but the symbol is still there:

 $ nm -C src/timew | grep timegm
                 U timegm@GLIBC_2.2.5
00000000000b5db0 T Datetime::timegm(tm*)

the symbol is not present when using manual -DCXXFLAGS method, only the glibc reference.

I had done make clean and then rm -rf CMakeFiles CMakeCache.txt cmake.h commit.h cmake_install.cmake install_manifest.txt in all of root, src, src/libshared, src/libshared/src prior to switching branches and rebuilding.

[smemsh]

Note also that even a standalone build of libshared still has this symbol defined:

 $ cd `mktemp -d` &&
   git clone -q https://github.com/GothenburgBitFactory/libshared &&
   cd libshared &&
   (cmake -DCMAKE_BUILD_TYPE=relwithdebinfo . && make -j4) &>/dev/null &&
   nm -C src/libshared.a |
   grep timegm
0000000000006120 T Datetime::timegm(tm*)

[smemsh]

I noticed that src/libshared/src/Datetime.{h,cpp} do not include cmake.h, so it will never pick it up, even if we fix cmake.

How about this for libshared:

--- a/src/Datetime.h
+++ b/src/Datetime.h
@@ -32,6 +32,8 @@
 #include <cstdint>
 #include <string>
 
+#include "cmake.h"
+
 #define EPOCH_MIN_VALUE 315532800    // 1980-01-01T00:00:00Z
 #define EPOCH_MAX_VALUE 253402293599 // 9999-12-31, 23:59:59 AoE

And then in timewarrior:

--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -6,8 +6,9 @@ set (HAVE_CMAKE true)
 project (timew)
 include (CXXSniffer)
 include (FindAsciidoctor)
+include (CheckFunctionExists)
 
set (PROJECT_VERSION "1.9.0-dev")
 
 string(TOUPPER "${CMAKE_BUILD_TYPE}" uppercase_CMAKE_BUILD_TYPE)
 
@@ -45,6 +46,9 @@ endif (FREEBSD OR DRAGONFLY)
 set (TIMEW_DOCDIR share/doc/timew CACHE STRING "Installation directory for doc files")
 set (TIMEW_BINDIR bin             CACHE STRING "Installation directory for Timewarrior executable")
 
+check_function_exists(strlcpy HAVE_STRLCPY)
+check_function_exists(timegm  HAVE_TIMEGM)
+
 message ("-- Configuring cmake.h")
 configure_file (${CMAKE_SOURCE_DIR}/cmake.h.in
                 ${CMAKE_SOURCE_DIR}/cmake.h)

Seems to work, although it's not a proper subproject in cmake, but it fixes the build and treats it same as before.

What do you think @tobiolo? Should we do your subproject idea also at the same time as adding the cmake.h include in libshared? Or just hack it minimally, like this?

[smemsh]

also note, I did confirm, the inclusion of cmake.h does fix standalone libshared build also (it already had correct stanza in its own CMakeLists.txt, just wasn't including cmake.h). but it doesn't fix timewarrior build without the additional timewarrior root cmake change.

[tobiolo]

I think that we should continue with your approach. I reached a dead end with the subdirectory approach because (I think that) the same cmake.h would be configured twice for timewarrior and for the libshared as $CMAKE_SOURCE_DIR/cmake.h.in in the configure_file command is always the top level cmake.h.in in the timewarrior source tree. The documentation says that it is assumed that there is only one valid cmake.h file and that should be the one on the top level so I think that your approach fits more with the general approach here.

[smemsh]

I'm sure there's some proper way to do it, but I don't care about it enough to figure it out, unless @lauft thinks we should.

Likewise I think the fallback function shouldn't be doing tzset() but it won't affect me (only Windows I think?) so I'm not going to bother.

I'll make the PRs in both repos with above changes, then. If you want to instead, that's ok also. Thanks for your help!

[tobiolo]

Thanks for your help and your effective fix! I am looking forward to see your pull requests!

[lauft]

Thanks @smemsh and @tobiolo for your efforts. 👍🏻

I think I will revert commit GothenburgBitFactory/libshared@2aa844c GothenburgBitFactory/libshared@5cb49e6 and create a bugfix release.