[php-maint] Bug#618462: php5: Large quantities of timezone file stat() calls causing possible regression

[Erik Jacobson]

Package: php5
Version: 5.3.10-1
Severity: normal


Hi, while trying to narrow down possible causes of Apache child wait
states, I came across this possible issue with PHP apparently calling
stat() against the system timezone files repeatedly.  This bug seems to
be primarily with tz init/searching looking at *all* the timezone files
with a question as to if it's a performance impact.

My issue is related but slightly different.

On a loaded server with ~150 php page requests a second, I was showing
an unusual amount of stat() calls in a child strace like so:


www-data 27168  0.7  0.1 321968 21780 ?        SN   13:04   0:02  \_ /usr/sbin/apache2 -k start 

# strace -p 27168  -f -c 
Process 27168 attached - interrupt to quit 
  
^CProcess 27168 detached 
% time     seconds  usecs/call     calls    errors syscall 
------ ----------- ----------- --------- --------- ---------------- 
 33.95    0.042694           3     12898       375 stat 
 25.95    0.032636           1     42586           select 
  6.68    0.008394           3      2893           munmap 
  5.15    0.006479           0     21928           sendto  

Doing an strace dump and analyzing the stat calls pointed some at htaccess and include path
searches, but the vast majority were calls like so:

stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0 
stat("/usr/share/zoneinfo/America/New_York", {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0

The above block of calls were contiguous, all in less then a second.
Blocks like the above seem to roll through more then once a minute, and
individual stat() calls to the same file seem to appear once every 10-20
syscalls. The above identical lookup is the vast majority of the listed
stat calls in strace.

This is in a SINGLE child thread, out of *hundreds* of active threads. 
The end result is thousands of stat calls a second.. To the same file.
Which never changes. And is never cached in APC. I haven't been able 
to test the above load with switching to UTC and hoping it doesn't 
try to lookup the file, as our current setup relies on local time for
certain operations (ugh).

I'm currently recompiling PHP to take advantage of their timezonedb lib,
and hoping it keeps everything in ram.  Either that or I put the
timezone directory in a ramdisk and hoping for the best.


-- System Information:
Debian Release: 6.0
  APT prefers unstable
  APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)

Kernel: Linux 2.6.32-5-amd64 (SMP w/4 CPU cores)

Versions of packages php5 depends on:
ii  libapache2-mod-php5           5.3.10-1   server-side, HTML-embedded scripti
ii  php5-common                   5.3.10-1   Common files for packages built fr

php5 recommends no packages.

php5 suggests no packages.

-- no debconf information