WL#6226: Protocol tracing - client side

Affects: Server-5.7   —   Status: Complete   —   Priority: Medium

Rationale
=========
This opens a possibility to collect data about performance of client-server 
connection (on client side). The CTA plugin for libmysql will use this 
protocol-tracing infrastructure.

Description
===========
Define hooks inside client library code which allow tracing of protocol events 
such as:
- sending packets to server,
- receiving various kinds of server replies (simple ERR/OK, resultset metadata, 
  resultset rows etc),
- various stages of authentication handshake.

Normally these hooks will do nothing (and should introduce minimal overhead). But 
there will be a possibility to load a trace plugin, which would be invoked by the 
hooks and which can process the events in some way.

Notes
=====
- Pushed to mysql-trunk on 2013-07-24.

User Documentation
==================
http://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-2.html
http://dev.mysql.com/doc/refman/5.7/en/writing-protocol-trace-plugins.html
A new type of client-side plugin, MYSQL_CLIENT_TRACE_PLUGIN will be defined. 
Such trace plugin, if loaded into libmysql, will receive notifications about 
various events related to MySQL protocol exchange with the server. It is up to 
the plugin to decide what to do with this information.

Only one trace plugin can be loaded at a time. Attempts to load another plugin 
of type MYSQL_CLIENT_TRACE_PLUGIN when one is already loaded will trigger an 
error.

After plugin is loaded, all new connections will be traced using that plugin. 
Connections which were active at the time of loading the plugin will not be 
traced.

Note: Only new connections can be traced and tracing always starts in
CONNECTING stage. An on-going connection which was not traced from the beginning 
can not be traced later.

Trace plugin methods
====================
A trace plugin will provide the following methods:

tracing_start
-------------
Called when tracing with this plugin is enabled on a connection.

Input:
 - pointer to the plugin instance (self),
 - connection handle,

Output:
 - pointer to plugin-specific, per-connection data (if any).

A trace plugin might want to maintain a per-connection information. It can
return a pointer to memory area holding such information. It will be stored in a 
connection handle and passed to other plugin methods.


tracing_stop
------------
Called when tracing with this plugin on a connection has stopped.

Input:
 - pointer to the plugin instance (self),
 - connection handle,
 - this plugin's per-connection data (if any),

Output: none.

If a plugin allocated any per-connection resources, it should de-allocate them 
here.


trace_event
-----------
Called when a trace event occurs.

Input:
 - pointer to the plugin instance (self),
 - trace event
 - current protocol stage
 - connection handle
 - plugin's per-connection data (if any),
 - optional trace event parameters.

Output:
 Indication whether tracing of the connection should be stopped here or 
 continued.

It is up to the plugin to decide what to do in this method. However, it can not 
send queries or other commands to the server because trace_event method can be 
called inside on-going conversation between client and server. The only 
exception is the AUTHENTICATED trace event (see below). When this event is 
passed to trace_event() method, the state of the client is such that it can send 
new queries and commands to the server. Generating of trace events will be 
suppressed for queries and commands issued inside trace_event() method.


Trace events
============

A trace plugin will be notified of the following events:

---------------------- -----------------------------------------------------
Connection events
---------------------- -----------------------------------------------------
CONNECTING             Client is connecting to the server.
CONNECTED              Physical connection has been established.
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           Cleint 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.
---------------------- -----------------------------------------------------

Note: The following commands used for replication are not supported: 
COM_BINLOG_DUMP, COM_BINLOG_DUMP_GTID, COM_TABLE_DUMP. When such command is 
issued by client, tracing of the connection will stop after sending DISCONNECTED 
event to the plugin.

Trace event data
----------------

For same events additional information will be passed to event handler:

- Packet to be sent and its length for: SEND_SSL_REQUEST,
  SEND_AUTH_RESPONSE, SEND_AUTH_DATA, SEND_FILE.
- For SEND_COMMAND, the command code and header and arguments part of the
  command packet with their lengths (as accepted by net_write_command).
- Packet received from server and its length for: PACKET_RECEIVED and
  CHALLENGE_RECEIVED.
- Authentication plugin name for AUTH_PLUGIN.


MySQL protocol stages
=====================

A client following the MySQL protocol goes through several stages of it. Each 
stage determines what packets can be expected from the server or can be send by 
the client.

Upon receiving each trace event, trace plugin will be notified of the current 
protocol stage so that it can correctly interpret the event.

These are the possible protocol stages and the transitions between them.

.. digraph:: protocol_stages

  CONNECTING -> WAIT_FOR_INIT_PACKET;
  CONNECTING -> DISCONNECTED [ label = "failed connection" ];

  WAIT_FOR_INIT_PACKET -> AUTHENTICATE;
  WAIT_FOR_INIT_PACKET -> SSL_NEGOTIATION -> AUTHENTICATE;

  AUTHENTICATE -> READY_FOR_COMMAND [ label = "accepted" ];
  AUTHENTICATE -> DISCONNECTED [ label = "rejected" ];

  READY_FOR_COMMAND -> DISCONNECTED [ label = "COM_QUIT" ];
  READY_FOR_COMMAND -> AUTHENTICATE [ label="after change user" ];
  READY_FOR_COMMAND -> WAIT_FOR_PACKET -> READY_FOR_COMAND;
  READY_FOR_COMMAND -> WAIT_FOR_RESULT
  READY_FOR_COMMAND -> WAIT_FOR_PS_DESCRIPTION
                                    [ label="after prepare command" ];
  READY_FOR_COMMAND -> WAIT_FOR_FIELD_DEF
                                    [ label="COM_FIELD_LIST" ];

  WAIT_FOR_RESULT -> READY_FOR_COMMAND [ label="simple reply" ];
  WAIT_FOR_RESULT -> WAIT_FOR_FIELD_DEF;
  WAIT_FOR_RESULT -> FILE_REQUEST;

  WAIT_FOR_FIELD_DEF -> WAIT_FOR_ROW [ label="in a resultset" ];
  WAIT_FOR_FIELD_DEF -> READY_FOR_COMMAND
                        [ label="after describe table or prepare command" ];

  WAIT_FOR_ROW -> READY_FOR_COMMAND;
  WAIT_FOR_ROW -> WAIT_FOR_RESULT [ label="multi-resultset" ];

  WAIT_FOR_PS_DESCRIPTION -> WAIT_FOR_PS_PARAMETER;
  WAIT_FOR_PS_DESCRIPTION -> READY_FOR_COMMAND
                                     [ label="no params and result" ];
  WAIT_FOR_PS_DESCRIPTION -> WAIT_FOR_FIELD_DEF [ label="no params" ];

  WAIT_FOR_PS_PARAMETER -> WAIT_FOR_FIELD_DEF;
  WAIT_FOR_PS_PARAMETER -> READY_FOR_COMMAND [ label="no result" ];

  FILE_REQUEST -> WAIT_FOR_RESULT [label="when whole file sent"];
Per-connection data for protocol tracing
========================================
The protocol tracing subsystem will store the following data in each connection 
handle:

------------------- -------------------------------------------------------
 plugin             pointer to the plugin tracing this connection
------------------- -------------------------------------------------------
 trace_plugin_data  pointer to the plugin specific data as returned by
                    plugin's tracing_start method
------------------- -------------------------------------------------------
 stage              current stage of the protocol
------------------- -------------------------------------------------------

  struct st_mysql_trace_info
  {
    struct st_mysql_client_plugin_TRACE   *plugin;
    void                       *trace_plugin_data;
    enum  mysql_trace_stage    stage;
  };


A pointer to st_mysql_trace_info struture will be stored inside
st_mysql_extension structure pointed by MYSQL::extension member:

  struct st_mysql_extension {
    struct st_mysql_trace_info *trace_data;
  }

The MYSQL::extension will be allocated only if used. Macro GET_EXTENSION(M) will 
return a pointer to the extension member of MYSQL handle M, allocating it if not 
done already. The memory pointed by MYSQL::extension will be freed inside 
mysql_close() function.


Trace plugin API
================

typedef
void* (tracing_start_callback)(struct st_mysql_client_plugin_TRACE *self,
                               struct st_mysql *connection_handle,
                               enum mysql_trace_stage stage);
typedef
void (tracing_stop_callback)(struct st_mysql_client_plugin_TRACE *self,
                             struct st_mysql *connection_handle,
                             void   *plugin_data, short int shutdown);
typedef
int (trace_event_handler)(struct st_mysql_client_plugin_TRACE *self,
                          void *data,
                          struct st_mysql *connection_handle,
                          enum mysql_trace_stage stage,
                          enum mysql_trace_event event,
                          struct st_trace_event_args args);

struct st_mysql_client_plugin_TRACE
{
  MYSQL_CLIENT_PLUGIN_HEADER
  tracing_start_callback *tracing_start;
  tracing_stop_callback  *tracing_stop;
  trace_event_handler    *trace_event;
};


enum mysql_trace_stage contains PROTOCOL_STAGE_XXX constant for each
protocol stage specified in HLS.

enum mysql_trace_event contains TRACE_EVENT_XXX constant for each trace
event specified in HLS.

Structure st_trace_event_args contains members to store all possible trace event 
arguments:

struct st_trace_event_args
{
  const char          *plugin_name;
  int                  cmd;
  const unsigned char *hdr;
  size_t               hdr_len;
  const unsigned char *pkt;
  size_t               pkt_len;
};

Various events store their arguments in the structure as follows. Unused members 
are set to 0/NULL.

 AUTH_PLUGIN    
------------- ----------------------------------
 plugin_name  the name of the plugin
------------- ----------------------------------

 SEND_COMMAND   
------------- ----------------------------------
 cmd          the command code
 hdr          pointer to command packet header
 hdr_len      length of the header
 pkt          pointer to command arguments
 pkt_len      length of arguments
------------- ----------------------------------

 Other SEND_* and *_RECEIVED events
------------- ----------------------------------
 pkt          the data sent or received
 pkt_len      length of the data
------------- ----------------------------------

 PACKET_SENT
------------- ----------------------------------
 pkt_len      number of bytes sent
------------- ----------------------------------


Global trace plugin pointer
===========================

A global pointer to the loaded trace plugin instance will be defined:

  extern "C" struct st_mysql_client_plugin_TRACE *trace_plugin;

Initially this pointer will be NULL. It will be set inside add_plugin() function 
in cleint_plugin.c if it is discovered that the plugin being added is a trace 
plugin.

If a trace plugin is loaded and trace_plugin is not NULL, an attempt to load 
another trace plugin will lead to an error.

When a trace plugin is loaded, trace events in on-going connections will not be 
reported to it. Only new connections starting in CONNECTING phase will be traced 
with the plugin. Connections which are traced and for which trace events are 
reported to the trace plugin are distinguished by the fact that for them 
MYSQL::extension->trace_data is not NULL.


Handling of trace events
========================

In places where trace events happen, trace hook will be inserted. It will
be a call of MYSQL_TRACE macro like this:

 MYSQL_TRACE(PACKET_RECEIVED, mysql, (len, net->read_pos));

where PACKET_RECEIVED is the event which happens, followed by connection
handle and optional event parameters.

The macro will expand to code for processing trace event. However, processing 
will be skipped if global trace_plugin pointer is NULL (no trace plugin loaded 
yet) or this connection is not traced (MYSQL::extension->trace_data is NULL). 
Tracing connection is initialized and connection's trace_data allocated when 
CONNECTING stage is set with MYSQL_TRACE_STAGE() macro (see below).

The logic for processing trace event in MYSQL_TRACE(Event, M, Args) macro will 
be as follows.

Note: not all of the logic needs to be in the macro expansion. For
efficiency, mostly the initial test determining whether further processing will 
be done should be inlined as macro expansion. The actual event
processing logic can be implemented as inline functions for example.

--------------------------------------------------------------------

 if trace_plugin is NULL or M->extension->trace_data is NULL
 then do nothing and stop;

 let trace_data= M->extension->trace_data;

 if defined, call trace_event(...) method of trace_plugin passing to it:
  - current event: Event,
  - connection handle: M,
  - current protocol stage: trace_data->stage,
  - plugin's per-connection data: trace_data->trace_plugin_data,
  - event arguments: Args.

 if current stage or Event is DISCONNECTED 
    or trace_event() method returned non-zero value
 then
   call tracing_stop(...) method of trace_plugin, if defined.
   free M->extension->trace_data and set it to NULL (this disables 
   further tracing in this connection);
 fi

--------------------------------------------------------------------

Protocol Stage Changes
======================
Hooks will be placed in code in places where new protocol stage is entered. 
These will be calls of MYSQL_TRACE_STAGE() macro like this:

  MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT);

The macro will store the new protocol stage in mysql->extension->tace_data.stage 
and this will be used when next trace event is reported to the trace plugin.

If the stage is CONNECTING, tracing in the connection will be initialized
(unless trace_plugin is NULL):

1. allocate trace_data structure and store pointer to it in 
   mysql->extension,
2. set trace_data.plugin to trace_plugin, trace_plugin.stage to CONNECTING,
3. call plugins trace_start() method, if defined.
4. if trace_start() returned a pointer, store it in 
   trace_data.trace_plugin_data, otherwise it is set to NULL.


Thread safety
=============

Tracing infrastructure does not enforce any synchronization between different 
application threads. This should be safe, assuming that only one application 
thread can use given MYSQL connection instance. Under that assumption the only 
shared resource is the global trace_plugin pointer. Even without 
synchronization, the following code is thread safe:

  if trace_plugin not NULL then
    use trace_plugin ...
  fi

This is because tace_plugin can be set from NULL to something not-NULL in a
parallel thread, but once it is not-NULL, its value will never change.

Important Note
--------------
Trace plugin methods must be thread-safe, as they can be called from different 
threads without any synchronization.


Implementation
==============
A tree with patch implementing this WL can be found here:

 bzr+ssh://myrepo.no.oracle.com/bzrroot/rsomla/mysql-wl6226


If configured with WITH_TEST_TRACE_PLUGIN build option, it will build libmysql
with built-in, pre-loaded test trace plugin and all the standard clients will
use this plugin. Test plugin will produce diagnostic output on stderr if 
MYSQL_TEST_TRACE_DEBUG environment variable is set to something else than 0.

Note: Test trace plugin can disclose passwords and other security sensitive
information in the diagnostic output.

Example output
--------------
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 reque
t 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
test_trace: 081: stage: READY_FOR_COMMAND, event: SEND_COMMAND
test_trace: 081: QUERY: SELECT user()

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: 28 bytes
  03 64 65 66 00 00 00 06  75 73 65 72 28 29 00 0C   .def....user()..
  08 00 4D 00 00 00 FD 00  00 1F 00 00               ..M.........
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: 15 bytes
  0E 72 6F 6F 74 40 6C 6F  63 61 6C 68 6F 73 74      .root@localhost
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
+----------------+
| user()         |
+----------------+
| root@localhost |
+----------------+
test_trace: 081: stage: READY_FOR_COMMAND, event: SEND_COMMAND
test_trace: 081: QUIT
test_trace: 081: stage: READY_FOR_COMMAND, event: PACKET_SENT
test_trace: 081: stage: READY_FOR_COMMAND, event: DISCONNECTED
test_trace: 081: Connection  closed
test_trace: 081: Tracing connection has ended
test_trace: Test trace plugin de-initialized

Getting code coverage info
--------------------------
To get code coverage one needs to configure build with ENABLE_GCOV option. Then, 
after building tree and running some tests, one can run gcov to generate .gcov 
files with the coverage information. I use this invocation:

gcov -o build/libmysql/CMakeFiles/clientlib.dir mysql_trace.c.o

which generates mysql_trace.c.gcov + some other files.