Long running transactions

By Mark Callaghan on Monday, November 2, 2009 at 11:04am

I was debugging a server that had too many concurrent queries. From SHOW INNODB STATUS output, there were many long running transactions with uncommitted work and there were many more transactions blocked on InnoDB locks. This is not a good state for a busy OLTP server and I am trying to figure out if the problem is the application or InnoDB.

The state can be detected by reading SHOW INNODB STATUS output to find open transactions with uncommitted changes and other transactions blocked on InnoDB locks. This is an example of a transaction that has been open for 7 seconds (see ACTIVE 7 sec) which also has uncommitted changes (see undo log entries 1).


---TRANSACTION 1 1389611842, ACTIVE 7 sec, process no 23350, OS thread id 1794885952
2 lock struct(s), heap size 368, undo log entries 1
MySQL thread id 188195534, query id 868681019 X.X.X.X foobar

And this is an example of a transaction blocked waiting on a lock.

---TRANSACTION 1 1389342643, ACTIVE 49 sec, process no 23350, OS thread id 1567488320 inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368
MySQL thread id 187149582, query id 868106817 X.X.X.X foobar update
INSERT INTO barfoo values (1)
------- TRX HAS BEEN WAITING 49 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 13533204 n bits 344 index `PRIMARY` of table `sample/barfoo` trx id 1 1389342643 lock_mode X locks rec but not gap waiting

I don't want to spend my day reading SHOW INNODB STATUS. So I wrote 2 scripts to search for it. The first script finds searches SHOW INNODB STATUS for transactions with uncommitted changes that have been open for more than 5 seconds. It can find a problem in progress. After finding the server the next step to debug it is to log output from SHOW PROCESSLIST and SHOW INNODB STATUS and enable the innodb_lock_monitor table.

mysql -A -e "show innodb status\G" | \
awk "/TRANSACTIONS/ { t=1 } /ACTIVE/ { if ($5 > 5 && t == 1) { on=1 } else { on=0 } } /undo log/ { if (on == 1) { print $0 } }"

The second script searches the binlog for problems that happened in the past. For each transaction in the binlog, the time at which the transaction started is recorded. This script compares the start time for the current and previous commits. It prints binlog contents for transactions when the start time for the previous commit is min_time seconds greater than the start time for the current commit.

min_time=30
mysqlbinlog ... | \
cat -v | \
sed 's/TIMESTAMP=/TIMESTAMP= /' - | \
sed 's/\/\*\!\*\// ZZ/g' - | \
awk '/SET TIMESTAMP/ { pts=ts; ts=$3; if ((pts - ts) > min_time) { on=1; printf "line %s, delta %d\n", NR, pts - ts } else { on=0 } } // { if (on == 1) { print $0 } }' min_time=$min_time