innodb crashes when importing big table using Expand Table Import
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://
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://
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/
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_
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/
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_
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/
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_
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`
---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`
---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-
Related branches
- Percona developers: Pending requested
- Stewart Smith: Pending requested
-
Diff: 168 lines (+44/-11)4 files modifiedinnodb_expand_import.patch (+27/-0)
innodb_pass_corrupt_table.patch (+2/-2)
innodb_separate_doublewrite.patch (+1/-1)
innodb_stats.patch (+14/-8)
- Oleg Tsarev (community): Needs Fixing (dev)
- Percona developers: Pending requested
-
Diff: 11671 lines (+7079/-693)63 files modifiedMakefile (+2/-2)
control_online_alter_index.patch (+1/-1)
innodb_adaptive_hash_index_partitions.patch (+45/-27)
innodb_admin_command_base.patch (+1/-1)
innodb_buffer_pool_pages_i_s.patch (+3/-3)
innodb_buffer_pool_shm.patch (+7/-7)
innodb_deadlock_count.patch (+3/-3)
innodb_dict_size_limit.patch (+10/-10)
innodb_expand_import.patch (+597/-87)
innodb_extend_slow.patch (+35/-34)
innodb_extra_rseg.patch (+1/-1)
innodb_fake_changes.patch (+614/-0)
innodb_fast_checksum.patch (+33/-46)
innodb_files_extend.patch (+15/-24)
innodb_fix_misc.patch (+39/-39)
innodb_io_patches.patch (+39/-38)
innodb_lru_dump_restore.patch (+8/-8)
innodb_overwrite_relay_log_info.patch (+17/-18)
innodb_pass_corrupt_table.patch (+106/-100)
innodb_recovery_patches.patch (+10/-10)
innodb_separate_doublewrite.patch (+34/-34)
innodb_show_lock_name.patch (+6/-6)
innodb_show_status.patch (+15/-15)
innodb_show_status_extend.patch (+8/-8)
innodb_show_sys_tables.patch (+1/-1)
innodb_split_buf_pool_mutex.patch (+37/-26)
innodb_stats.patch (+31/-25)
innodb_thread_concurrency_timer_based.patch (+7/-7)
install_tests.sh.THIS (+35/-0)
log_connection_error.patch (+3/-3)
log_warnings_suppress.patch (+3/-3)
memory_dynamic_rows.patch (+2865/-0)
microsec_process.patch (+1/-1)
mysql-test/memory_dynamic_rows.patch/percona_heap_blob.result (+952/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_blob.test.disabled (+642/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug783366.result (+14/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug783366.test.disabled (+19/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug783451.result (+132/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug783451.test.disabled (+16/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug784464.result (+70/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug784464.test.disabled (+67/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug784468.result (+15/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug784468.test.disabled (+16/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug788544.result (+9/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug788544.test.disabled (+15/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug788576.result (+19/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug788576.test.disabled (+19/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug788722.result (+18/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug788722.test.disabled (+20/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug789131.result (+7/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_bug789131.test.disabled (+14/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_var.result (+194/-0)
mysql-test/memory_dynamic_rows.patch/percona_heap_var.test.disabled (+84/-0)
normalize_patches.sh (+1/-1)
optimizer_fix.patch (+2/-2)
processlist_row_stats.patch (+2/-2)
query_cache_enhance.patch (+2/-2)
response_time_distribution.patch (+8/-8)
show_slave_status_nolock.patch (+1/-1)
show_temp.patch (+6/-6)
slow_extended.patch (+17/-17)
sql_no_fcache.patch (+8/-8)
userstat.patch (+58/-58)
Changed in percona-server: | |
assignee: | nobody → Yasufumi Kinoshita (yasufumi-kinoshita) |
Changed in percona-server: | |
importance: | Undecided → Medium |
Changed in percona-server: | |
status: | Confirmed → Fix Committed |
Changed in percona-server: | |
milestone: | none → 5.5.13-20.4 |
Changing to confirmed assuming Yasufumi has good idea what it is.