1

For an application using MySQL 5.5.60 under Debian, lately we experience transactions with database writes, which do not succeed within the 50s time limit of the innodb_lock_wait_timeout setting.

I need to identify the transactions / statements which hold those locks, thus the cause, to start resolving the issue.

My hope was to get this information from the MySQL side, but so far it seems embarrassingly difficult to identify the blockers.
Best information was in the TRANSACTIONS section from the report given by a show engine innodb status statement, e.g.:

---TRANSACTION 6FEE8DD5, ACTIVE 13021 sec
1314 lock struct(s), heap size 129464, 1599 row lock(s), undo log entries 1212
MySQL thread id 16165411, OS thread handle 0x7f1491f53700, query id 1056480972 host.domain.tld 217.69.64.139 username
Trx read view will not see trx with id >= 6FEE8DD6, sees < 6FEE0FE9

Though I do not see any SQL statement here.

For unknown reason such a transaction does not show up in the MySQL slow query log (or processlist, innotop, mytop etc.). And if it would show up there, it will not list the MySQL thread id or the query id.

The thread id seems to be listed in the MySQL global log, which I dared not to activate during business hours, due to the mass of information it has to store.

Is there a better approach?

My only hint for the invisibility so far is that multiple statements might be displayed differently.

Note transaction can be active even if the connection is in “Sleep” stage – if it is multiple-statement transaction.

(Source)

Can this be the case? And how would one identify /debug such a source for locking?

3
  • The mysql thread id 16165411 is the query that will exist in SHOW PROCESSLIST by the same number. Capture the full SHOW ENGINE INNODB STATUS (and include it) and SHOW PROCESSLIST when its blocking to get the queries. Show the EXPLAIN {query} for the two queries, and the EXPLAIN {tablename} for the tables in those queries.
    – danblack
    Feb 26, 2020 at 0:04
  • You could also use a slow query log to find which statements are slow.
    – danblack
    Feb 26, 2020 at 0:05
  • Hi @danblack, thanks for your comments. The troubling bit is that I see nothing there. I am working on a script that does the catching to prevent mistakes from my side. I also try to explore weirder routes like the hint on "idle-in-transaction locking" from the Appendix E of "High Performance MySQL, 3rd ed".
    – mvw
    Feb 26, 2020 at 17:16

2 Answers 2

2

This query may assist in your search for locking and blocking ids.

# IS-tx-wait-block-qrys.sql to help research BUSY systems Last Updated 20191227 wh
# if this helps you, please email SHAREABLE comments to info@mysqlservertuning.com
# From article at 
# https://aws.amazon.com/premiumsupport/knowledge-center/rds-mysql-server-activity/
# 20191227 tested on MariaDB 10.3.10

SELECT r.trx_id waiting_trx_id, r.trx_mysql_thread_id waiting_thread, r.trx_query waiting_query, b.trx_id blocking_trx_id, b.trx_mysql_thread_id blocking_thread, b.trx_query blocking_query FROM information_schema.innodb_lock_waits w INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id;

9
  • Thanks for your answer. I see entries in table innodb_trx, but so far I saw no entries in innodb_locks and innodb_lockwaits. So I got no information from queries that join over these tables. I tried similar queries from the "MySQL High Performance, 3rd ed" book and the MySQL documentation. No luck. There is a hint in the MySQL documentation, that these tables seem empty if some innodb plugins are not installed, but as far as I can tell, they are installed.
    – mvw
    Feb 26, 2020 at 14:55
  • 1
    Can you cause the query to run that likely would get delayed and run this query AS IS while your long running query is active? Feb 26, 2020 at 16:25
  • @mvw If you review the complete post, A) early it mentions being 1/2 completed and B) a later comment mentions requirement to read table twice that is not in the script. From my perspective, this is info that should be removed from the web, including the archives. Feb 26, 2020 at 21:43
  • Today we had a blocking MySQL thread in our test environment, caused by an early terminated Selenium test. Here I got information from innodb_locks and innodb_lockwaits. Guess i simply missed the entries on the much faster production server so far.
    – mvw
    Feb 27, 2020 at 15:57
  • I put your statement in my detection script on our production, using a sampling interval of 1s. But it did not catch anything today, one event of a failing transaction happening.
    – mvw
    Feb 27, 2020 at 16:00
1
  • Don't use autocommit=0, you might have forgotten to do COMMIT.
  • Try SHOW PROCESSLIST; again. But this time look for the non-system process with the highest "Time". It may indicate the 'user@host' that forgot to COMMIT (or whatever).
  • Alas, the slowlog does not show a query until it finishes.

"Sleep" can occur for an open transaction:

BEGIN;
SELECT ... FOR UPDATE; -- "SELECT" shows in processlist
do some client work    -- "Sleep" shows now
INSERT ...             -- "INSERT" shows
COMMIT                 -- "COMMIT" shows
1
  • Hi @RickJames. The hint about interfering interactive users is valid, but this seems not the issue here. We found one of our non-interactive house keeping jobs had suspicious exceptions, this is our suspect #1 right now. I had also taken an hour of global log, to extract long running transactions, but I am not done processing it.
    – mvw
    Mar 2, 2020 at 12:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.