Ulf Wendel

PHP replication plugin statistics and troubleshooting

The PHP replication and load balancing mysqlnd plugin as been released as an alpha through PECL. Alpha is for those who want to try out the 1.0 feature set as early as possible. Alpha is for those who do not fear debugging, if need be. Notes on troubleshooting.

Testing load balancing and read/write split

There are three ways to verify that load balancing and read/write split works as it should:

  • within PHP script: checking thread/connection ids
  • within PHP script: monitoring statistics
  • externally: mysqlnd debug log file

Thread/connection ids to distinguish connections

PECL/mysqlnd_ms changes the semantics of a PHP MySQL connection handle. If using the plugin, a connection handle returned by any of the three PHP MySQL extensions (mysql, mysqli, PDO_MySQL) does no longer map to a physical MySQL connection in a strict 1:1 way. The connection handle represents a pool of connections managed by the plugin. At a time, the connection handle may be mapped to a connection to the master. Later on, it may be mapped to a connection to one of the slaves.

Every physical connection to MySQL has a thread/connection id. By checking the thread id, a PHP script can detect if the plugin has decided to switch connections. You can obtain the thread id of a mysql or mysqli connection handle using the functions mysql_thread_id() respectively mysqli_thread_id(). PDO_MySQL offers no corresponding API call. Please, check the thread id immediately after running a query.

You must not use the query SELECT CONNECTION_ID() to fetch the thread id for checking if the load balancing plugin works! The query itself will be load balanced. It makes the plugin potentially switch connections. It changes the state of the connection handle. Thus, it cannot be used to monitor the state.

[myapp]
master[]=localhost:/tmp/mysql.sock
slave[]=192.168.2.27:3306
pick[]=random_once

function run_query($mysqli, $query, $hint = NULL) {

  if (!is_null($hint) )
    $query = sprintf("/*%s*/%s", $hint, $query);
  
  if ($ret = $mysqli->query($query))
    return $ret;

  printf("[%d] %s\n", $mysqli->errno, $mysqli->error);
  return $ret;
}

/* Create load balanced connection handle */
$mysqli = new mysqli("myapp", "username", "password", "database");

/* Find connection thread ids, assumption: SQL hints work */
$threads = array('master' => NULL, 'slaves' => array());
run_query($mysqli, "SELECT 1 FROM DUAL", MYSQLND_MS_MASTER_SWITCH);
$threads['master'] = $mysqli->thread_id();
run_query($mysqli, "SELECT 1 FROM DUAL", MYSQLND_MS_SLAVE_SWITCH);
$threads['slaves'][$mysqli->thread_id()] = $mysqli->thread_id();

/* Verify if plugin works */
run_query($mysqli, "DROP TABLE IF EXISTS test");
if ($mysqli->thread_id != $threads['master'])
  printf("DROP TABLE has not been run on the master!");
run_query($mysqli, "SELECT 1 FROM DUAL");
if (!isset($threads['slaves'][$mysqli->thread_id]))
  printf("SELECT has not been run on a slave!");

The more slaves you have, the more complicated the thread id checking matter becomes. Do yourself a favor: start with one or two slaves. If it works with one or two slaves, why wouldn’t it work with three or four… Watch out for the load balancing strategy (random, random_once (sticky), roundrobin, user) you have configured when collecting thread ids.

Statistics – mysqlnd_ms_get_stats()

Users of PDO_MySQL may want to (ab)use statistics to monitor decisions of the plugin. There are some 15 statistics telling you how many statements have been sent to the master server and the slave servers, why they have been sent there, how many connections have been opened and how often the transaction mode has been used.

mysqlnd_ms.enable=1
mysqlnd_ms.collect_statistics=1

Statistics are returned by mysqlnd_ms_get_stats() if mysqlnd_ms.collect_statistics=1 has been set in the PHP configuration file (php.ini).

The statistics have not been designed specifically to monitor connection switches of the plugin when running many PDO_MySQL scripts in parallel on a web server. Like with the mysqlnd query cache plugin statistics are aggregated per process. If your web server deployment model serves several web requests with the same PHP process, you’ll see that statistics are not reset before the PHP process ends.

which server and why
use_slave, use_slave_sql_hint, use_slave_callback, use_master, use_master_sql_hint, use_master_callback, use_last_used_sql_hint
number of successful and failed connects
non_lazy_connections_slave_success, non_lazy_connections_slave_failed, non_lazy_connections_master_success, non_lazy_connections_master_failed, lazy_connections_slave_success, lazy_connections_slave_failed, lazy_connections_master_success, lazy_connections_master_failed
transaction mode related
trx_autocommit_on, trx_autocommit_off, trx_master_forced

Nonetheless, you can use the statistics in some cases. The basic idea is that you check the statistics before and after running a query.

$pdo = new PDO( 'mysql:host=myapp;dbname=test', 'username', 'password');

$stats_before = mysqlnd_ms_get_statistics();
$stmt = $pdo->prepare("SELECT 1 FROM DUAL");
$stats_after = mysqlnd_ms_get_statistics();

foreach ($stats_before as $stat => $value) {
  if ($stats_after[$stat] != $value)
    printf("%s - before: %d, after %d\n", $stat, $value, $stats_after[$stat]);
}

The last resort: mysqlnd debug log

If nothing else helps, try to isolate the issue, install a debug version of PHP and check the mysqlnd debug log. The debug log is only available when using a debug version of PHP. Turning on debug can be a severe performance hit, depending on the amount of data written to the log file. Debug log writing is activated with the PHP configuration directive mysqlnd.debug in the PHP configuration file (php.ini).

mysqlnd.debug="d:t:x:O,/tmp/mysqlnd.trace"

The debug log is a function trace log. It shows all mysqlnd and mysqlnd_ms internal function calls. Many of the function calls take a mysqlnd connection handle as a parameter. Relevant function often either show the memory address of the connection handle or its thread id. This way you can track exactly what mysqlnd has done and which server has been used to execute a query.

>mysqlnd_connect
| info : host=myapp user=root db=test port=3306 flags=131072
| >mysqlnd_ms::connect
| | >mysqlnd_ms_ini_section_exists
| | | info : section=[myapp] len=[5]
| | | info : ret=1
| | <mysqlnd_ms_ini_section_exists
| | >mysqlnd_ms_conn_free_plugin_data
| | | >_mysqlnd_plugin_get_plugin_connection_data
| | | | info : plugin_id=5
| | | <_mysqlnd_plugin_get_plugin_connection_data
| | <mysqlnd_ms_conn_free_plugin_data
| | >_mysqlnd_plugin_get_plugin_connection_data
| | | info : plugin_id=5
| | <_mysqlnd_plugin_get_plugin_connection_data
| | >_mysqlnd_pestrdup
| | | info : file=mysqlnd_ms.c    line= 450
| | | info : ptr=0x7fc7a50f29e0
| | <_mysqlnd_pestrdup
| | >_mysqlnd_pestrdup
| | | info : file=mysqlnd_ms.c    line= 454
| | | info : ptr=0x7fc7a50e3f48
| | <_mysqlnd_pestrdup
| | >mysqlnd_ms_ini_string
| | | info : name=master
| | | info : the list has 1 entries
| | | >_mysqlnd_pestrdup
| | | | info : file=mysqlnd_ms_ini.c line= 271
| | | | info : ptr=0x10baeb0
| | | <_mysqlnd_pestrdup
| | | info : ret=localhost:/tmp/mysql.sock
| | <mysqlnd_ms_ini_string
| | >mysqlnd_ms_ini_string
| | | info : name=lazy_connections
| | | info : ret=0
| | <mysqlnd_ms_ini_string
| | info : overwriting socket : /tmp/mysql.sock
| | >mysqlnd_conn::connect
| | | info : host=localhost user=root db=test port=3306 flags=131072 persistent=1 state=0
| | | >_mysqlnd_plugin_get_plugin_connection_data
| | | | info : plugin_id=5
| | | <_mysqlnd_plugin_get_plugin_connection_data
| | | >mysqlnd_ms::set_server_option
| | | <mysqlnd_ms::set_server_option
| | | info : socket=/tmp/mysql.sock
| | | info : transport=unix:///tmp/mysql.sock
| | | >mysqlnd_protocol::get_greet_packet
| | | <mysqlnd_protocol::get_greet_packet
| | | >mysqlnd_net::connect
| | | | info : hashed_details=0xf5b930
| | | | info : calling php_stream_xport_create
| | | | info : setting 31536000 as PHP_STREAM_OPTION_READ_TIMEOUT
| | | | >mysqlnd_net::set_client_option
| | | | | info : option=203
| | | | | info : MYSQLND_OPT_NET_READ_BUFFER_SIZE
| | | | | info : new_length=32768
| | | | <mysqlnd_net::set_client_option
| | | <mysqlnd_net::connect
| | | info : stream=0xf5bcf0
| | | >php_mysqlnd_greet_read
| | | | info : buf=0x7fffc587c990 size=2048
| | | | >mysqlnd_read_header_name
| | | | | info : compressed=0 conn_id=0
| | | | | >mysqlnd_net::receive
| | | | | <mysqlnd_net::receive
| | | | | >mysqlnd_net::network_read
| | | | | | info : count=4
| | | | | <mysqlnd_net::network_read
| | | | | info : HEADER: prot_packet_no=0 size= 78
| | | | <mysqlnd_read_header_name
| | | | >mysqlnd_net::receive
| | | | <mysqlnd_net::receive
| | | | >mysqlnd_net::network_read
| | | | | info : count=78
| | | | <mysqlnd_net::network_read
| | | | info : proto=10 server=5.5.11-log thread_id=6
| | | | info : server_capabilities=2148530175 charset_no=8 server_status=2 auth_protocol=mysql_native_password scramble_length=21
| | | <php_mysqlnd_greet_read

[...]
>mysqlnd_ms::query
| >_mysqlnd_plugin_get_plugin_connection_data
| | info : plugin_id=5
| <_mysqlnd_plugin_get_plugin_connection_data
| >mysqlnd_ms_pick_server
| | >_mysqlnd_plugin_get_plugin_connection_data
| | | info : plugin_id=5
| | <_mysqlnd_plugin_get_plugin_connection_data
| | >mysqlnd_ms_choose_connection_random_once
| | | >mysqlnd_ms_query_is_select
| | | | >mysqlnd_tok_create_scanner
| | | | <mysqlnd_tok_create_scanner
| | | | >mysqlnd_tok_get_token
| | | | | info : token=329
| | | | | info : strval=ms=master
| | | | <mysqlnd_tok_get_token
| | | | info : forced master
| | | | >mysqlnd_tok_get_token
| | | | | info : token=709
| | | | <mysqlnd_tok_get_token
| | | | >mysqlnd_tok_free_scanner
| | | | <mysqlnd_tok_free_scanner
| | | <mysqlnd_ms_query_is_select
| | | info : USE_MASTER rnd_idx=0
| | | info : Using master connection
| | <mysqlnd_ms_choose_connection_random_once
| <mysqlnd_ms_pick_server
| info : Connection 0xf5ab00
| >mysqlnd_conn::query
| | info : conn=6 query=/*ms=master*/SET @myrole='master'
| | >mysqlnd_conn::simple_command
| | | info : command=QUERY ok_packet=13 silent=0
| | | >mysqlnd_protocol::get_command_packet
| | | <mysqlnd_protocol::get_command_packet
| | | >php_mysqlnd_cmd_write
| | | | >mysqlnd_net::send
| | | | | info : conn=6 count=34 compression=0
| | | | | info : no compression
| | | | | >mysqlnd_net::network_write
[...]

The mysqlnd debug log is the ultimate tool – beside a debugger – to learn how mysqlnd_ms works internally. However, it is targeting developers and not users.

Reporting bugs

If you find that PECL/mysqlnd_ms is not working as it should or you have a feature request, please tell us. It should not be hard to find ways to contact me, Andrey or Johannes. Bugs can be reported using the php.net/PECL bug tracker. Needless to say, it would be fantastic if you followed the hints from above on debugging when filing a bug report to give as much qualified input as possible.

Happy Easter, happy hacking!

Comments are closed.