Debugging PHP using Windbg


 

After the release of Windows Azure Websites, we are happy to see that we attracted a lot of PHP users hosting their web site on Azure Websites. A very common type of request we received from customer is how to troubleshooting PHP site performance issue. Last time, I published a blog using XDEBUG, but that requires some additional coding, configuration etc. Also, XDEBUG profiler slows down the request as well which may not acceptable some production scenarios. The blog is here for your reference.

 

 

http://blogs.msdn.com/b/asiatech/archive/2013/11/15/azure-websites-find-php-performance-bottleneck.aspx

 

Hang dump analysis is a very efficient and direct way for performance issues. We rely on Debugging tools for Windows (Windbg) to analyze the hang dump and find out the performance bottleneck. We have a very well documented way to find out the current executing function of ASP and ASP.NET. In this article, I will share how I use Windbg to find out the current executing function of PHP.

 

Setup Symbol

Before we start, we need to setup the symbol. All the PHP symbols can be downloaded from PHP site. The symbol files are included in the Debug Pack.

http://windows.php.net/download/

For archived version:

http://windows.php.net/downloads/releases/archives/

For example, if your PHP version is 5.4.9, then you need download this pack.

php-debug-pack-5.4.9-nts-Win32-VC9-x86.zip

For how to setup symbol for Windbg, please reference this article.

Debugging with Symbols

http://msdn.microsoft.com/en-us/library/windows/desktop/ee416588(v=vs.85).aspx

Find out the current Executing PHP function

Capture a hang dump

First, capture a hang dump for php-cgi.exe process using procdump or AdPlus.exe. For WAWS, you can use the process and minidump feature here.

https://github.com/projectkudu/kudu/wiki/Process-list-and-minidump

Or follow this blog to use the Kudu console to capture full memory dump.

http://blogs.msdn.com/b/asiatech/archive/2013/07/18/using-kudu-to-capture-hang-dumps-for-windows-azure-web-sites.aspx

Find out the _zend_execute_data

After captured the dump, open it in Windbg. Here is a sample PHP stack.

0:000> kL

ChildEBP RetAddr 

00cfe2b0 75fe11f8 ntdll!NtDelayExecution+0xc

00cfe318 65db04a3 KERNELBASE!SleepEx+0x62

00cfe32c 65b39bb7 php5!zif_sleep+0x52

00cfe388 65b398af php5!zend_do_fcall_common_helper_SPEC+0x207

00cfe3ac 65b2b264 php5!ZEND_DO_FCALL_SPEC_CONST_HANDLER+0x8f

00cfe3c8 65b01a0d php5!execute+0x164

00000000 00000000 php5!zend_execute_scripts+0xdd

The key data structure here is _zend_execute_data. The easiest way to find out it is using the dv debugging command.

0:000> .frame 3

03 00cfe388 65b398af php5!zend_do_fcall_common_helper_SPEC+0x207 [c:\php-sdk\php54dev\vc9\x86\php-5.4.9\zend\zend_vm_execute.h @ 642]

0:000> dv

       execute_data = 0x014222d8

dv doesn’t work all the times, in case this, you need to find out the structure yourself by reading the assembly. Here is a sample for this scenario.

0:000> knL

 # ChildEBP RetAddr 

00 0165cc84 7432711e ntdll!NtWaitForSingleObject+0xc

01 0165ccc8 74308599 mswsock!SockWaitForSingleObject+0x25015

02 0165cdd8 75430ccf mswsock!WSPSelect+0x338

03 (Inline) ——– ws2_32!DPROVIDER::WSPSelect+0x16

04 0165ce74 658e9f37 ws2_32!select+0x145

05 0165dac4 658ea090 php5!php_poll2+0x107

06 0165daf4 656017a8 php5!php_sockop_read+0x70

07 0165db0c 6585faa3 php_openssl!php_openssl_sockop_read+0x28

08 0165db5c 6585f9db php5!php_stream_fill_read_buffer+0x73

09 0165db90 6590596d php5!php_mysqlnd_net_network_read_ex_pub+0x17b

0a 0165dbb0 658ca2c2 php5!php_mysqlnd_net_receive_ex_pub+0x2d

0b 0165dbd4 658e2fc7 php5!mysqlnd_read_header+0x22

0c 0165e420 6584d6ce php5!php_mysqlnd_auth_response_read+0x67

0d 0165e470 65854b13 php5!mysqlnd_auth_handshake+0xde

0e 0165e538 65856c37 php5!mysqlnd_connect_run_authentication+0x183

0f 0165e5a4 658ea848 php5!php_mysqlnd_conn_data_connect_pub+0x347

10 0165e5dc 65904294 php5!php_mysqlnd_conn_connect_pub+0x48

11 0165e614 658111fa php5!mysqlnd_connect+0x64

12 0165e6a4 6581df76 php_mysqli!mysqli_common_connect+0x1da

13 0165e6b4 65889bb7 php_mysqli!zif_mysqli_link_construct+0x16

14 0165e714 65887cbe php5!zend_do_fcall_common_helper_SPEC+0x207

15 0165e71c 6587b264 php5!ZEND_DO_FCALL_BY_NAME_SPEC_HANDLER+0xe

16 0165e738 65851a0d php5!execute+0x164

17 00000000 00000000 php5!zend_execute_scripts+0xdd

 

0:000> .frame 14

14 0165e714 65887cbe php5!zend_do_fcall_common_helper_SPEC+0x207 [c:\php-sdk\php54dev\vc9\x86\php-5.4.9\zend\zend_vm_execute.h @ 642]

 

//This dv output is invalid. address of execute_data is invalid.

0:000> dv

       execute_data = 0x57b12c00

 

0:000> dt execute_data

Local var @ edi Type _zend_execute_data*

   +0x000 opline           : ????

   +0x004 function_state   : _zend_function_state

   +0x00c fbc              : ????

   +0x010 called_scope     : ????

   +0x014 op_array         : ????

   +0x018 object           : ????

   +0x01c Ts               : ????

   +0x020 CVs              : ????

   +0x024 symbol_table     : ????

   +0x028 prev_execute_data : ????

   +0x02c old_error_reporting : ????

   +0x030 nested           : ??

   +0x034 original_return_value : ????

   +0x038 current_scope    : ????

   +0x03c current_called_scope : ????

   +0x040 current_this     : ????

   +0x044 current_object   : ????

Memory read error 57b12c44

 

//By reading the assembly, you can know it is here instead.

0:000> dd 0165e714-38-8-4 l1

0165e6d0  01852180

Walk the PHP call stacks

The two members of _zend_execute_data we interesting are op_array and prev_execute_data.

0:000> dt 0x014222d8 _zend_execute_data op_array prev_execute_data

php_cgi!_zend_execute_data

   +0x014 op_array          : 0x01e72e00_zend_op_array

   +0x028 prev_execute_data : 0x01422200_zend_execute_data

op_array contains the function name and the PHP file name. The current executing PHP function is mySleep, file name is Slow.php.

0:000> dt 0x01e72e00_zend_op_array function_name filename

php_cgi!_zend_op_array

   +0x004 function_name : 0x05631b28  “mySleep

   +0x050 filename      : 0x05631b30  “C:\DWASFiles\Sites\php-mysql\VirtualDirectory0\site\wwwroot\Slow.PHP”

prev_execute_data contains the information of upper level function call.

0:000> dt 0x01422200 _zend_execute_data op_array prev_execute_data

php_cgi!_zend_execute_data

   +0x014 op_array          : 0x01e72ce0_zend_op_array

   +0x028 prev_execute_data : 0x014220d0_zend_execute_data

 

//SlowFunction calls mySleep

0:000> dt 0x01e72ce0_zend_op_array function_name filename

php_cgi!_zend_op_array

   +0x004 function_name : 0x05631984  “SlowFunction”

   +0x050 filename      : 0x056319e0  “C:\DWASFiles\Sites\php-mysql\VirtualDirectory0\site\wwwroot\Slow.PHP”

 

//Walk to the next frame, until prev_execute_data is null.

0:000> dt 0x014220d0_zend_execute_data op_array prev_execute_data

php_cgi!_zend_execute_data

   +0x014 op_array          : 0x0143cbd0 _zend_op_array

   +0x028 prev_execute_data : (null)

 

So, for this PHP, the call stack is like this:

NT Sleep API

mySleep

SlowFunction

PHP page Entry

 

See you next time,

Wei

Comments (0)

Skip to main content