Analyzing MySQL with strace

By
Analyzing MySQL with strace

Analyzing MySQL with straceIn this blog post, we will briefly explore the OS tool strace. It is not widely used due to its performance impacts, and we don’t recommend using it in production. Still, it is amazing at helping you understand some things that happen in MySQL, where the OS is involved, and as a last case resource for troubleshooting.

The strace tool intercepts and records any system calls (a.k.a.  syscalls) performed and any signals received by a traced process. It is excellent for complex troubleshooting, but beware, as it has a high-performance impact for the traced process.

We start our exploration with a simple question: what are the files opened in the OS when you issue FLUSH LOGS in MySQL? We could look at the documentation, but we decided to find out using strace.

For that, we started a MySQL lab instance and attached strace to it using the command below:

strace -s2048 -f -o /tmp/strace.out -p $(pgrep -x mysqld)

The -s option is the size of the output print string. The default is 32, which most of the time is not enough, so we use 2k, which allows us to see more lines in the log.

The -f is to follow forks. This is important because MySQL has a thread-based architecture, and the connection we want to analyze (the one running the FLUSH LOGS) is a forked thread from the main process.

The option -o is used to specify an output file and -p specifies the PID to which we want to attach strace (the mysqld PID, in this case).

First, we want to find out what is the OS Thread ID of our session. With that in hand, we can filter the strace.out file, so we don’t have unnecessary noise in our outputs.

We can find our OS Thread ID with SHOW PROCESSLIST alongside the table PERFORMANCE_SCHEMA.THREADS:

mysql> show processlist;
+----+------+-----------------+------+---------+------+----------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+------+-----------------+------+---------+------+----------+------------------+-----------+---------------+
| 5 | root | localhost:47724 | test | Query | 0 | starting | show processlist | 0 | 0 |
+----+------+-----------------+------+---------+------+----------+------------------+-----------+---------------+
1 row in set (0.00 sec)

mysql> select THREAD_OS_ID from performance_schema.threads where PROCESSLIST_ID = 5;
+--------------+
| THREAD_OS_ID |
+--------------+
| 1851 |
+--------------+
1 row in set (0.00 sec)

Now that we have our OS Thread ID, we can issue the FLUSH LOGS using that same session:

mysql> flush logs;
Query OK, 0 rows affected (0.16 sec)

We grep the strace.out file using the Thread ID and look for open and close syscalls (which are the ones used to open and close files) as that is what we want to investigate:

shell> grep 1851 /tmp/strace.out | egrep "open|close"

1851 open("/home/vinicius.grippa/sandboxes/rsandbox_5_7_22/master/data/msandbox.err", O_WRONLY|O_CREAT|O_APPEND, 0666) = 32
1851 close(32) = 0
1851 open("/home/vinicius.grippa/sandboxes/rsandbox_5_7_22/master/data/msandbox.err", O_WRONLY|O_CREAT|O_APPEND, 0666) = 32
1851 close(32) = 0
1851 openat(AT_FDCWD, "./", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 32
1851 close(32) = 0
1851 close(41) = 0
1851 close(4) = 0
1851 open("./mysql-bin.index", O_RDWR|O_CREAT, 0640) = 4
1851 open("./mysql-bin.~rec~", O_RDWR|O_CREAT, 0640) = 32
1851 close(32) = 0
1851 open("./mysql-bin.~rec~", O_RDWR|O_CREAT, 0640) = 32
1851 open("./mysql-bin.000013", O_WRONLY|O_CREAT, 0640) = 41
1851 open("./mysql-bin.index_crash_safe", O_RDWR|O_CREAT, 0640) = 42
1851 close(42) = 0
1851 close(4) = 0
1851 open("./mysql-bin.index", O_RDWR|O_CREAT, 0640) = 4
1851 close(32) = 0

Looking at the first line, we see the number 1851, which is the Thread ID that made the system calls (the one we used grep on) and then the system call (open) with the file /home/vinicius.grippa/sandboxes/rsandbox_5_7_22/master/data/msandbox.err, which is the configured error log for this particular lab instance.
We also found the MySQL binlog index being opened (mysql-bin.index), a mysql-bin.~rec~ file, the current MySQL binary log (mysql-bin.000013), the file mysql-bin.index_crash_safe, and lastly, mysql-bin.index again.

The error log, the current binary log file, and the binary log index file were all expected to show up in the tests. The files mysql-bin.~rec~ and mysql-bin.index_crash_safe were a surprise at first, but when you investigate a bit, it becomes clear what they are here for.

Here is a quick look at the source code where both these are “created”:

int MYSQL_BIN_LOG::set_purge_index_file_name(const char* base_file_name)
{
    int error = 0;
    DBUG_TRACE;
    if (fn_format(
            purge_index_file_name, base_file_name, mysql_data_home, ".~rec~",
            MYF(MY_UNPACK_FILENAME | MY_SAFE_PATH | MY_REPLACE_EXT))
        == nullptr) {
        error = 1;
        LogErr(ERROR_LEVEL, ER_BINLOG_FAILED_TO_SET_PURGE_INDEX_FILE_NAME);
    }
    return error;
}
int MYSQL_BIN_LOG::set_crash_safe_index_file_name(const char* base_file_name)
{
    int error = 0;
    DBUG_TRACE;
    if (fn_format(crash_safe_index_file_name, base_file_name, mysql_data_home,
            ".index_crash_safe", MYF(MY_UNPACK_FILENAME | MY_SAFE_PATH | MY_REPLACE_EXT))
        == nullptr) {
        error = 1;
        LogErr(ERROR_LEVEL, ER_BINLOG_CANT_SET_TMP_INDEX_NAME);
    }
    return error;
}

The function fn_format is used to format a file name. They are both auxiliary files that help in safely altering the binlog index file.

Conclusion

In conclusion, strace is a powerful tool that gives you unfiltered information on MySQL behavior (regarding system calls). It can be overwhelming, as it outputs a lot of information, but if you know what you are looking for, it is extremely helpful. As a final warning, it is a tool that severely degrades performance and should be avoided in production environments.

Useful Resources

Finally, you can reach us through the social networks, our forum, or access our material using the links presented below:


by Leonardo Bacchi Fernandes via Percona Database Performance Blog

Comments

Post a Comment