Bug 5184 - strftime stats /etc/localtime too much
Summary: strftime stats /etc/localtime too much
Status: RESOLVED INVALID
Alias: None
Product: glibc
Classification: Unclassified
Component: libc (show other bugs)
Version: 2.3.6
: P2 normal
Target Milestone: ---
Assignee: Ulrich Drepper
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-10-16 02:25 UTC by Andy Isaacson
Modified: 2014-07-04 07:19 UTC (History)
1 user (show)

See Also:
Host:
Target:
Build:
Last reconfirmed:
fweimer: security-


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Andy Isaacson 2007-10-16 02:25:04 UTC
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).
Comment 1 Ulrich Drepper 2007-10-16 05:44:58 UTC
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.
Comment 2 Jakub Jelinek 2007-10-16 08:13:46 UTC
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().
Comment 3 Andy Isaacson 2007-10-16 08:33:56 UTC
(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.
Comment 4 Tim Mann 2008-08-13 00:22:51 UTC
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);
   }
}
Comment 5 Tim Mann 2008-08-13 00:27:45 UTC
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.