How to avoid excessive stat(/etc/localtime) calls in strftime() on linux?

Question

I left a record processing program of mine running for a few minutes under strace.

This showed in those minutes over 200 000 000 calls to stat("/etc/localtime",..) which sounds a bit excessive and unneeded.

The strace output looks like this:

write(1, "C137015 393393093052629137110 47"..., 16384) = 16384 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0 read(0, "\224q\1\207\0\0\202\1\4\203\1\4\204\1\1\205\1\1\206\1\7\207\1\6\211\1\22\212\1\22\213\1"..., 16384) = 16384 

Essentially it turned out to be 1 stat() call for every record processed and the culprit turned out to be this quite ordinary line of code

strftime(call->date_time,DATELEN,"%Y%m%d %H%M%S",&tm_buf); 

So - how can I avoid strftime() calling stat(/etc/localtime) at every call?

Answer 1

It might be doing that because your timezone isn't set. strftime queries /etc/localtime to find it.

Try setting the TZ environment variable.

Here's a link for that behavior.

Answer 2

With GNU libc library, here is another tip to solve this when /etc/localtime is not configured (this is often the case on tiny embedded systems). This consists to set TZ environment variable to the empty string. This makes the library default to the UTC.

Here is an example strace output on some embedded system calling a logging function which calls localtime() and strftime() when neither /etc/localtime nor TZ are set. With glibc 2.23, this triggers several unsuccessful calls to "openat(/etc/localtime)":

[...] [pid 200113] gettid() = 200113 [pid 200113] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) [pid 200113] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) [pid 200113] gettid() = 200113 [pid 200113] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) [pid 200113] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) [pid 200113] getpid() = 200113 [pid 200113] writev(4, [{iov_base="DUH\1\1\0\0\0", iov_len=8}, {iov_base="=\2\0\261ECU1\0\3\r\261\r\32\265\3431\2SWMCSWMC", iov_len=26}, {iov_base="\0\2\0\0'\0Tue Mar 1 13:49:20 2022 _"..., iov_len=151}], 3) = 185 [pid 200113] gettid() = 200113 [pid 200113] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) [pid 200113] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) [pid 200113] gettid() = 200113 [...] 

And here is the same program's output with strace when TZ is set to the empty string:

$ export TZ= [...] [pid 201837] gettid() = 201837 [pid 201837] gettid() = 201837 [pid 201837] getpid() = 201837 [pid 201837] writev(4, [{iov_base="DUH\1\1\0\0\0", iov_len=8}, {iov_base="=\2\0\261ECU1\0\3\24m\r7\253\3171\2SWMCSWMC", iov_len=26}, {iov_base="\0\2\0\0'\0Tue Mar 1 13:52:30 2022 _"..., iov_len=151}], 3) = 185 [pid 201837] gettid() = 201837 [pid 201857] <... read resumed>"DUH\1\f\0\0\0\0DUH\1\6\0\0\0\5\0\0\0\0\0DUH\1\6\0\0\0\5"..., 10024) = 37 [pid 201837] gettid( <unfinished ...> [pid 201857] read(3, <unfinished ...> [pid 201837] <... gettid resumed>) = 201837 [pid 201837] getpid() = 201837 [pid 201837] writev(4, [{iov_base="DUH\1\1\0\0\0", iov_len=8}, {iov_base="=\3\0\257ECU1\0\3\24m\r7\253\364A\2SWMCSWMC", iov_len=26}, {iov_base="\0\2\0\0'\0Tue Mar 1 13:52:30 2022 _"..., iov_len=149}], 3) = 183 [...] 

N.B.: Here is the corresponding glibc's source code snippet in time/tzset.c which sets UTC when TZ is empty:

/* Interpret the TZ envariable. */ static void internal_function tzset_internal (int always, int explicit) {  static int is_initialized;  const char *tz; if (is_initialized && !always)  return;  is_initialized = 1; /* Examine the TZ environment variable. */  tz = getenv ("TZ");  if (tz == NULL && !explicit)  /* Use the site-wide default. This is a file name which means we  would not see changes to the file if we compare only the file  name for change. We want to notice file changes if tzset() has  been called explicitly. Leave TZ as NULL in this case. */  tz = TZDEFAULT;  if (tz && *tz == '\0')  /* User specified the empty string; use UTC explicitly. */  tz = "Universal"; [...]