A quest for the full InnoDB status

When running InnoDB you are able to dig into the engine internals, look at various gauges and counters, see past deadlocks and the list of all open transactions. This is in your reach with one simple command —

Shell

1

SHOW ENGINE InnoDB STATUS

. On most occasions it works beautifully. The problems appear when you have a large spike in number of connections to MySQL, which often happens when several transactions kill the database performance resulting in very long execution times for even simplest queries, or a huge deadlock.

In such rare cases

Shell

1

SHOW ENGINE InnoDB STATUS

often fails to provide the necessary information. The reason is that its output is limited to 64000 bytes, so a long list of transactions or a large deadlock dump may easily exhaust the limit. MySQL in such situation truncates the output so it fits the required size and obviously this is not good since you may lose some valuable information from your sight. With large deadlocks you can actually deal by intentionally creating a new tiny deadlock which will replace the previous one in the output thus reducing the space occupied by that section of InnoDB status. Baron once wrote an article on how to do this.

There is not such easy way for the long transaction list, but fortunately there are some alternatives to the limited MySQL command output.

First one is that you can have

Shell

1

innodb-status-file

option set in your my.cnf. This will make InnoDB to write the full status output into

Shell

1

innodb_status.<PID>

file located in MySQL data directory. Unfortunately this is a startup time parameter, so unless you set it early, it will not be available in an emergency situation.

Other possibility is to create a special InnoDB table called

Shell

1

innodb_monitor

:

Shell

1

CREATE TABLE innodb_monitor(aINT)ENGINE=InnoDB

Creating it causes the full status to be periodically printed into MySQL error log. You can later disable logging by simply dropping the table. The problem I faced many times is that people do not configure their error log at all, so the messages disappear into nothingness. So what then?

I discovered that InnoDB will still create the status file on disk even if you do not specify innodb-status-file option. The file is actually used for every

Shell

1

SHOW ENGINE InnoDB STATUS

call, so whenever someone runs the command, InnoDB writes the output to that file first and then the stored information is read back to user. To make things more difficult, MySQL keeps the file deleted, so it is not possible access it with a simple

Shell

1

catfilename

or any other command through the file system. However on many systems such as Linux or Solaris, but possibly also others, there is a relatively simple way to access deleted but not-yet-closed files (file is physically removed only after it is no longer open by any process).

First be sure to run

Shell

1

SHOW ENGINE InnoDB STATUS

at least once. Then see what MySQL process ID is:

Shell

1

2

garfield~# ps ax | grep [m]ysqld

11886?Ssl0:01/usr/sbin/mysqld--defaults-file=/etc/mysql/my.cnf

In my case the process ID is 11886, so I will be using it in the examples, but you should of course use whatever

Shell

1

ps

returned to you.

Now you can use

Shell

1

/proc

to see all the file descriptors that are being kept open by the process. So go to

Shell

1

/proc/<PID>/fd

and list all the files that were deleted.

Shell

1

2

3

4

5

6

7

garfield~# cd /proc/11886/fd

garfield fd# ls -l | grep deleted

lrwx------1root root64Oct3118:2612->/tmp/iblnLBhO(deleted)

lrwx------1root root64Oct3118:265->/tmp/ibuQBSgo(deleted)

lrwx------1root root64Oct3118:266->/tmp/ibLVtBuZ(deleted)

lrwx------1root root64Oct3118:267->/tmp/ibsMzkIA(deleted)

lrwx------1root root64Oct3118:268->/tmp/ibj08Rkc(deleted)

The entries are presented as symbolic links from file descriptor number to a real path as in

Shell

1

12->/tmp/iblnLBhO

.

One of these entries is what you are looking for, it’s often (always?) the file with the lowest file descriptor number, so in my case it should be 5. But of course you can try reading a few first bytes from every such file to discover where InnoDB status is. You can also help yourself with

Shell

1

lsof

tool available for many platforms:

Shell

1

2

3

4

5

6

garfield fd# lsof -c mysqld | grep deleted

mysqld11886mysql5uREG253,1013093212/tmp/ibuQBSgo(deleted)

mysqld11886mysql6uREG253,10013/tmp/ibLVtBuZ(deleted)

mysqld11886mysql7uREG253,10014/tmp/ibsMzkIA(deleted)

mysqld11886mysql8uREG253,10015/tmp/ibj08Rkc(deleted)

mysqld11886mysql12uREG253,10016/tmp/iblnLBhO(deleted)

The 4th column contains file descriptor numbers and in the 7th column there are the file sizes. This makes it obvious that InnoDB status has to be under file descriptor 5 since it’s the only non-zero length file.

Tags:

Categories:

Comments

I should check again, but I believe that it’s the mysql cmdline client that truncates the output, not the server. So it is possible to get it.

We could tweak so that the innodb-status-file option is enabled by default… doesn’t make much sense not to, if it writes to a file first anyway…. but I prefer a solution that can be accessed from the client side (although slow query log can’t be either in 5.0).

I think it’s the server. The code is in InnoDB. There are a couple places it happens; in one place it actually checks how big the output is and stops outputting any more txns.

The best tweak is a) my patches, which reduce the verbosity, b) Google’s patches, which increase the allowed size and move the deadlock and other less-useful stuff to the end of the output, so if it gets truncated at least you get the important stuff.