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_pecalloc (total=401 own=401 in_calls=0)
   1:| >mysqlnd_conn::set_state
   2:| | info : New state=0
   1:| <mysqlnd_conn::set_state (total=247 own=247 in_calls=0)
   1:| >mysqlnd_conn::get_reference
   2:| | info : conn=0 new_refcount=1
   1:| <mysqlnd_conn::get_reference (total=195 own=195 in_calls=0)
   1:| >mysqlnd_conn::init
   2:| | >_mysqlnd_pecalloc
   3:| | | info : file=mysqlnd_net.c   line= 886
   3:| | | info : size=156 ptr=0x2e086f8
   2:| | <_mysqlnd_pecalloc (total=586 own=586 in_calls=0)
   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_pemalloc (total=599 own=599 in_calls=0)
   3:| | | <mysqlnd_net::set_client_option (total=4764 own=4165 in_calls=599)
   2:| | <mysqlnd_net_init (total=5406 own=642 in_calls=4764)
   2:| | >_mysqlnd_pecalloc
   3:| | | info : file=mysqlnd_wireprotocol.c line=2095
   3:| | | info : size=72 ptr=0x2e06f78
   2:| | <_mysqlnd_pecalloc (total=442 own=442 in_calls=0)
   2:| | >mysqlnd_protocol_init
   3:| | | info : persistent=0
   2:| | <mysqlnd_protocol_init (total=207 own=207 in_calls=0)
   1:| <mysqlnd_conn::init (total=15320 own=8679 in_calls=6641)
   0:<mysqlnd_init (total=26276 own=10113 in_calls=16163)

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

• Get the PHP 5.3.4-dev source, 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 :-o).
• 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 debuging 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 free…