|
|
php.net | support | documentation | report a bug | advanced search | search howto | statistics | random bug | login |
[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 PatchesPull RequestsHistoryAllCommentsChangesGit/SVN commits
|
|||||||||||||||||||||||||||||||||
Copyright © 2001-2023 The PHP GroupAll rights reserved. |
Last updated: Wed Feb 01 08:03:58 2023 UTC |
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.