PHP: the 38 characters of the mysqlnd profiler

Recently I was forced to benchmark a mysqlnd plugin on Windows. X-Debug was no help. It worked flawless on Windows but it can't tell you what goes on inside a PHP user space API call, for example, you will not know how much time mysqli_query() spends reading a result set. Very Sleepy is nice and the latest Microsoft Visual Studio profiler are probably wonderful but any of those external profiling tools did give me too fine-grained information. Also, they are external profiler which means you have to install extra software.

The mysqlnd statistics didn't help me either. I didn't need any aggregated values, I was curios if a certain function was the bottleneck. The solution:

• extra statistics for critical sections in the plugin using the mysqlnd statistics framework (C coding)
• dump profiling information into mysqlnd debug log (thanks Andrey)
• make mysqlnd debug log available on Windows (when using VC9 or newer, thanks Andrey)

Since today mysqlnd adds profiling information to its debug log. Note the "(total = n own= n in_calls=n)" behind the closing tag of a function call. The times are given in milliseconds. For example, "_mysqlnd_pecalloc (total=401 own=401 in_calls=0)" tells you that mysqlnd has spend 401 milliseconds to allocate some memory. Why is that so slow? Simple: I'm using a VM.

0:mysqlnd_init 1:| info : persistent=0 1:| _mysqlnd_pecalloc 2:| | info : file=mysqlnd.c line=2322 2:| | info : size=780 ptr=0x2e08d30 1:| mysqlnd_conn::set_state 2:| | info : New state=0 1:| mysqlnd_conn::get_reference 2:| | info : conn=0 new_refcount=1 1:| mysqlnd_conn::init 2:| | _mysqlnd_pecalloc 3:| | | info : file=mysqlnd_net.c line= 886 3:| | | info : size=156 ptr=0x2e086f8 2:| | mysqlnd_net_init 3:| | | info : persistent=0 3:| | | mysqlnd_net::set_client_option 4:| | | | info : option=202 4:| | | | info : MYSQLND_OPT_NET_CMD_BUFFER_SIZE 4:| | | | info : new_length=4096 4:| | | | _mysqlnd_pemalloc 5:| | | | | info : file=mysqlnd_net.c line= 586 5:| | | | | info : size=4096 ptr=0x2e09070 persistent=0 4:| | | | _mysqlnd_pecalloc 3:| | | info : file=mysqlnd_wireprotocol.c line=2095 3:| | | info : size=72 ptr=0x2e06f78 2:| | mysqlnd_protocol_init 3:| | | info : persistent=0 2:| |

Here is how you create such a debug log with profiling information:

• Get PHP 5.3.4-dev, the fresh meat not the stinky one
• Compile PHP with mysqlnd support and enable debugging, for example, ./configure --with-mysqli=mysqlnd --enable-debug on Linux or configure --with-mysqli --with-mysqlnd --enable-debug on Windows.
• Set the PHP configuration (php.ini) setting: mysqlnd.debug, for example, mysqlnd.debug="d:t:O,/tmp/mysqlnd.log" (38 characters) on Linux or mysqlnd.debug="d:t:O,mysqlnd.log" (34).
• Run your PHP MySQL script

Pitfall: the mysqlnd debug option parser does not support file names that contain ":" You cannot use something like "C:\tmp\mysqlnd.log". Its about debug and profiling. We will probably not lift that limitation without a strong need. But, of course, mysqlnd is Open Source. If you need it urgently, feel freea€¦

• Read the original article at Planet PHP