[Bug libc/5184] New: strftime stats /etc/localtime too much

[Bug libc/5184] New: strftime stats /etc/localtime too much

[adi at hexapodia dot org]

Running "2.3.6.ds1-8" from Debian unstable on x86_64, the following is observed
using strace:

...
open("/etc/localtime", O_RDONLY)        = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x2b47ac40b000
read(3, "TZif\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0"..., 4096) = 1017
close(3)                                = 0
munmap(0x2b47ac40b000, 4096)            = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
time(NULL)                              = 1192500153
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
exit_group(0)                           = ?
Process 9465 detached
adi@xxxxx:~/tmp$ cat strftime-stats.c
#include <time.h>

int main(void)
{
    char buf[40];
    time_t now;
    
    now = time(0);
    strftime(buf, sizeof(buf), "%F %T", localtime(&now));
    now = time(0);
    strftime(buf, sizeof(buf), "%F %T", localtime(&now));
    return 0;
}

It appears that strftime is stat(2)ing /etc/localtime for every date component.
This could result in an inconsistent date representation being generated if it
races with an update to /etc/localtime.  If /etc/localtime is updated atomically
using rename(2), strftime should generate a date entirely using the old data or
entirely using the new, not a partial mix.  Even ignoring modifications to
/etc/localtime, this is certainly a performance bug (6 stats instead of one).

-- 
           Summary: strftime stats /etc/localtime too much
           Product: glibc
           Version: 2.3.6
            Status: NEW
          Severity: normal
          Priority: P2
         Component: libc
        AssignedTo: drepper at redhat dot com
        ReportedBy: adi at hexapodia dot org
                CC: glibc-bugs at sources dot redhat dot com


http://sourceware.org/bugzilla/show_bug.cgi?id=5184

------- You are receiving this mail because: -------
You are on the CC list for the bug, or are watching someone who is.

[Bug libc/5184] strftime stats /etc/localtime too much

[drepper at redhat dot com]

------- Additional Comments From drepper at redhat dot com  2007-10-16 05:44 -------
No, /etc/localtime is not touched too often.  All the time functions are
required to check TZ all the time.  Missing that envvar, /etc/localtime is used.
 People who move laptops from one timezone to the other appreciate that.

If this is no problem of yours just set TZ to /etc/localtime and all this will stop.

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |INVALID


http://sourceware.org/bugzilla/show_bug.cgi?id=5184

------- You are receiving this mail because: -------
You are on the CC list for the bug, or are watching someone who is.

[Bug libc/5184] strftime stats /etc/localtime too much

[jakub at redhat dot com]

------- Additional Comments From jakub at redhat dot com  2007-10-16 08:13 -------
I think the complaint in this case is that strftime, instead of doing tzset
just once, does it 5 times.
#include <time.h>

#define DBG(str) write (-1, str, sizeof (str) - 1)

int
main (void)
{
  char buf[40];
  time_t now;
  struct tm *tmp;

  now = time (0);
  tmp = localtime (&now);
  strftime (buf, sizeof (buf), "%F %T", tmp);
  DBG ("before time");
  now = time (0);
  DBG ("before localtime");
  tmp = localtime (&now);
  DBG ("before strftime");
  strftime (buf, sizeof (buf), "%F %T", tmp);
  DBG ("after strftime");
  return 0;
}

strace ./Y # against CVS glibc
...
write(4294967295, "before time", 11)    = -1 EBADF (Bad file descriptor)
write(4294967295, "before localtime", 16) = -1 EBADF (Bad file descriptor)
write(4294967295, "before strftime", 15) = -1 EBADF (Bad file descriptor)
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2246, ...}) = 0
write(4294967295, "after strftime", 14) = -1 EBADF (Bad file descriptor)

That is IMHO easily fixable with some rearrangments of strftime_l.c - changing
the my_strftime function to an an internal helper with an additional argument,
writing a tiny wrapper and not calling tzset () if it has been called already by
an outer strftime in case of recursion.

BTW, doesn't localtime have to stat /etc/localtime?
http://www.opengroup.org/onlinepubs/009695399/functions/localtime.html
Local timezone information is used as though localtime() calls tzset().

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=5184

------- You are receiving this mail because: -------
You are on the CC list for the bug, or are watching someone who is.

[Bug libc/5184] strftime stats /etc/localtime too much

[adi at hexapodia dot org]

------- Additional Comments From adi at hexapodia dot org  2007-10-16 08:33 -------
(In reply to comment #2)
> I think the complaint in this case is that strftime, instead of doing tzset
> just once, does it 5 times.

Indeed, thanks.

> BTW, doesn't localtime have to stat /etc/localtime?
> http://www.opengroup.org/onlinepubs/009695399/functions/localtime.html
> Local timezone information is used as though localtime() calls tzset().

I noticed that too, and opened #5186.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=5184

------- You are receiving this mail because: -------
You are on the CC list for the bug, or are watching someone who is.

[Bug libc/5184] strftime stats /etc/localtime too much

[mann at vmware dot com]

------- Additional Comments From mann at vmware dot com  2008-08-13 00:22 -------
Why is strftime special?  If I write a program that repeatedly calls ctime()
and/or localtime(), it reads /etc/localtime only once.  But if I call strftime,
it reads /etc/localtime once for each call to strftime.  TZ is not set in my
environment.  This behavior is inconsistent with the claim that "All the time
functions are required to check TZ all the time.  Missing that envvar,
/etc/localtime is used."  Surely localtime and ctime are included in the set
"All the time functions."

Reading this file on every call is pretty ugly for programs that write log
messages and include a timestamp on each line formatted using strftime.

I'm using libc 2.6.1-1ubuntu10, from Ubuntu 7.10 on x86_64.

Here's a sample program to demonstrate.  Run it with no arguments and it will
open and read /etc/localtime 11 times.

#include <stdio.h>
#include <sys/time.h>
#include <time.h>

int
main(int argc, char **argv)
{
   int count = 10, i;

   if (argc > 1) {
      count = atoi(argv[1]);
   }

   for (i = 0; i < count; i++) {
      time_t now = time(NULL);
      printf("%s", ctime(&now));
   }

   for (i = 0; i < count; i++) {
      time_t now = time(NULL);
      struct tm ltime;

      localtime_r(&now, &ltime);
      printf("%02u:%02u:%02u\n", ltime.tm_hour, ltime.tm_min, ltime.tm_sec);
   }

   for (i = 0; i < count; i++) {
      time_t now = time(NULL);
      struct tm ltime;
      char stime[1024];

      localtime_r(&now, &ltime);
      strftime(stime, sizeof(stime), "%H:%M:%S", &ltime);
      printf("%s\n", stime);
   }
}


-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|INVALID                     |


http://sourceware.org/bugzilla/show_bug.cgi?id=5184

------- You are receiving this mail because: -------
You are on the CC list for the bug, or are watching someone who is.

[Bug libc/5184] strftime stats /etc/localtime too much

[mann at vmware dot com]

------- Additional Comments From mann at vmware dot com  2008-08-13 00:27 -------
Sorry, I'm on drugs...  My sample program causes /etc/localtime to be opened and
read only once, but stat'ed 10 times.  The stat isn't so bad, but still costs
something that users may need to be aware of.

Also, it looks like bug 5186 is saying that localtime should also be stat'ing
/etc/localtime every time.  

If that's where things are going, I guess it's just another performance trap to
be wary of, and we can avoid it by setting TZ if we're OK with our programs not
dynamically tracking changes to /etc/localtime.


-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|REOPENED                    |RESOLVED
         Resolution|                            |INVALID


http://sourceware.org/bugzilla/show_bug.cgi?id=5184

------- You are receiving this mail because: -------
You are on the CC list for the bug, or are watching someone who is.