Eric Bergen

I’ve posted a new table statistics patch which is the next version of the session table/index statistics patch This version of the patch adds slow query log output. If a query is logged to the slow query log it will have row count statistics added to it.

I’m not sure about the format of the log which is why I’m posting this so early. The first format I tried was:

# Time: 100119 19:24:37
# User@Host: [ebergen] @ localhost []
# Query_time: 10 Lock_time: 0 Rows_sent: 7 Rows_examined: 3
# Rows_read: sbtest.foo:3, sbtest.bar:3,
select * from foo a, bar b where sleep(1) = 0;

Where there would be an additional line for each of rows_changed, rows_changed_x_indexes and index_rows_read. This seemed verbose so I tried a different format of:

# Time: 100119 20:27:16
# User@Host: [ebergen] @ localhost []
# Query_time: 6 Lock_time: 0 Rows_sent: 6 Rows_examined: 14
# Rows Stats: sbtest.foo 18 0 0, sbtest.bar 15 3 3,
# Index Stats: sbtest.bar.u 6,
select * from foo a, bar b where b.u=4 order by sleep(1);

Where the row stats has 3 columns per table of rows_read, rows_changed, rows_changed_x_index. I’m leaning towards the second format but I’m open to ideas. What do you think?

The new patch is here

I had some free time over Thanksgiving so I decided to work on something I have been thinking about for quite some time. I hacked up Google’s show table_statistics patch to also track stats per connection. I say this is a first draft hack because I based it off of the v2 patch which uses a straight up hash table instead of the intermediate object cache.

I’ve added the global/session key word to the existing show table_statistics command in the same way that show status works. This means that the default behavior of show table_statistics is to show session data instead of global data. This is different from the Google patch which only works globally. This has been running in production environments for a bit and seems stable. Note that these environments don’t run at the concurrency that motivated Google to update the patch to be less likely to lock a global mutex. You have been warned!

I’m planning on updating the patch with more stats and a cache for the global stats. So far it’s been useful in debugging queries that have low row estimates in the explain plan but are actually scanning quite a few rows. Explain tends to handle row count estimates for sub queries poorly. It’s handy to copy a query from the slow query log on a production server and run it again using show session table_statistics to see how many rows it actually read from individual tables. I also have plans to have build time tests which can keep track of row counts from a sample database. I also want to look into adding these stats directly into the slow query log.

Here is the updated patch. The patch applies against 5.0.72sp1. Here are the command descriptions.

For table statistics:

SHOW [GLOBAL | SESSION] TABLE_STATISTICS [LIKE 'pattern' | WHERE expr]

FLUSH [GLOBAL | SESSION] TABLE_STATISTICS

Index statistics:

SHOW [GLOBAL | SESSION] INDEX_STATISTICS [LIKE 'pattern' | WHERE expr]

FLUSH [GLOBAL | SESSION] INDEX_STATISTICS

Some examples.

mysql> show session table_statistics;
Empty set (0.00 sec)

mysql> show global table_statistics;
+————+———–+————–+————————-+
| Table | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+————+———–+————–+————————-+
| sbtest.foo | 6 | 0 | 0 |
+————+———–+————–+————————-+
1 row in set (0.00 sec)

mysql> select * from sbtest.foo;
+——-+
| t |
+——-+
| 82921 |
| 24489 |
| 73681 |
+——-+
3 rows in set (0.00 sec)

mysql> show session table_statistics;
+————+———–+————–+————————-+
| Table | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+————+———–+————–+————————-+
| sbtest.foo | 3 | 0 | 0 |
+————+———–+————–+————————-+
1 row in set (0.00 sec)

mysql> show global table_statistics;
+————+———–+————–+————————-+
| Table | Rows_read | Rows_changed | Rows_changed_x_#indexes |
+————+———–+————–+————————-+
| sbtest.foo | 9 | 0 | 0 |
+————+———–+————–+————————-+
1 row in set (0.00 sec)

To continue the pid file theme I’ve found another slight issue. This was unrelated to the testing which I found the previous pid file issues. I was working on an unmonitored development mysql system. While working on it I ran it out of disk space in /. The box has it’s mysql datadir in a separate partition which had plenty of space. The pid file is in a dir on /. When I started mysqld_safe mysqld exited because it couldn’t create the pid file. mysqld_safe continued to restart mysqld until I saw the problem and killed it a few minutes later. I’m not sure exactly why, I didn’t spend very much time digging into a failure that I caused by filling up the disk. mysqld was exiting because it was trying to create a pid file in a full partition.

Note: This was a stock mysqld, not one running my pid file patch.

Previously I wrote about how late the mysql pid file is created in the startup process. At first glance it seemed like a relatively easy thing to fix. In main() there is a call to start_signal_handler(). The first instance of static void start_signal_handler() does only one thing. It checks !opt_bootstrap to make sure mysqld isn’t being called by mysql_install_db. I’m not sure why mysql_install_db can’t have a pid file created but that’s getting outside the scope of my investigation. It seems simple enough to move the call to start_signal_handler() above the call to init_server_components() in main() and have the pidfile created earlier. It turns out pidfile creation happens differently on different arches.

For windows and netware start_signal_handler simply creates the pid file. For __EMX__ (I’m not sure what that is) start signal handler does nothing. By default start_signal_handler starts a signal handler thread. This thread then creates the pid file. I think this can be cleaned up by removing the start_signal_handler functions that either do nothing or only create a pid file and handle the pid file creation for arches that need it directly in main with some good self documenting ifdefs right around it.

I don’t have all the environments to test that this patch really works. I’ve tested it on linux and it does create a pid file and deletes it on shutdown. The pid file is created just after argument parsing and before the heavy weight storage engine initialization.

[Update 2009-12-07: I think the old patch broke embedded. I updated it to ifdef out the call to start_signal_handler]
Here is the patch Create pid file sooner patch.

mysql_safe is responsible for restarting mysqld if it crashes and will exit cleanly if mysqld was shutdown. The way it determines if mysqld shutdown correctly is if the pid file is cleaned up correctly. MySQL does quite a few things before creating the pid file like initializing storage engines. It can take quite a while to initialize innodb if it has to roll forward the transaction log. During this time if mysqld crashes mysqld_safe won’t restart it. Normally this is ok because the server would just crash again but it can mess with your head a bit if you’re testing changes to mysqld_safe. Especially if those changes involve what mysqld_safe does if mysqld crashes. I think it makes sense to create the pidfile earlier and there is a bug for it. Chime in on the bug if this has burned you.

InnoDB Deadlock Count Patch

Deadlocks are a common occurrence in relational databases. They usually aren’t a problem until they start happening too frequently. Innodb can provide you with information about the latest deadlock in SHOW ENGINE INNODB STATUS. This can be useful for debugging but it’s almost impossible to get the rate at which deadlocks are occurring. This patch applies against MySQL 5.0.72sp1 and probably quite a few other versions. It adds a counter to show table status that tracks the number of deadlocks. In this example mysql-1> is connection 1 and mysql-2> is connection 2.

mysql-2> show global status like ‘innodb_deadlocks’;
+——————+——-+
| Variable_name | Value |
+——————+——-+
| Innodb_deadlocks | 0 |
+——————+——-+
1 row in set (0.00 sec)

mysql-1> begin; select * from t where t=1 for update;
Query OK, 0 rows affected (0.00 sec)

+—+
| t |
+—+
| 1 |
+—+
1 row in set (0.00 sec)

mysql-2> begin; select * from t where t=2 for update;
Query OK, 0 rows affected (0.00 sec)

+—+
| t |
+—+
| 2 |
+—+
1 row in set (0.00 sec)

mysql-1> select * from t where t=2 for update;
+—+
| t |
+—+
| 2 |
+—+
1 row in set (1.71 sec)

mysql-2> select * from t where t=1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
mysql> show global status like ‘innodb_deadlocks’;
+——————+——-+
| Variable_name | Value |
+——————+——-+
| Innodb_deadlocks | 1 |
+——————+——-+
1 row in set (0.00 sec)

Enjoy!

In a Great Magnet moment Trent Lloyd posted an excellent write-up on how to recover from relay log name changes on the same day I was going to write up a procedure to send to a client who had a similar issue. Thanks Trent! The problem goes a bit deeper than server hostname changes because there have been a few changes to how mysql handles default log file names in 5.0

Prior to 5.0.38 the default log file name started with the hostname. The problem is, as Trent points out, that if the hostname of the server changes then mysql doesn’t generate default log file names correctly. The error message though is something like:

090825 18:54:53 [ERROR] Failed to open the relay log ‘/mysql/old_hostname-relay-bin.000015′ (relay_log_pos 107657)

There are a few strange things going on here. First if the relay-log index file default name changed and it didn’t know how to open the file then how did it know to open file 15 which is the file it was processing before? The answer is simple, it gets that information from the relay-log.info file which records where the sql thread is in it’s processing. If it was processing that file and it exists, and it knows the correct file name then why can’t it open it?

A quick scan of the source shows two problems. Once the error messages are very vague, the other is that they are printed in a different order than they happened. This message:

[ERROR] Could not find target log during relay log initialization

Actually happens before the Failed to open relay log message. It’s just saved in a variable and printed out later. This message is kind of cryptic. It should be:

[ERROR] Could not find log file ‘old_hostname-relay-bin.000015′ in relay log index file ‘/mysql/new_hostname-relay-bin.index’

The issue isn’t that MySQL couldn’t open the binlog file. The file is there and perfectly healthy. The issue is that MySQL couldn’t match the log file name it had recorded in the relay-log.info file to a valid file name in the new_hostname-relay-bin.index file.

The “fix” that was put in place to solve the problem of default files being named after the hostname was to generate the default log file names from the pid-file variable without the extension. This doesn’t really fix the problem, it just moves it around. If you don’t set the relay-log and relay-log-index variables and you change the pid-file variable then it’s exactly the same as if you changed the hostname in the old method. If the master.info, and relay-log.info names are fixed why can’t the default log file name be something simple like ‘mysql’ instead of being based off of something else that can be changed and has nothing to do with replication?

cinfo is a kick ass program written by the author of PowerDNS Bert Hubert to show how much of a file is being cached by the operating system. It’s great for testing to see if myisam data files are being read from the operating system cache or off disk. For example this is the cache status of myd files for my blog:

wordpress_comments.MYD: 1127 pages, 1121 pages cached (99.47%)
wordpress_links.MYD: 1 pages, 1 pages cached (100.00%)
wordpress_options.MYD: 309 pages, 309 pages cached (100.00%)
wordpress_postmeta.MYD: 2 pages, 2 pages cached (100.00%)
wordpress_posts.MYD: 100 pages, 94 pages cached (94.00%)
wordpress_term_relationships.MYD: 2 pages, 2 pages cached (100.00%)
wordpress_terms.MYD: 1 pages, 1 pages cached (100.00%)
wordpress_term_taxonomy.MYD: 1 pages, 1 pages cached (100.00%)
wordpress_usermeta.MYD: 10 pages, 10 pages cached (100.00%)
wordpress_users.MYD: 2 pages, 2 pages cached (100.00%)

Most of the files are in the filesystem cache so there is a very good chance that when you loaded this page mysql was able to read all the data for my blog from ram.

Cinfo is distributed by source tarball but I’ve created a x86_64 rpm. You can download a modified tarball that can be used with rpmbuild to create your own rpm. The basic process for building an rpm from my tarball is:

create a ~/.rpmmacros file with a path to a buildroot:

%_topdir /tmp/my_buildroot

Then create some directories in that buildroot

cd /tmp/my_buildroot
mkdir SPECS SRPMS BUILD RPMS

The rpm can be built directly from the tarball with:

rpmbuild -ta cinfo-0.1.tar.gz

If everything works ok it should drop an arch specific rpm in:

/tmp/my_buildroot/RPMS

Modern operating systems give the impression of running more processes than the number of available processors by giving each process that wants to run, such as your web browser or text editor a tiny slice of time in which they can execute. By switching out the running process very quickly it looks as though all processes are running even though only a few are at a time. Other processes that want to run are placed in a queue where they wait for their slice of cpu time to execute. The number of processes waiting in this queue is called load average.

Most people who run a flavor of unix inevitably come across load average. It’s in quite a few tools such as uptime, top, and w. It’s usually displayed as a 1, 5, and 15 minute average. Load average can change based on the number of processes wanting to run on a machine. This is a deceptively evil monitoring metric because it’s very difficult to define what a good and bad load average is.

Load average is often used as a comparison metric when trying to diagnose machines that are overloaded. While participating in discussions about machine load I often hear things like, “But the load average is OK” or, “The load average is way high.”. The problem with this is that on one server an OK load average may be 10 and on a server that’s overloaded it may also be 10, or 5, or 200. For situations like this it’s much easier to use response time because it can be easily compared between different types of servers or software. A response time of one second is a response time of one second no matter where you are. It’s very easy to judge if that’s good or bad based on the application. On the same servers one could have a response time of one second and a load average of 200 and another could have a response time of one second with a load average of 50.

Using load average as a comparison metric is so difficult because a higher load average doesn’t really mean a server is more loaded or that it isn’t responding appropriately. The reason for this is that the time a process spends waiting in the queue can be effected by different forces including the number of processes in line before it, how long those processes run for, and if your process gets and interrupt that can let it jump the queue. This is why a server with a load average of 10 may be almost impossible to work with and a server on the same hardware right next to it with a load average of 200 may be responding just fine.

The moral of all of this is to use load average for exactly what it is, the depth of the run queue. Don’t use it for comparison between different types of servers and don’t quote it when saying a server is overloaded.

fadvise is a system call that can be used to give Linux hints about how it should be caching files. It has a few options for caching, not caching, read ahead, and random access. I was looking into used fadvise because a client ran into an issue where some infrequently used myisam data files were being pushed out of the filesystem cache by binary logs and other activity. The files are used infrequently for queries but when they are used they need to be fast. When the files weren’t cached the particular query ran in about 30 seconds. When they were cached the query ran in .8 seconds — huge difference. The fix seemed pretty trivial, call fadvise on the myd files, they stay in cache, the queries are consistently faster and the problem is solved. It seemed simple but it wasn’t. I’ll cover the myisam issue in more detail in another post, this is all about fadvise and debugging.

I couldn’t find an rpm that contained a simple tool to control fadvise that I could called from a shell script (aside from the perl with inline C tool) so I decided to roll my own. The client has an existing system for building C tools to be deployed on servers. The system is such that it takes a bit of time to compile, deploy, and test so I wrote a small C app to test my theory which I could later merge into the clients tool system. I wrote the tool, tested it and the files stayed in cache as predicted so I started on the process of merging the tool with the clients system. The system used to compile the tool is 32bit the mysql servers are 64bit. When I originally wrote the test tool I compiled it directly on the 64 bit boxes.

When I rolled the fadvise tool compiled on the 32 bit system to the 64 bit system it failed with an illegal seek error. My original call to fadvise looked something like this:

posix_fadvise(fd, 0, lseek(fd, 0, SEEK_END), POSIX_FADV_WILLNEED);

I’m sure some of you are thinking, “the lseek is pointless, 0 will include the entire file.” I learned that lesson later on and it plays an important part in this story. When I ran strace on the 32bit binary on the 64 bit system the fadvise syscall looked like:

fadvise64(3, 0, 0, 0×594 /* POSIX_FADV_??? */) = -1 EINVAL (Invalid argument)

Strange, right? I checked the code, added some debugging output for the lseek and tried again with the same result. I went back to my small test program and checked to see if it had the same fadvise and lseek calls. It did. I pinged a friend on IRC and he suggested quite a few things to check including removing the unnecessary lseek. After the lseek is removed the strace output changes to:

fadvise64(3, 0, 0, POSIX_FADV_NORMAL) = 0

Notice that the last argument is POSIX_FADV_NORMAL instead of POSIX_FADV_WILLNEED. At this point I had been trying to debug this for a few hours and I started to think I was going insane. Frustration lead to typos and eyestrain. I sent the output back to my friend assuring him that I’m not insane and this has to be another problem. After some more debugging something clicks in his brain and he realizes it’s a kernel bug. (Note: I don’t fully understand this part so if you’re reading this and you do, please leave a comment.). The 32bit binary running on the 64bit kernel with the bug is taking the 3rd argument and splitting it across two registers to make up the third and fourth argument. POSIX_FADV_NORMAL is defined as 0 so the call is really

fadvise64(3,0,0,0)

Which in my case is a no op but it’s a successful no op and since I haven’t checked it with strace I think it’s caching files. I move this fix over to the clients tool, recompile, and retry my myisam performance test only to find that the files aren’t being kept in memory. Rerunning the fadvise tool doesn’t bring them in memory because it’s being called with POSIX_FADV_NORMAL. After more work with my super smart friend we pin down the problem to the register issue above and I resolve to write a test the next day (today) to test the the theory.

The test works.

Now I have two binaries created from the same source code, one that will successfully execute on both 32 and 64 bit architectures but is a no op on the 64 bit architecture. Since the clients build system isn’t setup to compile 64 bit binaries I end up giving them two binaries with a shell script that will detect the architecture and execute the correct binary.

The debugging lesson learned is to stay calm and think through problems. Frustration and disbelief led to the debugging cycle taking a few hours longer than it should have (it was about 10hrs total including all the testing). It also stressed me out. The other lesson learned is that is pays to have really smart friends. Thanks guys, I owe you a beer.