X

MySQL and HeatWave

  • MySQL
    September 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.

Join the discussion

Comments ( 2 )
  • Richard Hernandez Sunday, September 29, 2013

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

    Hoping for more discussion.


  • rafal Wednesday, October 2, 2013

    Some information on trace event data:

    When trace event is reported to a plugin, additional arguments are passed in st_trace_event_args structure. The members of this structure hold different pieces of information relevant for different trace events - see its documentation in include/mysql/plugin_trace.h. When an event is reported only relevant members of the structure are filled - other members are NULL/0.

    A pointer to the contents of the packet being sent or received is stored in pkt member. Member pkt_len holds the length of the data. Only packet payload is given, without the 4 byte packet header.

    For SEND_COMMAND event, the payload of the command packet is split into 2 parts. The header, given by hdr and hdr_len members, contains a fixed length initial part of the packet. The rest of the payload is available through pkt and pkt_len members.


Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.