long semaphore wait output during compact backup rebuild indexes
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona XtraBackup moved to https://jira.percona.com/projects/PXB |
Fix Released
|
Undecided
|
Alexey Kopytov |
Bug Description
During
innobackupex --apply-log --rebuild-indexes --use-memory=10G /mnt/fio/
I see following output, which I believe is not needed and confusing:
InnoDB: Warning: a long semaphore wait:
--Thread 140352260916992 has waited at row0purge.c line 665 for 861.00 seconds the semaphore:
S-lock on RW-latch at 0xa43be0 '&dict_
a writer (thread id 140363751614208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.c line 665
Last time write locked in file compact.c line 918
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
=======
121212 10:02:29 INNODB MONITOR OUTPUT
=======
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 1_second, 1 sleeps, 0 10_second, 1 background, 0 flush
srv_master_thread log flush and writes: 1
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 141082, signal count 141203
--Thread 140352260916992 has waited at row0purge.c line 665 for 866.00 seconds the semaphore:
S-lock on RW-latch at 0xa43be0 '&dict_
a writer (thread id 140363751614208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.c line 665
Last time write locked in file compact.c line 918
Mutex spin waits 17622, rounds 67859, OS waits 1904
RW-shared spins 4551611, rounds 65660896, OS waits 139107
RW-excl spins 0, rounds 85, OS waits 1
Spin rounds per wait: 3.85 mutex, 14.43 RW-shared, 85.00 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 (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1294174 OS file reads, 897731 OS file writes, 206491 OS fsyncs
6.10 reads/s, 989351 avg bytes/read, 212.79 writes/s, 74.60 fsyncs/s
-------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------
Ibuf: size 1, free list len 122408, seg size 122410, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 21249841, node heap has 1 buffer(s)
858094.85 hash searches/s, 3043.45 non-hash searches/s
---
LOG
---
Log sequence number 407835978301
Log flushed up to 407835704337
Last checkpoint at 407835704337
Max checkpoint age 989246
Checkpoint age target 958333
Modified age 273964
Checkpoint age 273964
0 pending log writes, 0 pending chkp writes
197498 log i/o's done, 71.30 log i/o's/second
-------
BUFFER POOL AND MEMORY
-------
Total memory allocated 11034165248; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
Adaptive hash index 170019328 (169998728 + 20600)
Page hash 10625704 (buffer pool 0 only)
Dictionary cache 42584062 (42501104 + 82958)
File system 87512 (82672 + 4840)
Lock system 26564264 (26563016 + 1248)
Recovery system 0 (0 + 0)
Dictionary memory allocated 82958
Buffer pool size 655359
Buffer pool size, bytes 10737401856
Free buffers 0
Database pages 655358
Old database pages 241899
Modified db pages 19
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8995694, not young 0
0.35 youngs/s, 0.00 non-youngs/s
Pages read 9755742, created 1790248, written 2218934
0.35 reads/s, 609.17 creates/s, 761.41 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 655358, unzip_LRU len: 0
I/O sum[247200]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 5E88E00
Read view up limit trx id 5E88E00
Read view low limit trx id 5E88E00
Read view individually stored trx ids:
-----------------
Main thread process no. 18442, id 140352260916992, state: master purging
Number of rows inserted 1415074545, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 5E88E0D
Purge done for trx's n:o < 5E87C92 undo n:o < 0
History list length 485
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 5E88E0C, ACTIVE 866 sec inserting index entries
8 lock struct(s), heap size 1248, 29 row lock(s), undo log entries 4
TABLE LOCK table "SYS_STATS" trx id 5E88E0C lock mode IX
RECORD LOCKS space id 0 page no 13 n bits 72 index "CLUST_IND" of table "SYS_STATS" trx id 5E88E0C lock_mode X
TABLE LOCK table "SYS_FIELDS" trx id 5E88E0C lock mode IX
RECORD LOCKS space id 0 page no 12 n bits 152 index "CLUST_IND" of table "SYS_FIELDS" trx id 5E88E0C lock_mode X
TABLE LOCK table "SYS_INDEXES" trx id 5E88E0C lock mode IX
RECORD LOCKS space id 0 page no 11 n bits 112 index "CLUST_IND" of table "SYS_INDEXES" trx id 5E88E0C lock_mode X
TABLE LOCK table "tpccw2500"."stock" trx id 5E88E0C lock mode X
RECORD LOCKS space id 0 page no 11 n bits 112 index "CLUST_IND" of table "SYS_INDEXES" trx id 5E88E0C lock_mode X locks gap before rec
-------
END OF INNODB MONITOR OUTPUT
=======
=======
121212 10:02:49 INNODB MONITOR OUTPUT
=======
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 1_second, 1 sleeps, 0 10_second, 1 background, 0 flush
srv_master_thread log flush and writes: 1
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 141103, signal count 141226
--Thread 140352260916992 has waited at row0purge.c line 665 for 886.00 seconds the semaphore:
S-lock on RW-latch at 0xa43be0 '&dict_
a writer (thread id 140363751614208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.c line 665
Last time write locked in file compact.c line 918
Mutex spin waits 17699, rounds 68590, OS waits 1925
RW-shared spins 4551611, rounds 65660896, OS waits 139107
RW-excl spins 0, rounds 85, OS waits 1
Spin rounds per wait: 3.88 mutex, 14.43 RW-shared, 85.00 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 (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1294299 OS file reads, 901991 OS file writes, 207983 OS fsyncs
6.25 reads/s, 966000 avg bytes/read, 212.99 writes/s, 74.60 fsyncs/s
-------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------
Ibuf: size 1, free list len 122408, seg size 122410, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 21249841, node heap has 1 buffer(s)
860360.78 hash searches/s, 3051.40 non-hash searches/s
---
LOG
---
Log sequence number 408159206048
Log flushed up to 408158644762
Last checkpoint at 408158644762
Max checkpoint age 989246
Checkpoint age target 958333
Modified age 561286
Checkpoint age 561286
0 pending log writes, 0 pending chkp writes
198926 log i/o's done, 71.40 log i/o's/second
-------
BUFFER POOL AND MEMORY
-------
Total memory allocated 11034165248; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
Adaptive hash index 170019328 (169998728 + 20600)
Page hash 10625704 (buffer pool 0 only)
Dictionary cache 42584062 (42501104 + 82958)
File system 87512 (82672 + 4840)
Lock system 26564264 (26563016 + 1248)
Recovery system 0 (0 + 0)
Dictionary memory allocated 82958
Buffer pool size 655359
Buffer pool size, bytes 10737401856
Free buffers 0
Database pages 655358
Old database pages 241899
Modified db pages 29
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8995704, not young 0
0.50 youngs/s, 0.00 non-youngs/s
Pages read 9755752, created 1802463, written 2234164
0.50 reads/s, 610.72 creates/s, 761.46 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 655358, unzip_LRU len: 0
I/O sum[247200]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 5E88E00
Read view up limit trx id 5E88E00
Read view low limit trx id 5E88E00
Read view individually stored trx ids:
-----------------
Main thread process no. 18442, id 140352260916992, state: master purging
Number of rows inserted 1415074545, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 5E88E0D
Purge done for trx's n:o < 5E87C92 undo n:o < 0
History list length 485
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 5E88E0C, ACTIVE 886 sec inserting index entries
8 lock struct(s), heap size 1248, 29 row lock(s), undo log entries 4
TABLE LOCK table "SYS_STATS" trx id 5E88E0C lock mode IX
RECORD LOCKS space id 0 page no 13 n bits 72 index "CLUST_IND" of table "SYS_STATS" trx id 5E88E0C lock_mode X
TABLE LOCK table "SYS_FIELDS" trx id 5E88E0C lock mode IX
RECORD LOCKS space id 0 page no 12 n bits 152 index "CLUST_IND" of table "SYS_FIELDS" trx id 5E88E0C lock_mode X
TABLE LOCK table "SYS_INDEXES" trx id 5E88E0C lock mode IX
RECORD LOCKS space id 0 page no 11 n bits 112 index "CLUST_IND" of table "SYS_INDEXES" trx id 5E88E0C lock_mode X
TABLE LOCK table "tpccw2500"."stock" trx id 5E88E0C lock mode X
RECORD LOCKS space id 0 page no 11 n bits 112 index "CLUST_IND" of table "SYS_INDEXES" trx id 5E88E0C lock_mode X locks gap before rec
-------
END OF INNODB MONITOR OUTPUT
=======
Rebuilding indexes for table tpccw2500/warehouse (space id: 10)
121212 10:02:50 Percona XtraDB (http://
[notice (again)]
If you use binary log and don't use any hack of group commit,
the binary log position seems to be:
xtrabackup: starting shutdown with innodb_
121212 10:02:50 InnoDB: Starting shutdown...
InnoDB: ###### Diagnostic info printed to the standard error stream
121212 10:03:03 InnoDB: Shutdown completed; log sequence number 408172273933
Changed in percona-xtrabackup: | |
status: | New → In Progress |
assignee: | nobody → Alexey Kopytov (akopytov) |
Changed in percona-xtrabackup: | |
status: | In Progress → Fix Released |
Percona now uses JIRA for bug reports so this bug report is migrated to: https:/ /jira.percona. com/browse/ PXB-1192