php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #49770 Thread Deadlocking Under Load
Submitted: 2009-10-04 21:57 UTC Modified: 2009-10-06 12:13 UTC
Votes:2
Avg. Score:4.0 ± 1.0
Reproduced:0 of 1 (0.0%)
From: wickham at affl dot com Assigned:
Status: Open Package: Reproducible crash
PHP Version: 5.2SVN-2009-10-04 (snap) OS: win32 only - Windows Server 2003
Private report: No CVE-ID: None
View Add Comment Developer Edit
Anyone can comment on a bug. Have a simpler test case? Does it work for you on a different platform? Let us know!
Just going to say 'Me too!'? Don't clutter the database with that please — but make sure to vote on the bug!
Your email address:
MUST BE VALID
Solve the problem:
43 + 31 = ?
Subscribe to this entry?

 
 [2009-10-04 21:57 UTC] wickham at affl dot com
Description:
------------
We are having an issue with deadlocking requests from php.  This is only occuring during heavy load.  In our situation every user hits the same php file every 30 seconds.  This php file downloads a gzip file to the client and hands it off to a flex application.

This same code has run on 5 different servers over the last 3 years without this issue occuring.  Two weeks ago we completed a migration to a new server, and now we are seeing this deadlocking issue.

We originally put a ticket into Microsoft, and ran some debug.  They attribute the issue directly to a php deadlocking issue, with some of the data dump below.

We are running php on a Windows Server 2003 with IIS 6.  The php settings can be found at http://games.affl.com/test.php

Reproduce code:
---------------
<?PHP
 
// Include this function on your pages
function print_gzipped_page() {

    global $HTTP_ACCEPT_ENCODING;
    if( headers_sent() ){
        $encoding = false;
    }elseif( strpos($HTTP_ACCEPT_ENCODING, 'x-gzip') !== false ){
        $encoding = 'x-gzip';
    }elseif( strpos($HTTP_ACCEPT_ENCODING,'gzip') !== false ){
        $encoding = 'gzip';
    }else{
        $encoding = false;
    }

    if( $encoding ){
        $contents = ob_get_contents();
        ob_end_clean();
        header('Content-Encoding: '.$encoding);
        print("\x1f\x8b\x08\x00\x00\x00\x00\x00");
        $size = strlen($contents);
        $contents = gzcompress($contents, 9);
        $contents = substr($contents, 0, $size);
        print($contents);
        exit();
    }else{
        ob_end_flush();
        exit();
    }
}

 function gzfile_get_contents($filename, $use_include_path = 0)
{
    //File does not exist
    if( !@file_exists($filename) )
    {    return false;    }
  
    //Read and imploding the array to produce a one line string
   $data = gzfile($filename, $use_include_path);
   $data = implode($data);
   return $data;
}

// At the beginning of each page call these two functions
if (substr_count($_SERVER['HTTP_ACCEPT_ENCODING'], 'gzip'))
{
    ob_start("ob_gzhandler");
}
else
{
    ob_start();
}

ob_implicit_flush(0);


// $reqGzFileName =  "players.XML.GZ";
$reqGzFileName = $_POST["gzfilename"];
//Write file content here... live_scores_20071022231636.XML.GZ   live_scoring_players.xml.GZ   
// echo gzfile_get_contents ("players.XML.GZ");
echo gzfile_get_contents($reqGzFileName);
 
// Call this function to output everything as gzipped content.
print_gzipped_page();

 
?> 

Actual result:
--------------
Here is what I found in the dumps you sent to us:

There are two threads (4 and 11) deadlocking against each other.

Thread 9 is also waiting on a critical section owned by 11.

Thread 10 is waiting on a critical section owned by 9

There are 82 additional threads waiting on the critical section owned by thread 10.

The critical section owned by thread 4 is inside of ODBCINT.dll.  The critical section owned by thread 4 is not located within any loaded DLL.

There may be something in the PHP code being run or something in the PHP ISAPI that is causing the issue.  If we can get proper symbols for the PHP components that are laoded I can dig further in a see if we can glean any more details.

0:000> !critlist
CritSec at  1c04ad0.  Owned by thread 11.  Deadlocked on CritSec 261fc4.
  Waiting Threads: 4 9
CritSec at 77bf3a48.  Owned by thread 10.  Blocked by Deadlock.
  Waiting Threads: 5 6 7 8 31 34 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 109 110 111 112 113 114 115 CritSec at  1c04a88.  Owned by thread 9.  Blocked by Deadlock.
  Waiting Threads: 10 
CritSec at   261fc4.  Owned by thread 4.  Deadlocked on CritSec 1c04ad0.
  Waiting Threads: 11 


0:000> ~4kbn
 # ChildEBP RetAddr  Args to Child              
00 00f7d44c 7c827d29 7c83d266 0000082c 00000000 ntdll!KiFastSystemCallRet
01 00f7d450 7c83d266 0000082c 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
02 00f7d48c 7c83d2b1 0000082c 00000004 00000001 ntdll!RtlpWaitOnCriticalSection+0x1a3
03 00f7d4ac 77bcb7a9 01c04ad0 00000090 00f7d4f8 ntdll!RtlEnterCriticalSection+0xa8
04 00f7d4bc 77bbf35d 0000000b 77bf4a00 00000090 msvcrt!_lock+0x30
05 00f7d4f8 77bbe1f0 77bf4a00 00000090 00000004 msvcrt!_alloc_osfhnd+0x27
06 00f7d530 77bbe303 00000004 086eba08 042a0a20 msvcrt!_creat+0x52
07 00f7d564 01fffee8 00000004 020e4770 0429fbf0 msvcrt!_dup+0x55
WARNING: Stack unwind information not available. Following frames may be wrong.
08 00f7d580 01ffda08 00000000 0429bbb0 020e4770 php5ts!php_version_compare+0x41a8
09 00000000 00000000 00000000 00000000 00000000 php5ts!php_version_compare+0x1cc8

0:000> ~11kbn
 # ChildEBP RetAddr  Args to Child              
00 0114d45c 7c827d29 7c83d266 00000714 00000000 ntdll!KiFastSystemCallRet
01 0114d460 7c83d266 00000714 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
02 0114d49c 7c83d2b1 00000714 00000002 00261fc4 ntdll!RtlpWaitOnCriticalSection+0x1a3
03 0114d4bc 77bbf3f4 00261fc4 77bf4a00 0000006c ntdll!RtlEnterCriticalSection+0xa8
04 0114d4f8 77bbe1f0 77bf4a00 0000006c 00000003 msvcrt!_alloc_osfhnd+0xbe
05 0114d530 77bbe303 00000003 0316d680 03320f28 msvcrt!_creat+0x52
06 0114d564 01fffee8 00000003 020e4770 0331fcb8 msvcrt!_dup+0x55
WARNING: Stack unwind information not available. Following frames may be wrong.
07 0114d580 01ffda08 00000000 0331bc78 020e4770 php5ts!php_version_compare+0x41a8
08 00000000 00000000 00000000 00000000 00000000 php5ts!php_version_compare+0x1cc8

0:000> lmvm php5ts
start    end        module name
01e20000 0231c000   php5ts   C (export symbols)       php5ts.dll
    Loaded symbol image file: php5ts.dll
    Image path: \\?\C:\PHP\php5ts.dll
    Image name: php5ts.dll
    Timestamp:        Wed Jun 17 11:16:31 2009 (4A3908CF)
    CheckSum:         00000000
    ImageSize:        004FC000
    File version:     5.2.10.10
    Product version:  5.2.10.0
    File flags:       0 (Mask 3F)
    File OS:          4 Unknown Win32
    File type:        2.0 Dll
    File date:        00000000.00000000
    Translations:     0409.04b0
    CompanyName:      The PHP Group
    ProductName:      PHP Script Interpreter
    InternalName:     php5ts.dll
    OriginalFilename: php5ts.dll
    ProductVersion:   5.2.10
    FileVersion:      5.2.10.10
    PrivateBuild:     5.2.10.10
    SpecialBuild:     5.2.10.10
    FileDescription:  PHP Script Interpreter
    LegalCopyright:   Copyright (c) 1997-2007 The PHP Group
    LegalTrademarks:  PHP
    Comments:         PHP


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2009-10-04 22:44 UTC] pajoye@php.net
Can you try with the NTS version and FastCGI please? 
 [2009-10-04 23:53 UTC] wickham at affl dot com
Here is an updated comment by the Microsoft Engineer:

I managed to find public symbols for the version of PHP you have - this has allowed me to trace the stack back further.

The deadlocking threads look like this:

ChildEBP RetAddr
0d0bd44c 7c827d29 ntdll!KiFastSystemCallRet 0d0bd450 7c83d266 ntdll!NtWaitForSingleObject+0xc 0d0bd48c 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
0d0bd4ac 77bcb7a9 ntdll!RtlEnterCriticalSection+0xa8
0d0bd4bc 77bbf35d msvcrt!_lock+0x30
0d0bd4f8 77bbe1f0 msvcrt!_alloc_osfhnd+0x27 0d0bd530 77bbe303 msvcrt!_creat+0x52
0d0bd564 0203fee8 msvcrt!_dup+0x55
0d0bd580 0203da08 php5ts!php_stream_gzopen+0xc8
0d0bf5b8 01e7ce6b php5ts!zif_gzfile+0x68
0d0bf614 01e83105 php5ts!zend_do_fcall_common_helper_SPEC+0x7ab
0d0bf634 01e7c635 php5ts!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0xe5
0d0bf684 01e7cf8a php5ts!execute+0x1c5
0d0bf6d0 01e83105 php5ts!zend_do_fcall_common_helper_SPEC+0x8ca
0d0bf6f0 01e7c635 php5ts!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0xe5
0d0bf740 01e62e87 php5ts!execute+0x1c5
0d0bf778 01f1d30d php5ts!zend_execute_scripts+0x107
0d0bf944 10001f10 php5ts!php_execute_script+0x20d 0d0bfe40 5a322991 php5isapi!HttpExtensionProc+0x110 0d0bfe60 5a3968ff w3isapi!ProcessIsapiRequest+0x214
0d0bfe94 5a3a66f1 w3core!W3_ISAPI_HANDLER::IsapiDoWork+0x3fd
0d0bfeac 5a394c6f w3core!W3_ISAPI_HANDLER::OnCompletion+0x7e
0d0bfec4 5a394bf0 w3core!W3_HANDLER::MainOnCompletion+0x52
0d0bfee8 5a394baf w3core!W3_CONTEXT::ExecuteHandlerCompletion+0x23
0d0bff08 5a394fab w3core!W3_MAIN_CONTEXT::DoWork+0x91
0d0bff20 5a3618b2 w3core!W3_MAIN_CONTEXT::OnIoCompletion+0x37
0d0bff38 5a361650 w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x48
0d0bff48 5a3616ca w3dt!UL_NATIVE_REQUEST::DoWork+0x7f
0d0bff5c 5a3024ce w3dt!OverlappedCompletionRoutine+0x1a
0d0bff8c 5a3026ac w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x73
0d0bffa0 5a301da9 w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x24
0d0bffb8 77e6482f w3tp!THREAD_MANAGER::ThreadManagerThread+0x39
0d0bffec 00000000 kernel32!BaseThreadStart+0x34

And this:

ChildEBP RetAddr
00fbd3b8 7c827d29 ntdll!KiFastSystemCallRet 00fbd3bc 7c83d266 ntdll!NtWaitForSingleObject+0xc
00fbd3f8 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
00fbd418 77bbf3f4 ntdll!RtlEnterCriticalSection+0xa8
00fbd454 77bc02f3 msvcrt!_alloc_osfhnd+0xbe
00fbd484 77bc0480 msvcrt!_mktemp+0x266
00fbd4d0 01f2cb81 msvcrt!_open+0x2d
00fbd4f8 01f2ccf0 php5ts!_php_stream_fopen+0xc1 00fbd520 01f30003 php5ts!php_plain_files_stream_opener+0xa0
00fbd554 0203feb8 php5ts!_php_stream_open_wrapper_ex+0xc3
00fbd580 0203da08 php5ts!php_stream_gzopen+0x98
00fbf5b8 01e7ce6b php5ts!zif_gzfile+0x68
00fbf614 01e83105 php5ts!zend_do_fcall_common_helper_SPEC+0x7ab
00fbf634 01e7c635 php5ts!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0xe5
00fbf684 01e7cf8a php5ts!execute+0x1c5
00fbf6d0 01e83105 php5ts!zend_do_fcall_common_helper_SPEC+0x8ca
00fbf6f0 01e7c635 php5ts!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0xe5
00fbf740 01e62e87 php5ts!execute+0x1c5
00fbf778 01f1d30d php5ts!zend_execute_scripts+0x107
00fbf944 10001f10 php5ts!php_execute_script+0x20d 00fbfe40 5a322991 php5isapi!HttpExtensionProc+0x110 00fbfe60 5a3968ff w3isapi!ProcessIsapiRequest+0x214
00fbfe94 5a3a66f1 w3core!W3_ISAPI_HANDLER::IsapiDoWork+0x3fd
00fbfeac 5a394c6f w3core!W3_ISAPI_HANDLER::OnCompletion+0x7e
00fbfec4 5a394bf0 w3core!W3_HANDLER::MainOnCompletion+0x52
00fbfee8 5a394baf w3core!W3_CONTEXT::ExecuteHandlerCompletion+0x23
00fbff08 5a394fab w3core!W3_MAIN_CONTEXT::DoWork+0x91
00fbff20 5a3618b2 w3core!W3_MAIN_CONTEXT::OnIoCompletion+0x37
00fbff38 5a361650 w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x48
00fbff48 5a3616ca w3dt!UL_NATIVE_REQUEST::DoWork+0x7f
00fbff5c 5a3024ce w3dt!OverlappedCompletionRoutine+0x1a
00fbff8c 5a3026ac w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x73
00fbffa0 5a301da9 w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x24
00fbffb8 77e6482f w3tp!THREAD_MANAGER::ThreadManagerThread+0x39
00fbffec 00000000 kernel32!BaseThreadStart+0x34

In trying to poke around the local variables for things like filename and such I was receiving a lot of memory access errors due to the addresses being passed falling well under 0x0000FFFF.  This is a guard value - any address lower than this is automatically invalid.

0:033> kn
 # ChildEBP RetAddr
00 0d0bd44c 7c827d29 ntdll!KiFastSystemCallRet
01 0d0bd450 7c83d266 ntdll!NtWaitForSingleObject+0xc
02 0d0bd48c 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
03 0d0bd4ac 77bcb7a9 ntdll!RtlEnterCriticalSection+0xa8
04 0d0bd4bc 77bbf35d msvcrt!_lock+0x30
05 0d0bd4f8 77bbe1f0 msvcrt!_alloc_osfhnd+0x27
06 0d0bd530 77bbe303 msvcrt!_creat+0x52
07 0d0bd564 0203fee8 msvcrt!_dup+0x55
08 0d0bd580 0203da08 php5ts!php_stream_gzopen+0xc8
09 0d0bf5b8 01e7ce6b php5ts!zif_gzfile+0x68 0a 0d0bf614 01e83105 php5ts!zend_do_fcall_common_helper_SPEC+0x7ab
0b 0d0bf634 01e7c635 php5ts!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0xe5
0c 0d0bf684 01e7cf8a php5ts!execute+0x1c5 0d 0d0bf6d0 01e83105 php5ts!zend_do_fcall_common_helper_SPEC+0x8ca
0e 0d0bf6f0 01e7c635 php5ts!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0xe5
0f 0d0bf740 01e62e87 php5ts!execute+0x1c5 10 0d0bf778 01f1d30d php5ts!zend_execute_scripts+0x107
11 0d0bf944 10001f10 php5ts!php_execute_script+0x20d
12 0d0bfe40 5a322991 php5isapi!HttpExtensionProc+0x110
13 0d0bfe60 5a3968ff w3isapi!ProcessIsapiRequest+0x214 0:033> .frame 8
08 0d0bd580 0203da08 php5ts!php_stream_gzopen+0xc8 0:033> dv
        wrapper = 0x03305c00
           path = 0x00000019 "--- memory read error at address 0x00000019 ---"
           mode = 0x00000011 "--- memory read error at address 0x00000011 ---"
        options = 73325148
    opened_path = 0x045eda94
        context = 0x00000000
        tsrm_ls = 0x00000001
             fd = 25

From the PHP source for this function:

: php_stream *php_stream_gzopen(php_stream_wrapper *wrapper, char *path, char *mode, int options, 
:                                                           char **opened_path, php_stream_context *context STREAMS_DC TSRMLS_DC)
: {

I have no idea if this is how this code is supposed to work or if these values have been modified from what was actually passed by the code that has been executed prior to the hang.

In any case this may be of use to the PHP support people to help determine what is going on.
 [2009-10-05 18:39 UTC] pajoye@php.net
Take #2 (and last): Please try with the *NTS* version and FastCGI. That's the recommended SAPI for IIS 5/6/7.
 [2009-10-05 19:31 UTC] wickham at affl dot com
We are trying the FastCGI tonight.  This issue only occurs during high load time and that will be the next opportunity to see if it helps.  I will update with any new information after that.
 
PHP Copyright © 2001-2019 The PHP Group
All rights reserved.
Last updated: Mon Apr 22 08:01:25 2019 UTC