Thursday Sep 26, 2013

Tracing MySQL Protocol from Client Side

Protocol tracing infrastructure

Since introduction of PERFORMANCE_SCHEMA in MySQL Server, it is possible to trace what happens inside the server when it executes client queries. The client-side protocol tracing framework is a similar mechanism in the MySQL Client Library. It allows tracing communication of the client with the server. The infrastructure has been included in MySQL 5.7.2 Development Milestone Release.

Unlike PERFORMANCE_SCHEMA, focus of the client-side tracing framework is on tracing the protocol flow and client-server I/O rather than the performance of the client library implementation. The client-side tracing framework recognizes trace events which happen during normal conversation between the client and the server. Events such as sending packets to the server, receiving server replies, establishing and terminating a connection are recognized. These events can be passed to a trace plugin if one is loaded into the library. Trace plugin defines callback functions which are called by the protocol tracing framework when trace events happen.

Protocol tracing infrastructure is enabled by default in the client library. However, it does nothing until a trace plugin is loaded. It is possible to build client library with a test trace plugin included in it and use it to see the protocol tracing framework in action (see below). In what follows it is also described how to build and use own protocol trace plugins.

Note that there can be only one trace plugin loaded into the library. An attempt to load another trace plugin results in an error. This means that to use custom trace plugins one has to use client library without the test trace plugin built into it, as is the case when it is distributed by MySQL.

Test trace plugin

When building client library from sources it can be configured to include a built-in test trace plugin using WITH_TEST_TRACE_PLUGIN cmake option. If this was the case, then the test trace plugin is enabled in the library without any further configuration. It receives trace events and follows the protocol flow checking that everything goes as expected.

By default test trace plugin keeps quiet and ignores unexpected turns in the protocol flow. But user can tell it to produce diagnostic output on standard error stream by setting environment variable MYSQL_TEST_TRACE_DEBUG to something else than 0. An example output produced by the plugin might look as follows:


test_trace: Test trace plugin initialized
test_trace: Starting tracing in stage CONNECTING
test_trace: stage: CONNECTING, event: CONNECTING
test_trace: stage: CONNECTING, event: ERROR
test_trace: error 2038: Can't open shared memory; client could not create requet event (0)
test_trace: stage: CONNECTING, event: CONNECTED
test_trace: stage: WAIT_FOR_INIT_PACKET, event: READ_PACKET
test_trace: stage: WAIT_FOR_INIT_PACKET, event: PACKET_RECEIVED
test_trace: packet received: 74 bytes
  0A 35 2E 35 2E 32 37 00  51 00 00 00 28 3F 43 73   .5.5.27.Q...(?Cs
  3C 6C 2E 3F 00 FF F7 21  02 00 0F 80 15 00 00 00   <l.?...!........
test_trace: 081: stage: WAIT_FOR_INIT_PACKET, event: INIT_PACKET_RECEIVED
test_trace: 081: stage: AUTHENTICATE, event: AUTH_PLUGIN
test_trace: 081: Using authentication plugin: mysql_native_password
test_trace: 081: stage: AUTHENTICATE, event: SEND_AUTH_RESPONSE
test_trace: 081: packet sent: 60 bytes
  85 A2 3F 00 00 00 00 01  08 00 00 00 00 00 00 00   ..?.............
  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00   ................
test_trace: 081: stage: AUTHENTICATE, event: READ_PACKET
test_trace: 081: stage: AUTHENTICATE, event: PACKET_RECEIVED
test_trace: 081: packet received: 7 bytes
  00 00 00 02 00 00 00                               .......
test_trace: 081: stage: AUTHENTICATE, event: AUTHENTICATED
test_trace: 081: stage: READY_FOR_COMMAND, event: SEND_COMMAND
test_trace: 081: QUERY: select @@version_comment limit 1
test_trace: 081: stage: READY_FOR_COMMAND, event: PACKET_SENT
test_trace: 081: stage: WAIT_FOR_RESULT, event: READ_PACKET
test_trace: 081: stage: WAIT_FOR_RESULT, event: PACKET_RECEIVED
test_trace: 081: packet received: 1 bytes
  01                                                 .
test_trace: 081: Expecting result set with 1 columns
test_trace: 081: stage: WAIT_FOR_FIELD_DEF, event: READ_PACKET
test_trace: 081: stage: WAIT_FOR_FIELD_DEF, event: PACKET_RECEIVED
test_trace: 081: packet received: 39 bytes
  03 64 65 66 00 00 00 11  40 40 76 65 72 73 69 6F   .def....@@versio
  6E 5F 63 6F 6D 6D 65 6E  74 00 0C 08 00 13 00 00   n_comment.......
test_trace: 081: Received next field definition
test_trace: 081: stage: WAIT_FOR_FIELD_DEF, event: READ_PACKET
test_trace: 081: stage: WAIT_FOR_FIELD_DEF, event: PACKET_RECEIVED
test_trace: 081: packet received: 5 bytes
  FE 00 00 02 00                                     .....
test_trace: 081: No more fields
test_trace: 081: Reading result set rows
test_trace: 081: stage: WAIT_FOR_ROW, event: READ_PACKET
test_trace: 081: stage: WAIT_FOR_ROW, event: PACKET_RECEIVED
test_trace: 081: packet received: 20 bytes
  13 53 6F 75 72 63 65 20  64 69 73 74 72 69 62 75   .Source distribu
  74 69 6F 6E                                        tion
test_trace: 081: Received next row
test_trace: 081: stage: WAIT_FOR_ROW, event: READ_PACKET
test_trace: 081: stage: WAIT_FOR_ROW, event: PACKET_RECEIVED
test_trace: 081: packet received: 5 bytes
  FE 00 00 02 00                                     .....
test_trace: 081: End of data  

We can see the various trace events reported to the plugin and the data such as packet contents provided with each event. Note that the protocol tracing infrastructure maintains information about the current stage of the protocol. This is helpful for trace plugin to correctly interpret trace events. For example, a packet received from server (PACKET_RECEIVED event) has different meaning and structure depending on whether it arrives during authentication phase (WAIT_FOR_INIT_PACKET stage), just after query has been sent (WAIT_FOR_RESULT stage), when server sends result set metadata (WAIT_FOR_FIELD_DEF stage) or when it sends rows of a result set (WAIT_FOR_ROW stage).

As can be seen the output is quite verbose thus MYSQL_TEST_TRACE_DEBUG should be enabled only for debugging purposes. One can also instruct the test trace plugin to crash client application if it detects problems in the protocol flow. This is done by setting environment variable MYSQL_TEST_TRACE_CRASH to something else than 0.

How to write a trace plugin

Protocol trace plugins, as any other client-side plugins, are loaded into the client library from a shared module. Client library must know the location where plugin modules are stored (MYSQL_PLUGIN_DIR option) and the plugin must be explicitly loaded into the library using mysql_load_plugin() C API call. It is also possible to name the plugin module using environment variable LIBMYSQL_PLUGINS and then it will be automatically loaded during client library initialization. See documentation of plugin functions in C API for the details.

A plugin module must define plugin descriptor using mysql_declare_client_plugin() macro. This macro and other relevant types are defined by <mysql.h> and <mysql/plugin_trace.h> headers which should be included prior to defining a trace plugin.

mysql_declare_client_plugin(TRACE)
  "my_trace_plugin",            /* plugin name */
  "Author Name",                /* author */
  "protocol trace plugin",      /* description */
  {1,0,0},                      /* version = 1.0.0 */
  "GPL",                        /* license type */
  NULL,                         /* for internal use */
  plugin_init,                  /* plugin initialization function */
  plugin_deinit,                /* plugin shutdown function */
  plugin_options,               /* option-handling function */
  tracing_start,                /* start tracing new connection */
  tracing_stop,                 /* stop tracing connection */
  trace_event                   /* handle trace event */
mysql_end_client_plugin;

Callback functions plugin_init(), plugin_deinit() and plugin_options() are the same as for any other type of client-side plugin and are described in plugin data structures documentation.

Callbacks tracing_start(), tracing_stop() and trace_event() are specific to trace plugins and are documented in <mysql> header. Function tracing_start() is called when a new connection is established with mysql_real_connect() C API call. This happens at a very early stage, before any packets are exchanged with the server. Function might return a pointer to plugin specific trace data which will be kept in the MYSQL connection handle and passed to other tracing callbacks. Note that this function is different from the global plugin initialization function plugin_init() which is called only once, after loading the plugin. Function tracing_start() is called for each new connection made by the client.

Function tracing_stop() is called when tracing of the connection has ended. This can happen due to normal connection termination as defined by the protocol, because of connection error detected in the client library or because tracing of this connection has been explicitly terminated by trace_event() callback (see below). This function should de-allocate any resources allocated in tracing_start().

Function trace_event() is called by the protocol tracing infrastructure when various trace events happen. The current protocol stage and additional arguments are passed with each trace event so that this function can for example examine contents of the packets being sent or received. Function trace_event() can tell the protocol-tracing infrastructure to stop tracing the current connection by returning non-zero value.

Here is a list of trace events that are reported to a protocol trace plugin:


Connection events
CONNECTING Client is connecting to the server.
CONNECTED Client is connecting to the server.
DISCONNECTED Connection with server was terminated.
SSL events
SEND_SSL_REQUEST Client is sending SSL connection request.
SSL_CONNECT Client is initiating SSL handshake.
SSL_CONNECTED SSL connection has been established.
Authentication events
INIT_PACKET_RECEIVED Client received initial handshake packet.
AUTH_PLUGIN Client selects an authentication plugin to be used in the following authentication exchange.
SEND_AUTH_RESPONSE Client sends response to the authentication challenge.
SEND_AUTH_DATA Client sends extra authentication data packet.
AUTHENTICATED Server has accepted connection.
Command phase events
SEND_COMMAND Client is sending a command to the server.
SEND_FILE Client is sending local file contents to the server.
General events
READ_PACKET Client starts waiting for a packet from server.
PACKET_RECEIVED A packet from server has been received.
PACKET_SENT After successful sending of a packet to the server.
ERROR Client detected an error.

Test trace plugin implementation

A good place to look for an example of a trace plugin implementation is file test_trace_plugin.cc in libmysql/ subdirectory of MySQL Server source tree. It defines the test trace plugin described above.

Note that test trace plugin is a bit special as it is not loaded dynamically into client library, but it is built into it. This is why the plugin is not declared with the mysql_declare_client_plugin() macro but rather the plugin descriptor structure is defined explicitly. It is then added to the mysql_client_builtins[] array defined in sql-common/client.c.

Looking at the code in test_trace_plugin.cc one can see there how plugin's specific trace data structure st_trace_data is allocated in trace_start() callback. Among other things it contains a next_stage member which specifies the expected stage of the protocol when next trace event is reported. This expected stage is updated in check_event_XXX() functions called from the main trace_event() callback. In trace_event() function there is a check that the protocol stage reported by trace infrastructure is as expected:

if (data && data->next_stage != stage)
{
  LOG(("wrong stage, expected: %s",
       protocol_stage_name(data->next_stage)));
  if (opt_crash)
    DBUG_ASSERT(0);
}

One can also see how trace_event() function analyses arguments passed with each trace event and shows them in the log.

Full discussion of the implementation of test trace plugin is out of the scope of this article. But hopefully the source code and comments there can give an idea how one can write a trace plugin and what can be achieved with the protocol-tracing infrastructure.

About

Get the latest updates on products, technology, news, events, webcasts, customers and more.

Twitter


Facebook

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
2
5
6
9
10
11
12
13
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today