Bug 730078

Summary: httpd process hang in futex() - from __tz_convert
Product: Red Hat Enterprise Linux 6 Reporter: Orion Poplawski <orion>
Component: phpAssignee: Remi Collet <rcollet>
Status: CLOSED WONTFIX QA Contact: BaseOS QE - Apps <qe-baseos-apps>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.1CC: prc, rcollet, syeghiay
Target Milestone: rc   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-09-27 13:45:26 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Orion Poplawski 2011-08-11 17:39:01 UTC
Description of problem:

This may be a glibc or other issue, but I'll start with the affected component.  I'm seeing httpd process get stuck in futex():

# strace -fp 30585
Process 30585 attached - interrupt to quit
futex(0x516a8c, FUTEX_WAIT_PRIVATE, 2, NULL^C <unfinished ...>
Process 30585 detached

gdb shows:
(gdb) bt
#0  0x00289416 in __kernel_vsyscall ()
#1  0x00475b23 in __lll_lock_wait_private ()
    at ../nptl/sysdeps/unix/sysv/linux/i386/i486/lowlevellock.S:95
#2  0x00417c8b in _L_lock_2223 () at tzset.c:138
#3  0x00417a91 in __tz_convert (timer=0xbf88d8dc, use_localtime=1, tp=0xbf88d8b0)
    at tzset.c:619
#4  0x00415dec in __localtime_r (t=0xbf88d8dc, tp=0xbf88d8b0) at localtime.c:33
#5  0x0072bf12 in explode_time (xt=0xbf88da14, t=1313051033067883, offset=0, use_localtime=1)
    at time/unix/time.c:90
#6  0x0072bf4c in apr_time_exp_lt (result=0xbf88da14, input=1313051033067883)
    at time/unix/time.c:133
#7  0x00b065b3 in cached_explode (xt=0xbf88da14, t=1313051033067883, cache=0xb2afe0, use_gmt=0)
    at /usr/src/debug/httpd-2.2.15/server/util_time.c:120
#8  0x00b0698a in ap_explode_recent_localtime (tm=0xbf88da14, t=1313051033067883)
    at /usr/src/debug/httpd-2.2.15/server/util_time.c:137
#9  0x00b069d6 in ap_recent_ctime (date_str=0xbf88fadd "", t=1313051033067883)
    at /usr/src/debug/httpd-2.2.15/server/util_time.c:158
#10 0x00b03156 in log_error_core (
    file=0x58dbe90 "/builddir/build/BUILD/php-5.3.3/sapi/apache2handler/sapi_apache2.c", 
    line=326, level=3, status=0, s=0x1b728d8, c=<value optimized out>, r=0x1f0a018, pool=0x0, 
    fmt=0x58c6daa "%s", args=0xbf891b68 "\244\025\237\266")
    at /usr/src/debug/httpd-2.2.15/server/log.c:578
#11 0x00b03fc2 in ap_log_rerror (
    file=0x58dbe90 "/builddir/build/BUILD/php-5.3.3/sapi/apache2handler/sapi_apache2.c", 
    line=326, level=3, status=0, r=0x1f0a018, fmt=0x58c6daa "%s")
    at /usr/src/debug/httpd-2.2.15/server/log.c:737
#12 0x05891d5d in ?? () from /etc/httpd/modules/libphp5.so
#13 0x057ad63c in php_log_err () from /etc/httpd/modules/libphp5.so
#14 0x057adae1 in ?? () from /etc/httpd/modules/libphp5.so
#15 0x0580413a in zend_error () from /etc/httpd/modules/libphp5.so
#16 0x057f6f5b in zend_timeout () from /etc/httpd/modules/libphp5.so
#17 <signal handler called>
#18 0x00289416 in __kernel_vsyscall ()
#19 0x004558a3 in __read_nocancel () at ../sysdeps/unix/syscall-template.S:82
#20 0x003f337b in _IO_new_file_underflow (fp=0x1f19358) at fileops.c:598
#21 0x003f67ea in __underflow (fp=0x1f19358) at genops.c:361
#22 0x003f2ca0 in _IO_file_xsgetn (fp=0x1f19358, data=0xbf892428, n=44) at fileops.c:1437
#23 0x003f50e8 in _IO_sgetn (fp=0x1f19358, data=0xbf892428, n=44) at genops.c:500
#24 0x003f1e99 in fread_unlocked (buf=0xbf892428, size=44, count=1, fp=0x1f19358)
    at iofread_u.c:45
#25 0x004184fa in __tzfile_read (file=<value optimized out>, extra=0, extrap=0x0)
    at tzfile.c:205
#26 0x00417968 in tzset_internal (always=<value optimized out>, explicit=<value optimized out>)
    at tzset.c:439
#27 0x00417bed in __tzset () at tzset.c:592
#28 0x0573f817 in ?? () from /etc/httpd/modules/libphp5.so
#29 0x058128b7 in zend_hash_del_key_or_index () from /etc/httpd/modules/libphp5.so
#30 0x0573f4e3 in ?? () from /etc/httpd/modules/libphp5.so
#31 0x05854959 in ?? () from /etc/httpd/modules/libphp5.so
#32 0x0582b38e in execute () from /etc/httpd/modules/libphp5.so
#33 0x05803a06 in zend_execute_scripts () from /etc/httpd/modules/libphp5.so
#34 0x057aa786 in php_execute_script () from /etc/httpd/modules/libphp5.so
#35 0x05892ec3 in ?? () from /etc/httpd/modules/libphp5.so
#36 0x00afe401 in ap_run_handler (r=0x1f0a018)
    at /usr/src/debug/httpd-2.2.15/server/config.c:158
#37 0x00b02186 in ap_invoke_handler (r=0x1f0a018)
    at /usr/src/debug/httpd-2.2.15/server/config.c:376
#38 0x00b0eec8 in ap_process_request (r=0x1f0a018)
    at /usr/src/debug/httpd-2.2.15/modules/http/http_request.c:282
#39 0x00b0b9a8 in ap_process_http_connection (c=0x1efd798)
    at /usr/src/debug/httpd-2.2.15/modules/http/http_core.c:190
#40 0x00b06c91 in ap_run_process_connection (c=0x1efd798)
    at /usr/src/debug/httpd-2.2.15/server/connection.c:43
#41 0x00b1431a in child_main (child_num_arg=<value optimized out>)
---Type <return> to continue, or q <return> to quit---
    at /usr/src/debug/httpd-2.2.15/server/mpm/prefork/prefork.c:667
#42 0x00b146ae in make_child (s=<value optimized out>, slot=0)
    at /usr/src/debug/httpd-2.2.15/server/mpm/prefork/prefork.c:763
#43 0x00b14ab2 in startup_children (_pconf=0x1a450b8, plog=0x1a73170, s=0x1a46fb0)
    at /usr/src/debug/httpd-2.2.15/server/mpm/prefork/prefork.c:781
#44 ap_mpm_run (_pconf=0x1a450b8, plog=0x1a73170, s=0x1a46fb0)
    at /usr/src/debug/httpd-2.2.15/server/mpm/prefork/prefork.c:1002
#45 0x00ae8a32 in main (argc=1, argv=0xbf894ed4)
    at /usr/src/debug/httpd-2.2.15/server/main.c:740

#3  0x00417a91 in __tz_convert (timer=0xbf88d8dc, use_localtime=1, tp=0xbf88d8b0)
    at tzset.c:619
619       __libc_lock_lock (tzset_lock);
(gdb) print tzset_lock
$1 = 2
(gdb) up
#4  0x00415dec in __localtime_r (t=0xbf88d8dc, tp=0xbf88d8b0) at localtime.c:33
33        return __tz_convert (t, 1, tp);
(gdb) print *t
$2 = 1313051033
(gdb) print *tp
$3 = {tm_sec = 7523933, tm_min = 7419696, tm_hour = 0, tm_mday = 7524428, 
  tm_mon = -1081550030, tm_year = -1081549880, tm_wday = 0, tm_yday = 0, tm_isdst = 0, 
  tm_gmtoff = 0, tm_zone = 0xb78936c4 "\240IL"}

Version-Release number of selected component (if applicable):
httpd-2.2.15-9.sl6.i686
glibc-2.12-1.25.el6.i686
kernel-2.6.32-131.6.1.el6.i686

How reproducible:
Happens pretty frequently, need to restart httpd server about once a day to cleanup old processes.  Not sure what is triggering it.  It appears to be just trying to write a log file entry.

Comment 2 Joe Orton 2011-08-12 13:08:13 UTC
Thanks for the report.  This is php issue; if you have a core dump and could install php-debuginfo ("debuginfo-install php") and attach the backtrace with that installed, it might shed a little more light.

This part of the backtrace:

#15 0x0580413a in zend_error () from /etc/httpd/modules/libphp5.so
#16 0x057f6f5b in zend_timeout () from /etc/httpd/modules/libphp5.so
#17 <signal handler called>
#18 0x00289416 in __kernel_vsyscall ()
#19 0x004558a3 in __read_nocancel () at ../sysdeps/unix/syscall-template.S:82
#20 0x003f337b in _IO_new_file_underflow (fp=0x1f19358) at fileops.c:598

shows a signal handler interrupting the script; probably the max_execution_time timer expiring.  This process is not signal-safe, and has in this case triggered a deadlock by trying to re-enter tzset(), which was already executing further down the stack.  This is essentially a design flaw in PHP, and is "non-trivial" to fix.

If you can reproduce this, and work out why the script is running for longer than the execution time, fixing that would be the simplest way to avoid the problem.  (if you go up the stack to a frame inside httpd, you can print r->filename to discover what script is running, and r->args to find the query string)

Alternatively, you can increase the max_execution_time to avoid triggering the signal, if that is feasible.

Comment 3 Orion Poplawski 2011-08-12 14:33:34 UTC
Joe -

  Thanks a lot for the detailed analysis.  It is indeed a php script hitting the max_execution_time limit.  I've upped the limit for now to try to help.

Comment 5 RHEL Program Management 2011-08-16 03:28:33 UTC
This request was evaluated by Red Hat Product Management for
inclusion in the current release of Red Hat Enterprise Linux.
Because the affected component is not scheduled to be updated
in the current release, Red Hat is unfortunately unable to
address this request at this time. Red Hat invites you to
ask your support representative to propose this request, if
appropriate and relevant, in the next release of Red Hat
Enterprise Linux. If you would like it considered as an
exception in the current release, please ask your support
representative.

Comment 6 Remi Collet 2012-09-27 13:45:26 UTC
As this is a general design issue with signal handling in php and as workaound is known (setting max_execution_time to avoid trigerring the signal), closing that bug.

Comment 7 Remi Collet 2012-09-27 14:43:54 UTC
If you still face problems with this issue, please let us know.