High Performance MySQL (2012)

---

^[30^] We’re keeping it simple here for clarity, but Percona Server’s query log will produce a much more detailed report, which could help you understand why the query is apparently spending 144 ms to examine a single row—that’s a lot!

^[31^] The view is too lengthy to show here, but the Sakila database is available for download from MySQL’s website.

^[32^] If you own the second edition of this book, you’ll notice that we’re doing an about-face on this point.

Diagnosing Intermittent Problems

Intermittent problems such as occasional server stalls or slow queries can be frustrating to diagnose, and the most egregious wastes of time we’ve seen have been results of phantom problems that happen only when you’re not looking, or aren’t reliably reproducible. We’ve seen people spend literally months fighting with such problems. In the process, some of them reverted to a trial-and-error troubleshooting approach, and sometimes made things dramatically worse by trying to change things such as server settings at random, hoping to stumble upon something that would help.

Try to avoid trial and error if you can. Trial-and-error troubleshooting is risky, because the results can be bad, and it can be frustrating and inefficient. If you can’t figure out what the problem is, you might not be measuring correctly, you might be measuring in the wrong place, or you might not know the necessary tools to use. (Or the tools might not exist—we’ve developed a number of tools specifically to address the lack of transparency in various system components, from the operating system to MySQL itself.)

To illustrate the importance of trying to avoid trial and error, here are some sample resolutions we’ve found to some of the intermittent database performance problems we’ve been called in to solve:

§ The application was executing curl to fetch exchange rate quotes from an external service, which was running very slowly at times.

§ Important cache entries were expiring from memcached, causing the application to flood MySQL with requests to regenerate the cached items.

§ DNS lookups were timing out randomly.

§ The query cache was freezing MySQL periodically due to mutex contention or inefficient internal algorithms for deleting cached queries.

§ InnoDB scalability limitations were causing query plan optimization to take too long when concurrency was over some threshold.

As you can see, some of these problems were in the database, and some of them weren’t. Only by beginning at the place where the misbehavior could be observed and working through the resources it used, measuring as completely as possible, can you avoid hunting in the wrong place for problems that don’t exist there.

We’ll stop lecturing you now, and explain the approach and tools we use for solving intermittent problems.

Single-Query Versus Server-Wide Problems

Do you have any evidence of the problem? If so, try to determine whether the problem is with a single isolated query, or if it’s server-wide. This is important to point you in the right direction. If everything on the server is suffering, and then everything is okay again, then any given query that’s slow isn’t likely to be the problem. Most of the slow queries are likely to be victims of some other problem instead. On the other hand, if the server is running nicely as a whole and a single query is slow for some reason, you have to look more closely at that query.

Server-wide problems are fairly common. As more powerful hardware has become available in the last several years, with 16-core and bigger servers becoming the norm, MySQL’s scalability limitations on SMP systems have become more noticeable. Most of these problems are in older versions, which are unfortunately still widely used in production. MySQL still has some scalability problems even in newer versions, but they are much less serious, and much less frequently encountered, because they’re edge cases. This is good news and bad news: good because you’re much less likely to hit them, and bad because they require more knowledge of MySQL internals to diagnose. It also means that a lot of problems can be solved by simply upgrading MySQL.^[33^]

How do you determine whether the problem is server-wide or isolated to a single query? If the problem occurs repeatedly enough that you can observe it in action, or run a script overnight and look at the results the next day, there are three easy techniques that can make it obvious in most cases. We’ll cover those next.

Using SHOW GLOBAL STATUS

The essence of this technique is to capture samples of SHOW GLOBAL STATUS at high frequency, such as once per second, and when the problem manifests, look for “spikes” or “notches” in counters such as Threads_running, Threads_connected, Questions, and Queries. This is a simple method that anyone can use (no special privileges are required) without impacting the server, so it’s a great way to learn more about the nature of the problem without a big investment of time. Here’s a sample command and output:

$ mysqladmin ext -i1 | awk '

/Queries/{q=$4-qp;qp=$4}

/Threads_connected/{tc=$4}

/Threads_running/{printf "%5d %5d %5d\n", q, tc, $4}'

2147483647 136 7

798 136 7

767 134 9

828 134 7

683 134 7

784 135 7

614 134 7

108 134 24

187 134 31

179 134 28

1179 134 7

1151 134 7

1240 135 7

1000 135 7

The command captures samples of SHOW GLOBAL STATUS every second and pipes those into an awk script that prints out queries per second, Threads_connected, and Threads_running (number of queries currently executing). These three tend to be very sensitive to server-wide stalls. What usually happens is that, depending on the nature of the problem and how the application connects to MySQL, queries per second will drop and at least one of the other two will spike. Here the application is probably using a connection pool, so there’s no spike of connected threads, but there’s a clear bump in in-progress queries at the same time that the queries per second value drops to a fraction of its normal level.

What could explain this behavior? It’s risky to guess, but in practice we’ve seen two common cases. One is some kind of internal bottleneck in the server, causing new queries to begin executing but to pile up against some lock that the older queries are waiting to acquire. This type of lock usually puts back-pressure on the application servers and causes some queueing there, too. The other common case we’ve seen is a spike of heavy queries such as those that can happen with a badly handled memcached expiration.

At one line per second, you can easily let this run for hours or days and make a quick plot to see if there are any areas with aberrations. If a problem is truly intermittent, you can let it run as long as needed and then refer back to the output when you notice the problem. In most cases this output will show the problem clearly.

Using SHOW PROCESSLIST

With this method, you capture samples of SHOW PROCESSLIST and look for lots of threads that are in unusual states or have some other unusual characteristic. For example, it’s rather rare for queries to stay in the “statistics” state for very long, because this is the phase of query optimization where the server determines the best join order—normally very fast. Likewise, it’s rare to see a lot of threads reporting the user as “Unauthenticated user,” because this is a state that happens in the middle of the connection handshake when the client specifies the user it’s trying to use to log in.

Vertical output with the \G terminator is very helpful for working with SHOW PROCESSLIST, because it puts each column of each row of the output onto its own line, making it easy to do a little sort|uniq|sort incantation that helps you view the count of unique values in any desired column easily:

$ mysql -e 'SHOW PROCESSLIST\G' | grep State: | sort | uniq -c | sort -rn

744 State:

67 State: Sending data

36 State: freeing items

8 State: NULL

6 State: end

4 State: Updating

4 State: cleaning up

2 State: update

1 State: Sorting result

1 State: logging slow query

Just change the grep pattern if you want to examine a different column. The State column is a good one for a lot of cases. Here we can see that there are an awful lot of threads in states that are part of the end of query execution: “freeing items,” “end,” “cleaning up,” and “logging slow query.” In fact, in many samples on the server from which this output came, this pattern or a similar one occurred. The most characteristic and reliable indicator of a problem was a high number of queries in the “freeing items” state.

You don’t have to use command-line techniques to find problems like this. You can query the PROCESSLIST table in the INFORMATION_SCHEMA if your server is new enough, or use innotop with a fast refresh rate and watch the screen for an unusual buildup of queries. The example we just showed was of a server with InnoDB internal contention and flushing problems, but it can be far more mundane than that. The classic example would be a lot of queries in the “Locked” state. That’s the unlovable trademark of MyISAM with its table-level locking, which quickly escalates into server-wide pileups when there’s enough write activity on the tables.

Using query logging

To find problems in the query log, turn on the slow query log and set long_query_time to 0 globally, and make sure that all of the connections see the new setting. You might have to recycle connections so they pick up the new global value, or use Percona Server’s feature to force it to take effect instantly without disrupting existing connections.

If you can’t enable the slow query log to capture all queries for some reason, use tcpdump and pt-query-digest to emulate it. Look for periods in the log where the throughput drops suddenly. Queries are sent to the slow query log at completion time, so pileups typically result in a sudden drop of completions, until the culprit finishes and releases the resource that’s blocking the other queries. The other queries will then complete. What’s helpful about this characteristic behavior is that it lets you blame the first query that completes after a drop in throughput. (Sometimes it’s not quite the first query; other queries might be running unaffected while some are blocked, so this isn’t completely reliable.)

Again, good tools can help with this. You can’t be looking through hundreds of gigabytes of queries by hand. Here’s a one-liner that relies on MySQL’s pattern of writing the current time to the log when the clock advances one second:

$ awk '/^# Time:/{print $3, $4, c;c=0}/^# User/{c++}' slow-query.log

080913 21:52:17 51

080913 21:52:18 29

080913 21:52:19 34

080913 21:52:20 33

080913 21:52:21 38

080913 21:52:22 15

080913 21:52:23 47

080913 21:52:24 96

080913 21:52:25 6

080913 21:52:26 66

080913 21:52:27 37

080913 21:52:28 59

There was a drop in throughput in that output, which was interestingly also preceded by a rush of queries completing. Without looking into the log around these timestamps it’s hard to say what happened, but it’s possible that the spike is related to the drop immediately afterward. In any case, it’s clear that something odd happened in this server, and digging into the log around the timestamps in question could be very fruitful. (When we looked into this log, we found that the spike was due to connections being disconnected. Perhaps an application server was being restarted. Not everything is a MySQL problem.)

Making sense of the findings

Nothing beats visualization of the data. We’ve shown only small examples here, but in reality many of these techniques can result in thousands of lines of output. Get comfortable with gnuplot or R or another graphing tool of your choice. You can use them to plot things in a jiffy—much faster than a spreadsheet—and you can instantly zoom in on aberrations in a plot that you’ll have a hard time seeing in a scrolling terminal, even if you think you’re pretty good at Matrix-watching.^[34^]

We suggest trying the first two approaches—SHOW STATUS and SHOW PROCESSLIST—initially, because they’re cheap and can be done interactively with nothing more than a little bit of shell scripting or running queries repeatedly. Analyzing the slow query log is much more disruptive and harder to do, and often shows what looks like funny patterns that disappear as you look closer. We’ve found that it’s easy to imagine patterns where there are none.

When you find an aberration, what does it mean? It usually means that queries are queueing somewhere, or there’s a flood or spike of a particular kind of query. Now the task is to find out why.

Capturing Diagnostic Data

When an intermittent problem strikes, it’s important to measure everything you possibly can, preferably for only the duration of the problem. If you do this right, you will gather a ton of diagnostic data. The data you don’t collect often seems to be the data you really need to diagnose the problem.

To get started, you need two things:

1. A reliable and real-time “trigger”—a way to know when the problem happens

2. A tool to gather the diagnostic data

The diagnostic trigger

The trigger is very important to get right. It’s the foundation for capturing the data when the problem happens. There are two common problems that cause this to go sideways: false positives and false negatives. If you have a false positive, you’ll gather diagnostic data when nothing’s wrong, and you’ll waste time and get frustrated. False negatives will result in missed opportunities and more wasted time and frustration. Spend a little extra time making sure that your trigger indicates for sure that the problem is happening, if you need to. It’s worth it.

What is a good criterion for a trigger? As shown in our examples, Threads_running tends to be very sensitive to problems, but pretty stable when nothing is wrong. A spike of unusual thread states in SHOW PROCESSLIST is another good indicator. But there can be many more ways to observe the problem, including specific output in SHOW INNODB STATUS, a spike in the server’s load average, and so on. The key is to express this as something that you can compare to a definite threshold. This usually means a count. A count of threads running, a count of threads in “freeing items” state, and so on works well. The -c option to grep is your friend when looking at thread states:

$ mysql -e 'SHOW PROCESSLIST\G' | grep -c "State: freeing items"

36

Pick a threshold that’s high enough that you won’t hit it during normal operation, but not so high that you won’t capture the problem in action. Beware, too, of setting the threshold too high to catch the problem when it begins. Problems that escalate tend to cause cascades of other problems, and if you capture diagnostic information after things have really gone down the toilet, you’ll likely have a harder time isolating the original cause. You want to collect your data when things are clearly circling the drain, if possible, but before the loud flushing sound deafens you. For example, spikes in Threads_connected can go insanely high—we’ve seen it escalate from 100 to 5000 or more in the space of a couple minutes. You could clearly use 4999 as the threshold, but why wait for things to get that bad? If the application doesn’t open more than 150 connections when it’s healthy, start collecting at 200 or 300.

Referring back to our earlier example of Threads_running, it looks like the normal concurrency is less than 10. But 10 is not a good threshold—it is way too likely to produce false positives, and 15 isn’t far enough away to definitely be out of the normal range of behavior either. There could be a mini-pileup at 15, but it’s quite possible that it could not quite cross the tipping point, and the problem could clear right up before getting bad enough to be clearly diagnosable. We’d suggest setting 20 as the threshold in that example.

You probably also want to capture the problem as soon as it is clearly happening, but only after waiting briefly to ensure that it’s not a false positive or short-term spike. So, our final trigger would be this: watch the status variables once per second, and if Threads_running exceeds 20 for more than 5 seconds, start gathering diagnostic data. (By the way, our example showed the problem going away after three seconds. That’s a bit contrived to keep the example brief. A three-second problem is not likely to be easily diagnosable, and most problems we’ve seen last a bit longer.)

Now you need to set up some kind of tool to watch the server and take action when the trigger condition occurs. You could script this yourself, but we’ve saved you the trouble. There’s a tool called pt-stalk in Percona Toolkit that is custom-built just for this. It has a lot of nice features whose necessity we’ve learned of through the school of hard knocks. For example, it looks at how much disk space is free, so it won’t fill up your disk with the data it collects and crash your server. Not that we’ve ever done that, you understand!

The pt-stalk tool is really simple to use. You can configure the variable to watch, the threshold, the frequency of checks, and so forth. It supports a lot more fanciness than that if needed, but that’s all you need to do for our example. Read the user’s manual that comes with it before you use it. It relies on another tool for actually collecting the data, which we’ll discuss next.

What kinds of data should you collect?

Now that you have determined a diagnostic trigger, you can use it to fire some process to collect data. But what kind of data should you collect? The answer, as mentioned previously, is everything you possibly can—but for only a reasonable amount of time. Gather operating system stats, CPU usage, disk utilization and free space, samples of ps output, memory usage, and everything you can from within MySQL, such as samples of SHOW STATUS, SHOW PROCESSLIST, and SHOW INNODB STATUS. You’ll need all of these things, and probably more, to diagnose problems.

Execution time is spent doing work or waiting, as you’ll recall. When an unknown problem happens, there are two types of causes, broadly speaking. The server could be doing a lot of work—consuming a lot of CPU cycles—or it could be stuck waiting for resources to become free. You need two different approaches to gather the diagnostic data to identify the causes of each of these types of problems: a profile when the system is doing too much work, and wait analysis when the system is doing too much waiting. But how do you know which of these to focus on when the problem is unknown? You don’t, so it’s best to collect data for both.

The primary profiling tool we rely on for server internals on GNU/Linux (as opposed to queries server-wide) is oprofile. We’ll show examples of this a bit later. You can also profile the server’s system calls with strace, but we have found this to be riskier on production systems. More on that later, too. For capturing queries to profile, we like to use tcpdump. It’s hard to turn the slow query log on and off reliably at a moment’s notice on most versions of MySQL, but you can get a pretty good simulation of it from TCP traffic. Besides, the traffic is useful for lots of other kinds of analysis.

For wait analysis, we often use GDB stack traces.^[35^] Threads that are stuck in a particular spot inside of MySQL for a long time tend to have the same stack trace. The procedure is to start gdb, attach it to the mysqld process, and dump stack traces for all threads. You can then use some short scripts to aggregate common stack traces together and do the sort|uniq|sort magic to show which ones are most common. We’ll show how to use the pt-pmp tool for this a bit later.

You can also do wait analysis with data such as snapshots of SHOW PROCESSLIST and SHOW INNODB STATUS by observing thread and transaction states. None of these approaches is perfectly foolproof, but in practice they work often enough to be very helpful.

Gathering all of this data sounds like a lot of work! You probably anticipated this already, but we’ve built a tool to do this for you too. It’s called pt-collect, and it’s also part of Percona Toolkit. It’s intended to be executed from pt-stalk. It needs to be run as root in order to gather most of the important data. By default, it will collect data for 30 seconds and then exit. This is usually enough to diagnose most problems, but not so much that it causes problems when there’s a false positive.

The tool is easy to download and doesn’t need any configuration—all of the configuration goes into pt-stalk. You will want to ensure that gdb and oprofile are installed on your server, and enable those in the pt-stalk configuration. You also need to ensure that mysqld has debug symbols.^[36^]When the trigger condition occurs, the tool will gather a pretty complete set of data. It will create timestamped files in a specified directory. At the time of writing, it’s rather oriented toward GNU/Linux and will need tweaking on other operating systems, but it’s still a good place to start.

Interpreting the data

If you’ve set up your trigger condition correctly and let pt-stalk run long enough to catch the problem in action a few times, you’ll end up with a lot of data to sift through. What’s the most useful place to start? We suggest looking at just a few things, with two purposes in mind. First, check that the problem really did occur, because if you have many samples to examine, you won’t want to spend your time on false positives. Second, see if something obvious jumps out at you.

NOTE

It’s very helpful to capture samples of how the server looks when it’s behaving well, not just when it’s in trouble. This will help you determine whether a particular sample, or even a portion of a sample, is abnormal or not. For example, when you’re looking at the states of queries in the process list, you can answer questions such as “Is it normal for a lot of queries to be sorting their results?”

The most fruitful things to look at are usually query or transaction behavior, and server internals behavior. Query or transaction behavior shows you whether the problem was caused by the way the server is being used: badly written SQL, bad indexing, bad logical database design, and so on. You can see what the users are doing to the server by looking at places where queries and transactions appear: in the logged TCP traffic, in the SHOW PROCESSLIST output, and so on. Server internals behavior tells you whether the server is buggy or has built-in performance or scalability problems. You can see this in some of the same places, but also in oprofile and gdb output. This takes more experience to interpret.

If you don’t know how to interpret what’s wrong, you can tarball the directory full of collected data and submit it to a support provider for analysis. Any competent MySQL support professional will be able to interpret the data and tell you what it means. And they’ll love you for sending such detailed data to peruse. You might also want to send the output of two other tools in Percona Toolkit: pt-mysql-summary and pt-summary. These show status and configuration snapshots of your MySQL instance and the operating system and hardware, respectively.

Percona Toolkit includes a tool designed to help you look through lots of samples of collected data quickly. It’s called pt-sift, and it helps you navigate between samples, shows a summary of each sample, and lets you drill down into particular bits of the data if desired. It can save a lot of keystrokes.

We showed some examples of status counters and thread states earlier. We’ll finish out this chapter by showing some examples of output from oprofile and gdb. Here’s an oprofile report from a server that was having trouble. Can you find the problem?

samples % image name app name symbol name

893793 31.1273 /no-vmlinux /no-vmlinux (no symbols)

325733 11.3440 mysqld mysqld Query_cache::free_memory_block()

117732 4.1001 libc libc (no symbols)

102349 3.5644 mysqld mysqld my_hash_sort_bin

76977 2.6808 mysqld mysqld MYSQLparse()

71599 2.4935 libpthread libpthread pthread_mutex_trylock

52203 1.8180 mysqld mysqld read_view_open_now

46516 1.6200 mysqld mysqld Query_cache::invalidate_query_block_list()

42153 1.4680 mysqld mysqld Query_cache::write_result_data()

37359 1.3011 mysqld mysqld MYSQLlex()

35917 1.2508 libpthread libpthread __pthread_mutex_unlock_usercnt

34248 1.1927 mysqld mysqld __intel_new_memcpy

If you said “the query cache,” you were right. This server’s query cache was causing far too much work and slowing everything down. This had happened overnight, a factor of 50 slowdown, with no other changes to the system. Disabling the query cache returned the server to its normal performance. This is an example of when server internals are relatively straightforward to interpret.

Another important tool for bottleneck analysis is wait analysis using stack traces from gdb. A single thread’s stack trace normally looks like the following, which we’ve formatted a bit for printing:

Thread 992 (Thread 0x7f6ee0111910 (LWP 31510)):

#0 0x0000003be560b2f9 in pthread_cond_wait@@GLIBC_2.3.2 () from /libpthread.so.0

#1 0x00007f6ee14f0965 in os_event_wait_low () at os/os0sync.c:396

#2 0x00007f6ee1531507 in srv_conc_enter_innodb () at srv/srv0srv.c:1185

#3 0x00007f6ee14c906a in innodb_srv_conc_enter_innodb () at handler/ha_innodb.cc:609

#4 ha_innodb::index_read () at handler/ha_innodb.cc:5057

#5 0x00000000006538c5 in ?? ()

#6 0x0000000000658029 in sub_select() ()

#7 0x0000000000658e25 in ?? ()

#8 0x00000000006677c0 in JOIN::exec() ()

#9 0x000000000066944a in mysql_select() ()

#10 0x0000000000669ea4 in handle_select() ()

#11 0x00000000005ff89a in ?? ()

#12 0x0000000000601c5e in mysql_execute_command() ()

#13 0x000000000060701c in mysql_parse() ()

#14 0x000000000060829a in dispatch_command() ()

#15 0x0000000000608b8a in do_command(THD*) ()

#16 0x00000000005fbd1d in handle_one_connection ()

#17 0x0000003be560686a in start_thread () from /lib64/libpthread.so.0

#18 0x0000003be4ede3bd in clone () from /lib64/libc.so.6

#19 0x0000000000000000 in ?? ()

The stack reads from the bottom up; that is, the thread is currently executing inside of the pthread_cond_wait function, which was called from os_event_wait_low. Reading down the trace, it looks like this thread was trying to enter the InnoDB kernel (srv_conc_enter_innodb), but got put on an internal queue (os_event_wait_low) because more than innodb_thread_concurrency threads were already inside the kernel. The real value of stack traces is aggregating lots of them together, however. This is a technique that Domas Mituzas, a former MySQL support engineer, made popular with his “poor man’s profiler” tool. He currently works at Facebook, and he and others there have developed a wide variety of tools for gathering and analyzing stack traces. You can find out more about what’s available at http://www.poormansprofiler.org.

We have an implementation of the poor man’s profiler in Percona Toolkit, called pt-pmp. It’s a shell and awk program that collapses similar stack traces together and does the usual sort|uniq|sort to show the most common ones first. Here’s what the full set of stack traces looks like after crunching it down to its essence. We’re going to use the -l 5 option to truncate the stack traces after five levels so that we don’t get so many traces with common tops but different bottoms, which would prevent them from aggregating together and showing where things are really waiting:

$ pt-pmp -l 5 stacktraces.txt

507 pthread_cond_wait,one_thread_per_connection_end,handle_one_connection,

start_thread,clone

398 pthread_cond_wait,os_event_wait_low,srv_conc_enter_innodb,

innodb_srv_conc_enter_innodb,ha_innodb::index_read

83 pthread_cond_wait,os_event_wait_low,sync_array_wait_event,mutex_spin_wait,

mutex_enter_func

10 pthread_cond_wait,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,

io_handler_thread

7 pthread_cond_wait,os_event_wait_low,srv_conc_enter_innodb,

innodb_srv_conc_enter_innodb,ha_innodb::general_fetch

5 pthread_cond_wait,os_event_wait_low,sync_array_wait_event,rw_lock_s_lock_spin,

rw_lock_s_lock_func

1 sigwait,signal_hand,start_thread,clone,??

1 select,os_thread_sleep,srv_lock_timeout_and_monitor_thread,start_thread,clone

1 select,os_thread_sleep,srv_error_monitor_thread,start_thread,clone

1 select,handle_connections_sockets,main

1 read,vio_read_buff,::??,my_net_read,cli_safe_read

1 pthread_cond_wait,os_event_wait_low,sync_array_wait_event,rw_lock_x_lock_low,

rw_lock_x_lock_func

1 pthread_cond_wait,MYSQL_BIN_LOG::wait_for_update,mysql_binlog_send,

dispatch_command,do_command

1 fsync,os_file_fsync,os_file_flush,fil_flush,log_write_up_to

The first line is the characteristic signature of an idle thread in MySQL, so you can ignore that. The second line is the most interesting one: it shows that a lot of threads are waiting to enter the InnoDB kernel but are blocked. The third line shows many threads waiting on some mutex, but we can’t see which one because we have truncated the deeper levels of the stack trace. If it is important to know which mutex that is, we would need to re run the tool with a larger value for the -l option. In general, the stack traces show that lots of things are waiting for their turn inside InnoDB, but why? That isn’t clear at all. To find out, we probably need to look elsewhere.

As the preceding stack trace and oprofile reports show, these types of analysis are not always useful to those who aren’t experts with MySQL and InnoDB source code, and you should ask for help from someone else if you get stuck.

Now let’s move on to a server whose problems don’t show up on either a profile or wait analysis, and need to be diagnosed differently.

A Case Study in Diagnostics

In this section we’ll step you through the process of diagnosing a real customer’s intermittent performance problem. This case study is likely to get into unfamiliar territory unless you’re an expert with MySQL, InnoDB, and GNU/Linux. However, the specifics we’ll discuss are not the point. Try to look for the method within the madness: read this section with an eye toward the assumptions and guesses we make, the reasoning-based and measurement-based approaches we take, and so on. We are delving into a specific and detailed case simply to illustrate generalities.

Before beginning to solve a problem at someone else’s request, it’s good to try to clear up two things, preferably taking notes to help avoid forgetting or omitting anything:

1. First, what’s the problem? Try to be clear on that. It’s surprisingly easy to go hunting for the wrong problem. In this case, the customer complained that once every day or two, the server rejected connections with a max_connections error. It lasted from a few seconds to a few minutes, and was highly sporadic.

2. Next, what has been done to try to fix it? In this case, the customer did not attempt to resolve the issue at all. This was extremely helpful, because few things are as hard to understand as another person’s description of the exact sequence of events, changes they made, and effects thereof. This is especially true when they call in desperation after a couple of sleepless nights and caffeine-filled days. A server that has been subjected to unknown changes, with unknown effects, is much harder to troubleshoot, especially if you’re under time pressure.

With that behind us, let’s get started. It’s a good idea not only to try to understand how the server behaves, but also to take an inventory of the server’s status, configuration, software, and hardware. We did so with the pt-summary and pt-mysql-summary tools. Briefly, this server had 16 CPU cores, 12 GB of RAM, and a total of 900 MB of data, all in InnoDB, on a solid-state drive. The server was running GNU/Linux with MySQL 5.1.37 and the InnoDB plugin version 1.0.4. We’d worked with this customer previously on other unexpected performance problems, and we knew the systems. The database was never the problem in the past; it had always been bad application behavior. We took a look at the server and found nothing obviously wrong at a glance. The queries weren’t perfect, but they were still running in less than 10 ms most of the time. So we confirmed that the server was fine under normal circumstances. (This is important to do; many problems that are noticed only sporadically are actually symptoms of chronic problems, such as failed hard drives in RAID arrays.)

NOTE

This case study might be a little tedious. We’ll “play dumb” to show all of the diagnostic data, explain everything we see in detail, and follow several potential trains of thought to completion. In reality, we don’t take such a frustratingly slow approach to every problem, and we’re not trying to say that you should, either.

We installed our diagnostic toolkit and set it to trigger on Threads_connected, which was normally less than 15 but increased to several hundred during these problems. We’ll present a sample of the data we collected as a result, but we’ll hold our commentary until later. See if you can drink from the fire hose and pick out items that are likely to be important:

§ The query activity ranged from 1,000 to 10,000 queries per second, with many of them being “garbage” commands such as pinging the server to see if it was alive. Most of the rest were SELECT commands—from 300 to 2,000 per second—and there were a very small number of UPDATEcommands (about 5 per second).

§ There were basically two distinct types of queries in SHOW PROCESSLIST, varying only in the values in the WHERE clauses. Here are the query states, summarized:

§ $ grep State: processlist.txt | sort | uniq -c | sort -rn

§ 161 State: Copying to tmp table

§ 156 State: Sorting result

§ 136 State: statistics

§ 50 State: Sending data

§ 24 State: NULL

§ 13 State:

§ 7 State: freeing items

§ 7 State: cleaning up

§ 1 State: storing result in query cache

1 State: end

§ Most queries were doing index scans or range scans—no full-table scans or cross joins.

§ There were between 20 and 100 sorts per second, with between 1,000 and 12,000 rows sorted per second.

§ There were between 12 and 90 temporary tables created per second, with about 3 to 5 of them on disk.

§ There was no problem with table locking or the query cache.

§ In SHOW INNODB STATUS, we observed that the main thread state was “flushing buffer pool pages,” but there were only a few dozen dirty pages to flush (Innodb_buffer_pool_pages_dirty), there was practically no change in Innodb_buffer_pool_pages_flushed, and the difference between the log sequence number and the last checkpoint was very small. The InnoDB buffer pool wasn’t even close to being full; it was much bigger than the data size. Most threads were waiting in the InnoDB queue: “12 queries inside InnoDB, 495 queries in queue.”

§ We captured iostat output for 30 seconds, one sample per second. This showed that there was essentially no read activity at all on the disks, but writes went through the roof, and average I/O wait times and queue length were extremely high. Here is the first bit of the output, simplified to fit on the page without wrapping:

§ r/s w/s rsec/s wsec/s avgqu-sz await svctm %util

§ 1.00 500.00 8.00 86216.00 5.05 11.95 0.59 29.40

§ 0.00 451.00 0.00 206248.00 123.25 238.00 1.90 85.90

§ 0.00 565.00 0.00 269792.00 143.80 245.43 1.77 100.00

§ 0.00 649.00 0.00 309248.00 143.01 231.30 1.54 100.10

§ 0.00 589.00 0.00 281784.00 142.58 232.15 1.70 100.00

§ 0.00 384.00 0.00 162008.00 71.80 238.39 1.73 66.60

§ 0.00 14.00 0.00 400.00 0.01 0.93 0.36 0.50

§ 0.00 13.00 0.00 248.00 0.01 0.92 0.23 0.30

0.00 13.00 0.00 408.00 0.01 0.92 0.23 0.30

§ The output of vmstat confirmed what we saw in iostat and showed that the CPUs were basically idle except for some I/O wait during the spike of writes (ranging up to 9% wait).

Is your brain full yet? This can happen quickly when you dig into a system in detail and you don’t have (or you try to ignore) any preconceived notions, so you end up looking at everything. Most of what you’ll look at is either completely normal, or shows the effects of the problem but doesn’t indicate the source of the problem. Although at this point we have some good guesses about the cause of the problem, we’ll keep going by looking at the oprofile report, and we’ll begin to add commentary and interpretation as we throw more data at you:

samples % image name app name symbol name

473653 63.5323 no-vmlinux no-vmlinux /no-vmlinux

95164 12.7646 mysqld mysqld /usr/libexec/mysqld

53107 7.1234 libc-2.10.1.so libc-2.10.1.so memcpy

13698 1.8373 ha_innodb.so ha_innodb.so build_template()

13059 1.7516 ha_innodb.so ha_innodb.so btr_search_guess_on_hash

11724 1.5726 ha_innodb.so ha_innodb.so row_sel_store_mysql_rec

8872 1.1900 ha_innodb.so ha_innodb.so rec_init_offsets_comp_ordinary

7577 1.0163 ha_innodb.so ha_innodb.so row_search_for_mysql

6030 0.8088 ha_innodb.so ha_innodb.so rec_get_offsets_func

5268 0.7066 ha_innodb.so ha_innodb.so cmp_dtuple_rec_with_match

It’s not at all obvious what most of these symbols represent, and most of the time is lumped together in the kernel^[37^] and in a generic mysqld symbol that doesn’t tell us anything.^[38^] Don’t get distracted by all of the ha_innodb.so symbols. Look at the percentage of time they contributed: regardless of what they do, they’re burning so little time that you can be sure they’re not the problem. This is an example of a problem that isn’t going to yield results from this type of profile analysis. We are looking at the wrong data. When you see something like the previous sample, move along and look at other data to see if there’s a more obvious pointer to the cause.

At this point, if you’re interested in the wait analysis from gdb stack traces, please refer to the end of the preceding section. The sample we showed there is from the system we’re currently diagnosing. If you recall, the bulk of stack traces were simply waiting to enter the InnoDB kernel, which corresponds to “12 queries inside InnoDB, 495 queries in queue” in the output from SHOW INNODB STATUS.

Do you see anything that points conclusively to a specific problem? We didn’t; we saw possible symptoms of many different problems, and at least two potential causes of the problem based on intuition and experience. But we also saw something that didn’t make sense. If you look at theiostat output again, in the wsec/s column you can see that for about six seconds, the server is writing hundreds of megabytes of data per second to the disks. Each sector is 512 bytes, so those samples show up to 150 MB of writes per second at times. Yet the entire database is only 900 MB, and the workload is mostly SELECT queries. How can this happen?

When you examine a system, try to ask yourself whether there are any things like this that simply don’t add up, and investigate them further. Try to follow each train of thought to its conclusion, and try not to get sidetracked on too many tangents, or you could forget about a promising possibility. Write down little notes and cross them off to help ensure that you’ve dotted all the Ts.^[39^]

At this point, we could jump right to a conclusion, and it would be wrong. We see from the main thread state that InnoDB is trying to flush dirty pages, which generally doesn’t appear in the status output unless flushing is delayed. We know that this version of InnoDB is prone to the “furious flushing” problem, also called a checkpoint stall. This is what happens when InnoDB doesn’t spread flushing out evenly over time, and it suddenly decides to force a checkpoint (flush a lot of data) to make up for that. This can cause serious blocking inside InnoDB, making everything queue and wait to enter the kernel, and thus pile up at the layers above InnoDB in the server. We showed an example in Chapter 2 of the periodic drops in performance that can happen when there is furious flushing. Many of this server’s symptoms are similar to what happens during a forced checkpoint, but it’s not the problem in this case. You can prove that in many ways, perhaps most easily by looking at the SHOW STATUS counters and tracking the change in the Innodb_buffer_pool_pages_flushed counter, which, as we mentioned earlier, was not increasing much. In addition, we noted that the buffer pool doesn’t have much dirty data to flush anyway—certainly not hundreds of megabytes. This is not surprising, because the workload on this server is almost entirely SELECT queries. We can therefore conclude that instead of blaming the problem on InnoDB flushing, we should blame InnoDB’s flushing delay on the problem. It is a symptom—an effect—not a cause. The underlying problem is causing the disks to become saturated that InnoDB isn’t having any luck getting its I/O tasks done. So we can eliminate this as a possible cause, and cross off one of our intuition-based ideas.

Distinguishing cause from effect can be hard sometimes, and it can be tempting to just skip the investigation and jump to the diagnosis when a problem looks familiar. It is good to avoid taking shortcuts, but it’s equally important to pay attention to your intuition. If something looks familiar, it is prudent to spend a little time measuring the necessary and sufficient conditions to prove whether that’s the problem. This can save a lot of time you’d otherwise spend looking through other data about the system and its performance. Just try not to jump to conclusions based on a gut feeling that “I’ve seen this before, and I am sure it’s the same thing.” Gather some evidence, if you can—especially evidence that could disprove your gut feeling.

The next step was to try to figure out what was causing the server’s I/O usage to be so strange. We call your attention to the reasoning we used earlier: “The server writes hundreds of megabytes to disk for many seconds, but the database is only 900 MB. How can this happen?” Notice the implicit assumption that the database is doing the writing? What evidence did we have that it’s the database? Try to catch yourself when you think unsubstantiated thoughts, and when something doesn’t make sense, ask if you’re assuming something. If you can, measure and remove the doubt.

We saw two possibilities: either the database was causing the I/O—and if we could find the source of that, we thought that it was likely that we’d find the cause of the problem—or, the database wasn’t doing all that I/O, but rather something else was, and the lack of I/O resources could have been impacting the database. We’re stating that very carefully to avoid another implicit assumption: just because the disks are busy doesn’t guarantee that MySQL will suffer. Remember, this server basically has a read-only in-memory workload, so it is quite possible to imagine that the disks could stop responding for a long time without causing serious problems.

If you’re following our reasoning, you might see that we need to go back and gut-check another assumption. We can see that the disk device was behaving badly, as evidenced by the high wait times. A solid-state drive shouldn’t take a quarter of a second per I/O on average. And indeed, we can see that iostat claimed the drive itself was responding quickly, but things were taking a long time to get through the block device queue to the drive. Remember that this is only what iostat claims; it could be wrong.

WHAT CAUSES POOR PERFORMANCE?

When a resource is behaving badly, it’s good to try to understand why. There are a few possibilities:

1. The resource is being overworked and doesn’t have the capacity to behave well.

2. The resource is not configured properly.

3. The resource is broken or malfunctioning.

In the case we’re examining, iostat’s output could point to either too much work, or misconfiguration (why are I/O requests queueing so long before reaching the disk, if it’s actually responding quickly?). However, a very important part of deciding what’s wrong is to compare the demand on the system to its known capacity. We know from extensive benchmarking that the particular SSD drive this customer was using can’t sustain hundreds of megabytes of writes per second. Thus, although iostat claims the disk is responding just fine, it’s likely that this isn’t entirely true. In this case, we had no way to prove that the disk was slower than iostat claimed, but it looked rather likely to be the case. Still, this doesn’t change our opinion: this could be disk abuse,^[40^] misconfiguration, or both.

After working through the diagnostic data to reach this point, the next task was obvious: measure what was causing the I/O. Unfortunately, this was infeasible on the version of GNU/Linux the customer was using. We could have made an educated guess with some work, but we wanted to explore other options first. As a proxy, we could have measured how much I/O was coming from MySQL, but again, in this version of MySQL that wasn’t really feasible due to lack of instrumentation.

Instead, we opted to try to observe MySQL’s I/O, based on what we know about how it uses the disk. In general, MySQL writes only data, logs, sort files, and temporary tables to disk. We eliminated data and logs from consideration, based on the status counters and other information we discussed earlier. Now, suppose MySQL were to suddenly write a bunch of data to disk temporary tables or sort files. How could we observe this? Two easy ways are to watch the amount of free space on the disk, or to look at the server’s open filehandles with the lsof command. We did both, and the results were convincing enough to satisfy us. Here’s what df -h showed every second during the same incident we’ve been studying:

Filesystem Size Used Avail Use% Mounted on

/dev/sda3 58G 20G 36G 36% /

/dev/sda3 58G 20G 36G 36% /

/dev/sda3 58G 19G 36G 35% /

/dev/sda3 58G 19G 36G 35% /

/dev/sda3 58G 19G 36G 35% /

/dev/sda3 58G 19G 36G 35% /

/dev/sda3 58G 18G 37G 33% /

/dev/sda3 58G 18G 37G 33% /

/dev/sda3 58G 18G 37G 33% /

And here’s the data from lsof, which for some reason we gathered only once per five seconds. We’re simply summing the sizes of all of the files mysqld has open in /tmp, and printing out the total for each timestamped sample in the file:

$ awk '

/mysqld.*tmp/ {

total += $7;

}

/^Sun Mar 28/ && total {

printf "%s %7.2f MB\n", $4, total/1024/1024;

total = 0;

}' lsof.txt

18:34:38 1655.21 MB

18:34:43 1.88 MB

18:34:48 1.88 MB

18:34:53 1.88 MB

18:34:58 1.88 MB

Based on this data, it looks like MySQL is writing about 1.5 GB of data to temporary tables in the beginning phases of the incident, and this matches what we found in the SHOW PROCESSLIST states (“Copying to tmp table”). The evidence points to a storm of bad queries all at once saturating the disk. The most common cause of this we’ve seen (this is our intuition at work) is a cache stampede, when cached items expire all at once from memcached and many instances of the application try to repopulate the cache simultaneously. We showed samples of the queries to the developers and discussed their purpose. Indeed, it turned out that simultaneous cache expiration was the cause (confirming our intuition). In addition to the developers addressing the problem at the application level, we were able to help them modify the queries so they didn’t use temporary tables on disk. Either one of these fixes might have prevented the problem, but it was much better to do both than just one.

Now, we’d like to apply a little hindsight to explain some questions you might have had as we went along (we certainly critiqued our own approach as we reviewed it for this chapter):

Why didn’t we just optimize the slow queries to begin with?

Because the problem wasn’t slow queries, it was “too many connections” errors. Sure, it’s logical to see that long-running queries cause things to stack up and the connection count to climb. But so can dozens of other things. In the absence of finding a good reason for why things are going wrong, it’s all too tempting to fall back to looking for slow queries or other general things that look like they could be improved.^[41^] But this goes badly more often than it goes well. If you took your car to the mechanic and complained about an unfamiliar noise, and then got slapped with a bill for balancing the tires and changing the transmission fluid because the mechanic couldn’t figure out the real problem and went looking for other things to do, wouldn’t you be annoyed?

But isn’t it a red flag that the queries were running slowly with a bad EXPLAIN?

They were indeed—during the incidents. Was that a cause or an effect? It wasn’t obvious until we dug into things more deeply. And remember, the queries seemed to be running well enough in normal circumstances. Just because a query does a filesort with a temporary table doesn’t mean it is a problem. Getting rid of filesorts and temporary tables is a catch-all, “best practice” type of tactic.

Generic “best practices” reviews have their place, but they are seldom the solution to highly specific problems. The problem could easily have been misconfiguration, for example. We’ve seen many cases where someone tried to fix a misconfigured server with tactics such as optimizing queries, which was ultimately a waste of time and just prolonged the damage caused by the real problem.

If cached items were being regenerated many times, wouldn’t there be multiple identical queries?

Yes, and this is something we did not investigate at the time. Multiple threads regenerating the same cached item would indeed cause many completely identical queries. (This is different from having multiple queries of the same general type, which might differ in a parameter to theWHERE clause, for example.) Noticing this could have stimulated our intuition and directed us to the solution more quickly.

There were hundreds of SELECT queries per second, but only five UPDATEs. What’s to say that these five weren’t really heavy queries?

They could indeed have been responsible for a lot of load on the server. We didn’t show the actual queries because it would clutter things too much, but it’s a valid point that the absolute number of each type of query isn’t necessarily meaningful.

Isn’t the “proof” about the origin of the I/O storms still pretty weak?

Yes, it is. There could be many explanations for why a small database would write a huge amount of data to disk, or why the disk’s free space decreased quickly. This is something that’s ultimately pretty hard to measure (though not impossible) on the versions of MySQL and GNU/Linux in question. Although it’s possible to play devil’s advocate and come up with lots of scenarios, we chose to balance the cost and potential benefit by pursuing what seemed like the most promising leads first. The harder it is to measure and be certain, the higher the cost/benefit ratio climbs, and the more willing we are to accept uncertainty.

We said “the database was never the problem in the past.” Wasn’t that a bias?

Yes, that was a bias. If you caught it, great—if not, well, then hopefully it serves as a useful illustration that we all have biases.

We’d like to finish this troubleshooting case study by pointing out that this issue probably could have been solved (or prevented) without our involvement by using an application profiling tool such as New Relic.