PhpRiot
News Archive
PhpRiot Newsletter
Your Email Address:

More information

PHP: the 38 characters of the mysqlnd profiler

Note: This article was originally published at Planet PHP on 29 October 2010.
Planet PHP

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