http://bugzilla.opensuse.org/show_bug.cgi?id=1182834 Bug ID: 1182834 Summary: glibc: bad performance calling localtime() when TZ env var not ser Classification: openSUSE Product: openSUSE Tumbleweed Version: Current Hardware: Other OS: Other Status: NEW Severity: Normal Priority: P5 - None Component: Basesystem Assignee: screening-team-bugs@suse.de Reporter: dfaggioli@suse.com QA Contact: qa-bugs@suse.de Found By: --- Blocker: --- The other day, by pure coincidence, I run into this: https://bugzilla.redhat.com/show_bug.cgi?id=1608367#c7 It's basically about making sure that the TZ env variable is defined, to avoid doing syscalls for stat-ing /etc/localtime. Out of curiosity, I checked on my openSUSE and SLE systems, and we seem not to have it there (or is it just my installations?). I went on, and run the quick experiments suggested in the bugreport. Here's me on openSUSE Tumbleweed: $ gcc -Wall -O2 time_vdso.c -o time_vdso $ ldd time_vdso linux-vdso.so.1 (0x00007fff71fde000) libc.so.6 => /lib64/libc.so.6 (0x00007f2e3a774000) /lib64/ld-linux-x86-64.so.2 (0x00007f2e3a95e000) $ echo "TZ currently is: " $TZ TZ currently is: $ time ./time_vdso real 0m6,687s user 0m1,569s sys 0m5,118s $ strace -c ./time_vdso % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100,00 25,410273 5 5000003 newfstatat 0,00 0,000000 0 3 read 0,00 0,000000 0 3 close 0,00 0,000000 0 1 lseek 0,00 0,000000 0 8 mmap 0,00 0,000000 0 3 mprotect 0,00 0,000000 0 1 munmap 0,00 0,000000 0 3 brk 0,00 0,000000 0 4 pread64 0,00 0,000000 0 1 1 access 0,00 0,000000 0 1 execve 0,00 0,000000 0 2 1 arch_prctl 0,00 0,000000 0 3 openat ------ ----------- ----------- --------- --------- ---------------- 100,00 25,410273 5 5000036 2 total On the other hand, after having done an `export TZ=Europe/Rome`: $ echo "TZ currently is: " $TZ TZ currently is: Europe/Rome $ time ./time_vdso real 0m0,845s user 0m0,845s sys 0m0,000s $ strace -c ./time_vdso % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0,00 0,000000 0 3 read 0,00 0,000000 0 3 close 0,00 0,000000 0 1 lseek 0,00 0,000000 0 8 mmap 0,00 0,000000 0 3 mprotect 0,00 0,000000 0 1 munmap 0,00 0,000000 0 3 brk 0,00 0,000000 0 4 pread64 0,00 0,000000 0 1 1 access 0,00 0,000000 0 1 execve 0,00 0,000000 0 2 1 arch_prctl 0,00 0,000000 0 3 openat 0,00 0,000000 0 4 newfstatat ------ ----------- ----------- --------- --------- ---------------- 100,00 0,000000 0 37 2 total I tried on a pretty freshly deployed SLE 15.3 too, this time using /usr/bin/time, just for a change and... /usr/bin/time ./time_vdso 2.36user 7.65system 0:10.02elapsed 99%CPU (0avgtext+0avgdata 1284maxresident)k 0inputs+0outputs (0major+62minor)pagefaults 0swaps TZ=Europe/Rome /usr/bin/time ./time_vdso 0.89user 0.00system 0:00.89elapsed 99%CPU (0avgtext+0avgdata 1504maxresident)k 0inputs+0outputs (0major+68minor)pagefaults 0swaps So, again, the high 'system' value confirms we're drowning in syscalls. Of course, this is a typical micro-benchmark and results should be interpreted as such. I mean, real programs do not sample the time _all_the_time_ in super-tight loops. And indeed, benchmarks and time-sensitive applications will use things like clock_gettime() for measuring time intervals, interact with timers, etc. Still, localtime()/time() are probably pretty popular when it comes to logging (e.g., on webservers... and in fact, I gave a quick look at the code of ngnix, and they're there). Surely excessive logging would be bad for other reasons, but I think that something like this means that even "normal logging" has more impact on performance than it could/should have. -- You are receiving this mail because: You are on the CC list for the bug.