MySQL Bugs: #34414: SELECT hangs in InnoDB while running massive UPDATEs

Bug #34414	SELECT hangs in InnoDB while running massive UPDATEs
Submitted:	8 Feb 2008 13:07	Modified:	13 May 2010 16:12
Reporter:	Yoshinori Matsunobu	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.1.23	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
START TRANSACTION WITH CONSISTENT SNAPSHOT; 
-> SELECT; 
-> waiting long time  (massive updates from other sessions)
-> SELECT; 
then SELECT hangs in InnoDB. 

This might happen when taking an online backup(large tables) with mysqldump --single-transaction
while there are massive insert/update/delete traffics.

How to repeat:
1. run mysqlslap (please make sure it will take long time, e.g: running 50,000,000 queries)
/path/to/mysqlslap --concurrency=50 --iterations=1 --number-int-cols=2 --number-char-cols=3 --auto-generate-sql --engine=innodb --auto-generate-sql-add-autoincrement --auto-generate-sql-load-type=update --auto-generate-sql-write-number=10000 --number-of-queries=50000000

2. as soon as starting mysqlslap, connect to mysqld
/path/to/mysql -uroot mysqlslap

3. execute the following statements
mysql> start transaction with consistent snapshot;
Query OK, 0 rows affected (0.00 sec)

mysql> select avg(intcol1) from t1;
+-----------------+
| avg(intcol1) |
+-----------------+
| 1308397607.6205 |
+-----------------+
1 row in set (0.11 sec)

mysql> select avg(intcol1) from t1;
+-----------------+
| avg(intcol1) |
+-----------------+
| 1308397607.6205 |
+-----------------+
1 row in set (0.23 sec)

mysql> select sleep(1200); # wait for a long time
+-------------+
| sleep(1200) |
+-------------+
| 0 |
+-------------+
1 row in set (20 min 0.01 sec)

mysql> select avg(intcol1) from t1;
->  hangs

---

Yasunori,

what does SHOW INNODB STATUS\G print during the hang?

Does the server print anything to the .err log if you leave it hung for 15 minutes?

Regards,

Heikki

show innodb status log

Attachment: show_innodb_status.txt (text/plain), 41.80 KiB.

show processlist log

Attachment: show_processlist.txt (text/plain), 10.48 KiB.

Heikki,

"show innodb status" and "show processlist" were attached.

No specific error message was written to .err file.

Yoshinori,

---TRANSACTION 0 36239217, ACTIVE 1539 sec, process no 13237, OS thread id 1172302176 fetching rows, thread declared inside InnoDB 456
mysql tables in use 1, locked 0
MySQL thread id 106, query id 17357367 localhost 127.0.0.1 root Sending data
select avg(intcol1) from t1
Trx read view will not see trx with id >= 0 36239218, sees < 0 22505490

It is probably not hung, just proceeds very slowly.

Please print two successive SHOW INNODB STATUS\G. If the number after "thread declared inside InnoDB" changes, then the query is proceeding. The number '456' is 'tickets' that the thread uses to enter InnoDB.

Regards,

Heikki

Heikki,

I ran show innodb status serveral times.
"thread declared inside InnoDB" was not shown after reaching 500 (default innodb_concurrency_tickets) and SELECT is not finished yet (State: "Sending data").

1.
------------
TRANSACTIONS
------------
Trx id counter 0 70862677
Purge done for trx's n:o < 0 57204450 undo n:o < 0 0
History list length 6829114
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 57204448, ACTIVE 1317 sec, process no 26363, OS thread id 1171769696 fetching rows, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 52, query id 5524680 localhost 127.0.0.1 root Sending data
select avg(intcol1) from t1
Trx read view will not see trx with id >= 0 57204449, sees < 0 57204449

2.
------------
TRANSACTIONS
------------
Trx id counter 0 73436285
Purge done for trx's n:o < 0 57204450 undo n:o < 0 0
History list length 8115918
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 26363, OS thread id 1172035936
MySQL thread id 53, query id 8261214 localhost 127.0.0.1 root
show innodb status
---TRANSACTION 0 57204448, ACTIVE 1518 sec, process no 26363, OS thread id 1171769696
mysql tables in use 1, locked 0
MySQL thread id 52, query id 5524680 localhost 127.0.0.1 root Sending data
select avg(intcol1) from t1
Trx read view will not see trx with id >= 0 57204449, sees < 0 57204449

3.
------------
TRANSACTIONS
------------
Trx id counter 0 73436285
Purge done for trx's n:o < 0 57204450 undo n:o < 0 0
History list length 8115918
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 26363, OS thread id 1172035936
MySQL thread id 53, query id 8261219 localhost 127.0.0.1 root
show innodb status
---TRANSACTION 0 57204448, ACTIVE 2391 sec, process no 26363, OS thread id 1171769696
mysql tables in use 1, locked 0
MySQL thread id 52, query id 5524680 localhost 127.0.0.1 root Sending data
select avg(intcol1) from t1
Trx read view will not see trx with id >= 0 57204449, sees < 0 57204449

Verified exactly as described in "How to repeat" with latest 5.1.24-BK on Linux. Last select hangs for 1800+ seconds already (no explict my.cnf settings). 

Waits on  buf/bug0buf.c line 547 are also present.

Since the state of the thread changes, it is not genuinely hung. It just progresses slowly.

I am marking this as 'Not a bug'. There are lots of file reads per second. The way to resolve the problem is to add more memory or make the tables smaller, so that there is less disk I/O.

Heikki,

I'd still consider a problem the fact that executing SELECT takes much longer than concurrent transactions spent changing data before it started.

Does Oracle, for example, demonstrate the same behaviour (question to myself also)?

Valeriy,

----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 1304889730; in additional pool allocated 11399168
Dictionary memory allocated 37240
Buffer pool size   70400
Free buffers       0
Database pages     70384
Modified db pages  22469
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages read 421147, created 497196, written 861125
293.71 reads/s, 0.95 creates/s, 26.18 writes/s
Buffer pool hit rate 657 / 1000

It is very much disk-bound. The only way to speed up one query is to slow down other queries.

In some database brands you probably can prioritize a query thread, but not in MySQL/InnoDB.

saw another case when innodb selects slowed down alot, and there was a 1.5 million 'History list length' due to a sleeping transaction that didn't commit/rollback
for 20 hours.

see feature request at bug #54455