long semaphore wait output during compact backup rebuild indexes

Bug #1089618 reported by Vadim Tkachenko
6
This bug affects 1 person
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/back/2012-12-12_08-02-29/

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_operation_lock'
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_operation_lock'
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]:cur[4284], unzip sum[0]:cur[0]
--------------
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_operation_lock'
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]:cur[19524], unzip sum[0]:cur[0]
--------------
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://www.percona.com) 1.1.8-20.1 started; log sequence number 363149060878

[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_fast_shutdown = 1
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
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/PXB-1192

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.