Archive for the ‘Innotop’ tag
This article shows you how to use a little-known InnoDB feature to find out what is holding the lock for which an InnoDB transaction is waiting. I then show you how to use an undocumented feature to make this even easier with innotop.
One of the most common complaints I’ve heard from DBAs used to other database
servers is “I can’t find out who holds the locks that are blocking all these
connections and making them time out.” I feel your pain. Before I helped scale
my employer’s systems to deal with larger volumes of data, InnoDB lock
contention was a serious issue. And as far as I knew, you couldn’t find out who
was holding locks. I knew you could see who was waiting for locks to be
granted; that’s easy. You just run
SHOW INNODB STATUS and
look for the following text:
------------ TRANSACTIONS ------------ Trx id counter 0 4874 Purge done for trx's n:o < 0 4869 undo n:o < 0 0 History list length 21 Total number of lock structs in row lock hash table 2 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 4873, ACTIVE 6 sec, process no 7142, OS thread id 1141152064 starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 368 MySQL thread id 9, query id 173 localhost root Sending data select * from t1 for update ------- TRX HAS BEEN WAITING 6 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 9 page no 3 n bits 72 index `PRIMARY` of table `test/t1` trx id 0 4873 lock_mode X waiting ...
That’s fine, but who holds the lock? I thought there was no way to find that out.
InnoDB Lock Monitor
Until I learned about the InnoDB Lock Monitor, that is. You enable it by running the following command:
CREATE TABLE innodb_lock_monitor(a int) ENGINE=INNODB;
It’s quite an ugly hack, but it turns out the table name is actually “magical.” It’s a special table name that tells InnoDB to start the lock monitor. You can stop it by dropping the table again.
This little-noticed feature makes InnoDB print out a slightly modified
version of what you see with
SHOW INNODB STATUS. The “slight modification” is
to print out not only the locks the transaction waits for, but also those it
holds. For example, here’s the transaction that holds the locks:
---TRANSACTION 0 4872, ACTIVE 32 sec, process no 7142, OS thread id 1141287232 2 lock struct(s), heap size 368 MySQL thread id 8, query id 164 localhost root TABLE LOCK table `test/t1` trx id 0 4872 lock mode IX RECORD LOCKS space id 9 page no 3 n bits 72 index `PRIMARY` of table `test/t1` trx id 0 4872 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;; Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000000d35; asc 5;; 2: len 7; hex 800000002d0110; asc - ;;
That’s fine, but there are, ah, limitations. As the manual says, InnoDB periodically prints out this text — essentially spewing InnoDB’s guts — to its standard output. This gets redirected to the server error log in any sane installation. Who’s looking there? And it gets printed out at long intervals, which seems to be about every 16 seconds on the machines I use.
Plus, if you’ve looked at the result, you’ll understand this is not something you want to search through manually looking for data. The output can be absolutely huge. What DBA wants to pore over thousands of hex-dumped rows from the table just to answer the question “who holds that lock?”
All in all, this is not very convenient (yep, I know that’s an understatement).
Slightly more convenient
What’s a little more convenient than combing through all that text by hand is writing a program to parse InnoDB’s status output. You don’t have to, though. That’s what I wrote innotop to do. And I’ve just released version 1.5.2, which at long last has the ability to watch a log file as well as connecting to server(s).
Here’s how this works: you start innotop, and press the L key to switch to Lock
mode. This replaces the old Lock Wait mode, which was only able to monitor
the InnoDB lock waits you see in the normal output of
SHOW INNODB STATUS.
This mode shows you something like the following:
_____________________________ InnoDB Locks __________________________ CXN ID Type Waiting Wait Active Mode DB Table Index file 12 RECORD 1 00:10 00:10 X test t1 PRIMARY file 12 TABLE 0 00:10 00:10 IX test t1 file 12 RECORD 1 00:10 00:10 X test t1 PRIMARY file 11 TABLE 0 00:00 00:25 IX test t1 file 11 RECORD 0 00:00 00:25 X test t1 PRIMARY
That’s helpful! I can see the locks held and waited for in a nice tabular format. It’s pretty easy to see connection 11 is blocking connection 12.
This is still pretty inconvenient, though. To get access to the server’s error log, I have to run innotop on the database server machine itself. Is there a better way?
There is, in fact, but I discovered it completely by accident. It’s not
documented, but the extra information doesn’t just get printed to the server
log. It also shows up in
SHOW INNODB STATUS! Now that’s a nice surprise. It
means innotop can get lock information from a normal connection instead of
monitoring a log file.
After discovering this, I immediately added some more features to innotop. There are now hot-keys in L mode to enable and disable the lock monitor. Now you can press L, press the ‘a’ key to start the lock monitor, see what’s blocking the waiting transaction, press ‘o’ to stop the lock monitor, and you’re done.
I’m sure you InnoDB administrators already recognize what an improvement this
is over the options you previously had (essentially, you didn’t have any).
There’s still a long way to go, though. Locks could be in the
INFORMATION_SCHEMA or in a
SHOW LOCKS command. I won’t speculate on why they
Of course, the upcoming Falcon storage engine already has better features for debugging lock contention than this. But my guess is it’ll be a long time before Falcon has the market share InnoDB has. All things considered, InnoDB is a pretty nice piece of software.
The conclusion to this whole article is: use innotop if you use InnoDB. Heck, use it if you use MySQL at all. It makes a lot of things a lot easier, not just debugging InnoDB lock contention. Feedback is welcome — just use the Sourceforge bug tracker, forums, and mailing lists.
This release is part of the unstable 1.5 branch. Its features will ultimately go into the stable 1.6 branch. You can download it from the innotop-devel package.
The major change is a new Command Summary’ mode (switch to this mode with the ‘C’ key) that’s similar to mytop’s ‘c’ mode. It shows you the relative size of variables from SHOW STATUS and SHOW VARIABLES. Here’s a sample:
Command Summary (? for help) localhost, 25+07:16:43, 2.45 QPS, 3 thd, 5.0.40 _____________________ Command Summary _____________________ Name Value Pct Last Incr Pct Select_scan 3244858 69.89% 2 100.00% Select_range 1354177 29.17% 0 0.00% Select_full_join 39479 0.85% 0 0.00% Select_full_range_join 4097 0.09% 0 0.00% Select_range_check 0 0.00% 0 0.00%
The default is to show the
Com_* variables, but I’ve used a different prefix to illustrate that you can view any variables you want. You just choose the prefix. Useful ones are
Sort_. This gives you instant insight into the kind of work your server is doing. You can see in the sample above that the kinds of joins the server does is healthily balanced towards scans and ranges on the first table. The server does very few full joins, full range joins, and range-check query plans (this is good).
The example shows one server, as you can see by the first line. Naturally, you can monitor many servers in aggregate, and it’s configured to do this by default if you’re watching more than one server. However, there’s a bug in the percentage columns when you do that (the Value columns are accurate when aggregated). I have a fix in mind for that, which will also fix many other things that cause me (and you) too much work when customizing innotop. But that’ll come later. I feel this is good enough for now, since the main use for this mode is when you’re just trying to familiarize yourself with a server, perhaps at a consulting job, or when reading someone’s tuning tutorial or the like.
Version 1.4.3 of the innotop MySQL and InnoDB monitor is out. This release fixes some minor bugs and feature annoyances, and at last innotop has thorough documentation, available online!
Here’s what’s new:
- Added standard –version command-line option
- Changed colors to cyan instead of blue; more visible on dark terminals.
- Added information to the filter-choosing dialog.
- Added column auto-completion when entering a filter expression.
- Changed Term::ReadKey from optional to mandatory.
- Clarified username in password prompting.
- Ten thousand words of documentation! Documentation is embedded in innotop, installed as a man page, and available online.
- innotop crashed in W mode when InnoDB status data was truncated.
- innotop didn’t display errors in tables if debug was enabled.
- The colored() subroutine wasn’t being created in non-interactive mode.
- Don’t prompt to save password except the first time.
I don’t know how much time I’ll get to put into this in the coming months, but there’s already a lot of half-finished functionality in the Subversion repository, including the ability to write innotop plugins. If you’re interested, the code is in the trunk and in various branches.
Hopefully I’ll get time to work on some of that before the year is out.