Debugging MySQL execution with server tracing

In the life of a professional MySQL DBA there comes a moment when issues are no longer trivial enough to be diagnosed using simple repros and built-in diagnostic commands. While trying to understand complex problems, you may be forced (challenged?) to look for answers at the lowest level, by analyzing the server's source code.

If you're a seasoned database engineer who killed several keyboards reporting MySQL bugs, you can stop reading now. If you're just about to begin your journey into the source, you could probably use all the help you can get so keep reading. In this short article I'll describe the MySQL server tracing feature I've been using as an aid during MySQL investigations.

When investigating issues at code level, one of the first questions you will ask yourself is "where do I start?". Let's say you're attempting to debug a SHOW CREATE TABLE statement that does not work as expected. Unless you're already familiar with MySQL sources (in which case you're wasting your time reading this), you need something to point you in the right direction and this is where MySQL debugging/tracing options may be of great help.

MySQL is able to generate trace files describing internal server execution step-by-step. The feature is quite flexible and lets you do many cool things, such as:

• Generate step-by-step execution traces showing function nesting with references to source files/lines executed by the server,
• Debug all executed functions or selectively include/exclude functions,
• Enabled/disable tracing server-wide or on a per-session basis,
• Tag each trace line with a process ID or thread ID that generated it. This is particularly useful for server-wide debugging.

You can read more in dbug_package documentation here.

Being able to generate trace files is very useful as it allows you to follow server execution line by line and function by function, so that you know exactly which parts of the code you should be looking at. 

To start debugging MySQL, you need the following:

• A MySQL server compiled with debugging (see reference),
• An easy way to enable/disable debugging, preferably a script that would let you quickly generate execution traces for a pre-defined list of SQL statements.

Once you have a MySQL server compiled for debugging, you can either start MySQL with --debug parameter or you can enable/disable debugging at runtime. I like to use the latter option as it allows me to only generate traces from the operations I'm interested in. See here for the full list of options supported by --debug parameter. For my tests, I use the following format:

d:t:F:L:o,/trace/file/path:-f,my_raw_malloc,alloc_root,free_root

This stands for:

• d: (with no modifiers) enables output from all debugging macros,
• t: enable function call/exit trace lines,
• F: print source file name for  each line of output,
• L: print source line for each line of output (probably only useful with F),
• o, /trace/file/path: direct output to /trace/file/path,
• -f,my_raw_malloc,alloc_root,free_root: do not include calls/exits from these three functions in the output. Traces for memory allocation functions are too low-level to be useful in most cases so I'm using this switch to reduce the amount of background noise in trace files.

Before I show you the simple bash script I use for generating traces, here's some background about my testing environment:

• I run multiple MySQL versions on the same server, each using its own port and socket file. The script below connects to MySQL via Unix socket and assumes that a socket file name is "/tmp/mysql-X.Y.Z.sock" e.g. "/tmp/mysql-5.7.9.sock".
• I run debug and non-debug versions of MySQL on the same machine but as you can see above, the socket file name is only determined by the server version. For that reason, the script is prepared to check if the MySQL process is running with debugging.
• The script reads SQL statements from an input file and executes them with debugging enabled. Alternatively I could be enabling debugging for the entire server but I wanted to ensure that trace files don't contain any output not related to the statements listed in the input file.
• Connection parameters are specified in the connectionString parameter.

The script goes like this:

mysql@sandbox:~$ cat ./gen_trace.sh
#!/bin/bash


if [ -z $1 ]; then

 echo "Usage: $0 X.Y.Z"
 exit 1

fi

socketFile="/tmp/mysql-$1.sock"
traceFile="/home/mysql/traces/mysql-$1.trace"
inputFile="/home/mysql/trace_input.sql"
tmpFile="$inputFile.tmp"

connectionString="mysql -S $socketFile -uroot -p123password"

debugOptions="d:t:F:L:o,$traceFile:-f,my_raw_malloc,alloc_root,free_root"

##

if [ ! -S $socketFile ]; then
 echo "Socket file $socketFile does not exist. Did you forget to start MySQL again?"
 exit 1
fi

if [ ! -f $inputFile ]; then
 echo "Input file $inputFile does not exist"
 exit 1
fi

isMysqlDebug=`$connectionString -e "show variables like 'version'" |grep debug|wc -l`

if [ $isMysqlDebug -ne 1 ]; then
 echo "MySQL is not running in debug mode"
 exit 1
fi

## Remove any existing trace/temp files

rm -f $traceFile
rm -f $tmpFile

## Enable tracing, execute input script

echo `date` "Reading statements from $inputFile"

echo "set session debug = '$debugOptions';" > $tmpFile
cat $inputFile >> $tmpFile

echo `date` "Generating trace to $traceFile"

$connectionString < $tmpFile > /dev/null 2>&1

echo `date` "done"

## Cleanup

rm $tmpFile

And it can be invoked using just a single argument i.e. the MySQL version to connect to:

mysql@sandbox:~$ ./gen_trace.sh 5.7.9
mysql: [Warning] Using a password on the command line interface can be insecure.
Wed Dec 2 22:08:09 UTC 2015 Reading statements from /home/mysql/trace_input.sql ...
Wed Dec 2 22:08:09 UTC 2015 Generating trace to /home/mysql/traces/mysql-5.7.9.trace ...
Wed Dec 2 22:08:09 UTC 2015 done

That's about it! Once the script executes, you get a nice trace file with lines that look like this:

mysql@sandbox:~$ fgrep -A2 '>mysql_parse' /home/mysql/traces/mysql-5.7.9.trace
  sql_parse.cc:  5219: | | >mysql_parse
  sql_parse.cc:  5220: | | | mysql_parse: query: 'show create table pstest.table1'
  sql_parse.cc:  5083: | | | >mysql_reset_thd_for_next_command

Each line shows the source code file (and line) where the operation happens, plus the details of the operation itself. In this case we see a call to mysql_parse for the SHOW CREATE TABLE statement I was diagnosing. Neat!

Of course, the output gets very long for more complex commands or if you're tracing internal server execution instead of looking at individual queries. In any case, output lines follow the same format and they're fairly easy to read.

Summary

Even if MySQL source code is relatively easy to read, with debugging features you don't need to jump straight into the code and risk getting lost forever. Scripted execution tracing can be very helpful in understanding MySQL internals as it lets you obtain a good amount of low-level diagnostic data without spending too much of your precious time.