innodb crashes when importing big table using Expand Table Import

Bug #684829 reported by Aurimas Mikalauskas
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Unassigned
5.1
Fix Released
Medium
Unassigned
5.5
Fix Released
Medium
Unassigned

Bug Description

Hi,

I've tried importing table which was over 350G in size and the import failed with a crash after few minutes due to long semaphore wait. Here's the log output when the server crashed:

InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
101203 5:42:01 InnoDB: Assertion failure in thread 140148625274640 in file srv/srv0srv.c line 2440
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
101203 5:42:02 - mysqld got signal 6 ;

Here's how import started:

mysql> alter table moves IMPORT TABLESPACE;
InnoDB: import: extended import of archive/moves is started.
InnoDB: import: 6 indexes are detected.
InnoDB: Progress in %: 1 2 3 4 5 6InnoDB: Warning: a long semaphore wait:
--Thread 140148607887120 has waited at ./include/dict0boot.ic line 45 for 241.00 seconds the semaphore:
Mutex at 0x1118995a0 '&dict_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140148616881936 has waited at row/row0purge.c line 541 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0xe1fc00 '&dict_operation_lock'
a writer (thread id 140148608288528) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row/row0purge.c line 541
Last time write locked in file row/row0mysql.c line 2552
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

Then it was constantly reporting:

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1550569, signal count 3592150
--Thread 140148607887120 has waited at ./include/dict0boot.ic line 45 for 255.00 seconds the semaphore:
Mutex at 0x1118995a0 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 140148616881936 has waited at row/row0purge.c line 541 for 255.00 seconds the semaphore:
S-lock on RW-latch at 0xe1fc00 '&dict_operation_lock'
a writer (thread id 140148608288528) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row/row0purge.c line 541
Last time write locked in file row/row0mysql.c line 2552

This was the last one:

=====================================
101203 5:41:51 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
----------
BACKGROUND THREAD
----------
srv_master_thread loops: 79131 1_second, 79131 sleeps, 7912 10_second, 2292 background, 2292 flush
srv_master_thread log flush and writes: 80996
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1550569, signal count 3592150
--Thread 140148607887120 has waited at ./include/dict0boot.ic line 45 for 943.00 seconds the semaphore:
Mutex at 0x1118995a0 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 140148616881936 has waited at row/row0purge.c line 541 for 943.00 seconds the semaphore:
S-lock on RW-latch at 0xe1fc00 '&dict_operation_lock'
a writer (thread id 140148608288528) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row/row0purge.c line 541
Last time write locked in file row/row0mysql.c line 2552
Mutex spin waits 13571030, rounds 76995094, OS waits 865847
RW-shared spins 10091568, OS waits 478390; RW-excl spins 1914567, OS waits 164816
Spin rounds per wait: 5.67 mutex, 5.35 RW-shared, 5.67 RW-excl
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (read thread)
I/O thread 7 state: waiting for i/o request (read thread)
I/O thread 8 state: waiting for i/o request (read thread)
I/O thread 9 state: waiting for i/o request (read thread)
I/O thread 10 state: waiting for i/o request (write thread)
I/O thread 11 state: waiting for i/o request (write thread)
I/O thread 12 state: waiting for i/o request (write thread)
I/O thread 13 state: waiting for i/o request (write thread)
I/O thread 14 state: waiting for i/o request (write thread)
I/O thread 15 state: waiting for i/o request (write thread)
I/O thread 16 state: waiting for i/o request (write thread)
I/O thread 17 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
10698748 OS file reads, 102623351 OS file writes, 2095877 OS fsyncs
1 pending preads, 0 pending pwrites
10152.24 reads/s, 16384 avg bytes/read, 10113.49 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 3 merges
Hash table size 339996331, node heap has 90638 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1726755541785
Log flushed up to 1726755541785
Last checkpoint at 1726755541785
Max checkpoint age 1910316996
Checkpoint age target 1850619590
Modified age 0
Checkpoint age 0
0 pending log writes, 0 pending chkp writes
73557844 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 176076881920; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 4204987848 (2719970648 + 1485017200)
    Page hash 169998968
    Dictionary cache 680263488 (679994096 + 269392)
    File system 92848 (82672 + 10176)
    Lock system 424996872 (424996136 + 736)
    Recovery system 0 (0 + 0)
    Threads 407736 (406936 + 800)
Dictionary memory allocated 269392
Buffer pool size 10485760
Buffer pool size, bytes 171798691840
Free buffers 0
Database pages 10395122
Old database pages 3837241
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3562931, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15547563, created 539136, written 47095361
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 10395122, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 16196, id 140148642060048, state: waiting for server activity
Number of rows inserted 37033821, updated 99583441, deleted 445545, read 2000240221
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 14631F92
Purge done for trx's n:o < 14631E9E undo n:o < 2
History list length 122
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 14631F91, ACTIVE 943 sec, process no 16196, OS thread id 140148607887120 inserting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 119241, query id 173846268 invalidating query cache entries (table)
TABLE LOCK table `hidden`.`games` trx id 14631F91 lock mode IX
TABLE LOCK table `hidden`.`games_users` trx id 14631F91 lock mode IX
---TRANSACTION 14631EE3, ACTIVE 943 sec, process no 16196, OS thread id 140148608288528 importing tablespace
mysql tables in use 1, locked 1
MySQL thread id 125616, query id 173845896 localhost root
alter table moves IMPORT TABLESPACE
----------------------------
END OF INNODB MONITOR OUTPUT
============================

I assume a reason is that there was some activity on the server, though really it was on an unrelated database/table:

------------
TRANSACTIONS
------------
Trx id counter 14631F92
Purge done for trx's n:o < 14631E9E undo n:o < 2
History list length 122
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 14631F91, ACTIVE 255 sec, process no 16196, OS thread id 140148607887120 inserting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 119241, query id 173846268 invalidating query cache entries (table)
TABLE LOCK table `hidden`.`games` trx id 14631F91 lock mode IX
TABLE LOCK table `hidden`.`games_users` trx id 14631F91 lock mode IX
---TRANSACTION 14631EE3, ACTIVE 255 sec, process no 16196, OS thread id 140148608288528 importing tablespace
mysql tables in use 1, locked 1
MySQL thread id 125616, query id 173845896 localhost root
alter table moves IMPORT TABLESPACE

The server is 5.1.43-60.5.0.3.20-log (Percona SQL Server (GPL), XtraDB 9.1, Revision 60)

Related branches

Changed in percona-server:
assignee: nobody → Yasufumi Kinoshita (yasufumi-kinoshita)
Revision history for this message
Stewart Smith (stewart) wrote :

Changing to confirmed assuming Yasufumi has good idea what it is.

Changed in percona-server:
status: New → Confirmed
Revision history for this message
Alexey Kopytov (akopytov) wrote :

Might be a duplicate of http://bugs.mysql.com/bug.php?id=47183, fixed in 5.1.57.

Revision history for this message
Yasufumi Kinoshita (yasufumi-kinoshita) wrote :

we need to expand the 600 seconds threshold, during the import. I will fix it

Changed in percona-server:
importance: Undecided → Medium
Changed in percona-server:
status: Confirmed → Fix Committed
Stewart Smith (stewart)
Changed in percona-server:
milestone: none → 5.5.13-20.4
Revision history for this message
Alexey Kopytov (akopytov) wrote :

In 5.1 the fix was released in 5.1.57-12.8. Updating the target milestone accordingly.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1165

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.