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: