Innodb Threads Settings

maurizio · March 14, 2011, 8:21am

We are running MySQL 5.5.9 on a Dual XEON Server with 8 cores and 120GB of RAM. The tablespace is on a fast SSD Drive.

I was experiencing very low mysql performance while the overall CPU load was under 10% and very low SSD access.

After looking at innodb monitor I lowered innodb_thread_concurrency from 256 to 32. Result: a huge performance boost. Seems the threads were waiting for mutexes most of the time…

My questions are:
Could 32 threads still be to much?
What is a good mutex spin wait/ os wait ratio?
Is it normal to have all I/O threads in state: “wait Windows aio” (I never saw another state)?

Current Settings:
innodb_read_io_threads = 8
innodb_write_io_threads = 8
innodb_thread_concurrency = 32

Thank you very much for your help!
Maurizio

— APPENDIX ----

Some semaphores innodb monitor outputs:
20 seconds:

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 1237274, signal count 1718960
Mutex spin waits 61927390, rounds 88274233, OS waits 1191097
RW-shared spins 292403, rounds 1200748, OS waits 22765
RW-excl spins 30001, rounds 1436869, OS waits 18966
Spin rounds per wait: 1.43 mutex, 4.11 RW-shared, 47.89 RW-excl

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 1510828, signal count 1927689
Mutex spin waits 64256205, rounds 98465742, OS waits 1460531
RW-shared spins 313695, rounds 1311507, OS waits 25333
RW-excl spins 32153, rounds 1546598, OS waits 20362
Spin rounds per wait: 1.53 mutex, 4.18 RW-shared, 48.10 RW-excl

This is a full innodb monitor output:

110314 13:25:32 INNODB MONITOR OUTPUT

Per second averages calculated from the last 20 seconds

BACKGROUND THREAD

srv_master_thread loops: 11373 1_second, 11372 sleeps, 1124 10_second, 405 background, 405 flush
srv_master_thread log flush and writes: 11464

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 1508316, signal count 1925586
Mutex spin waits 64229942, rounds 98364059, OS waits 1458040
RW-shared spins 313502, rounds 1310927, OS waits 25321
RW-excl spins 32136, rounds 1545701, OS waits 20355
Spin rounds per wait: 1.53 mutex, 4.18 RW-shared, 48.10 RW-excl

TRANSACTIONS

Trx id counter 596A0C341
Purge done for trx’s n:o < 596A0B720 undo n:o < 0
History list length 205
LIST OF TRANSACTIONS FOR EACH SESSION:
—TRANSACTION 596A0C1C9, not started, OS thread id 208136
MySQL thread id 17697, query id 8151093 localhost ::1 root
—TRANSACTION 596A0C333, not started, OS thread id 20760
MySQL thread id 17610, query id 8151726 localhost ::1 root
—TRANSACTION 596A0B286, not started, OS thread id 285112
MySQL thread id 17570, query id 8144961 localhost ::1 root
—TRANSACTION 596A0BE36, not started, OS thread id 55348
MySQL thread id 17339, query id 8149503 localhost ::1 root
—TRANSACTION 0, not started, OS thread id 84980
MySQL thread id 1791, query id 6569273 localhost ::1 root
—TRANSACTION 59647C428, not started, OS thread id 57584
MySQL thread id 49, query id 1103345 localhost ::1 root
—TRANSACTION 596A0C340, ACTIVE 0 sec, OS thread id 30544 starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 0
MySQL thread id 17670, query id 8151743 localhost ::1 root statistics
Select DomainUID from DomainTable Where Domain=‘http://www.blawsom.com’ Limit 1
Trx read view will not see trx with id >= 596A0C341, sees < 596A0863E
—TRANSACTION 596A0863E, ACTIVE 37 sec, OS thread id 140664 fetching rows, thread declared inside InnoDB 395
mysql tables in use 1, locked 1
30867 lock struct(s), heap size 3996088, 8006426 row lock(s)
MySQL thread id 893, query id 8126690 localhost ::1 root Sending data
Replace Into Backlink.2011_10

( SELECT LinkDomainUID, DomainUID, PageUID, Position, DeepLink, Follow, Active, TextUID, Week, WeekRescan, YearRescan FROM Firma.PagerelationsTable

WHERE Saved = 99 Limit 20300000, 100000 )

FILE I/O

I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: wait Windows aio (read thread)
I/O thread 6 state: wait Windows aio (read thread)
I/O thread 7 state: wait Windows aio (read thread)
I/O thread 8 state: wait Windows aio (read thread)
I/O thread 9 state: wait Windows aio (read thread)
I/O thread 10 state: wait Windows aio (write thread)
I/O thread 11 state: wait Windows aio (write thread)
I/O thread 12 state: wait Windows aio (write thread)
I/O thread 13 state: wait Windows aio (write thread)
I/O thread 14 state: wait Windows aio (write thread)
I/O thread 15 state: wait Windows aio (write thread)
I/O thread 16 state: wait Windows aio (write thread)
I/O thread 17 state: wait Windows aio (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 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
2557122 OS file reads, 162752 OS file writes, 28198 OS fsyncs
86.20 reads/s, 5248 avg bytes/read, 9.05 writes/s, 3.85 fsyncs/s

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 261426, seg size 261428, 13571 merges
merged operations:
insert 83277, delete mark 459921, delete 58180
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 144498583, node heap has 83577 buffer(s)
94999.75 hash searches/s, 1993.50 non-hash searches/s

LOG

Log sequence number 9836204638037
Log flushed up to 9836204595512
Last checkpoint at 9835970245764
0 pending log writes, 0 pending chkp writes
11324 log i/o’s done, 1.10 log i/o’s/second

BUFFER POOL AND MEMORY

Total memory allocated 74725720064; in additional pool allocated 0
Dictionary memory allocated 1012343
Buffer pool size 4456448
Free buffers 1246014
Database pages 2587126
Old database pages 955033
Modified db pages 63332
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 10964, not young 0
5.65 youngs/s, 0.00 non-youngs/s
Pages read 2556935, created 32065, written 144994
86.20 reads/s, 5.20 creates/s, 6.85 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
LRU len: 2587126, unzip_LRU len: 1446750
I/O sum[4719]:cur[6], unzip sum[5324]:cur[10]

ROW OPERATIONS

2 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 140360, state: sleeping
Number of rows inserted 2259224, updated 1561336, deleted 1190, read 2729194687
65.40 inserts/s, 10.85 updates/s, 0.00 deletes/s, 96350.43 reads/s

END OF INNODB MONITOR OUTPUT

Peter · March 14, 2011, 10:11am

Hi,

There does not seems to be much load in the innodb sample you have provided. It shows there is one IO pending with only 80 reads/sec which is rather little for SSD.

Also note:

WHERE Saved = 99 Limit 20300000, 100000

This is pretty bad for performance because MySQL has to skip 20300000 rows to get you 100000

This can be real cause of your performance issues

maurizio · March 14, 2011, 2:42pm

Hi Peter,

thanks for your reply.
Yes, there was little load and the query you mentioned is slow, but only a maintenance task run once a week - not our typical load.

The server is runnig quite fast now even under heavier load.
With 256 as innodb_thread_concurrency and 32 i/o thread the performance was a good deal worse for the same load.

What do you say to my questions:
Could innodb_thread_concurrency=32 still be to much?
What is a good mutex spin wait/ os wait ratio?
Is it normal to have all I/O threads in state: “wait Windows aio” (I never saw another state)?

This is an automatic innodb monitor output in our error.log after a long semaphore wait with innodb_thread_concurrency=256:

InnoDB: Warning: a long semaphore wait:
–Thread 14316 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0000000140758C08 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
a writer (thread id 183672) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
Last time write locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
110309 12:02:06 INNODB MONITOR OUTPUT

Per second averages calculated from the last 30 seconds

BACKGROUND THREAD

srv_master_thread loops: 17925 1_second, 17921 sleeps, 1701 10_second, 5612 background, 5606 flush
srv_master_thread log flush and writes: 18214

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 4529303, signal count 10234957
–Thread 133740 has waited at …....\mysql-5.5.9\storage\innobase\row\row0ins.c line 2002 for 20.00 seconds the semaphore:
X-lock on RW-latch at 00000003F13D8F40 created in file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 898
a writer (thread id 240236) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\buf\buf0flu.c line 1292
Last time write locked in file …....\mysql-5.5.9\storage\innobase\row\row0ins.c line 2002
–Thread 283240 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293 for 160.00 seconds the semaphore:
X-lock on RW-latch at 0000000140758C08 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
a writer (thread id 183672) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
Last time write locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
–Thread 184808 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 215236 has waited at …....\mysql-5.5.9\storage\innobase\row\row0purge.c line 654 for 20.00 seconds the semaphore:
S-lock on RW-latch at 00000001407CD940 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 710
a writer (thread id 45764) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\row\row0purge.c line 654
Last time write locked in file …....\mysql-5.5.9\storage\innobase\row\row0mysql.c line 2781
–Thread 211668 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 240236 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 135260 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 14316 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 247.00 seconds the semaphore:
S-lock on RW-latch at 0000000140758C08 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
a writer (thread id 183672) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
Last time write locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
–Thread 218044 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293 for 20.00 seconds the semaphore:
X-lock on RW-latch at 0000000140758C08 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
a writer (thread id 183672) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
Last time write locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
–Thread 91896 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 22664 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 7376 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 183672 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 180060 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 60552 has waited at …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
Mutex at 000000000A89F1C8 created file …....\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
waiters flag 1
–Thread 84312 has waited at G:\pb2\build\sb_0-2859905-1295578448.44\mysql-5.5.9\storage\ innobase\include\dict0boot.ic line 45 for 20.00 seconds the semaphore:
Mutex at 0000000113990EA8 created file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 697, lock var 1
waiters flag 1
–Thread 225356 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 740 for 20.00 seconds the semaphore:
Mutex at 0000000113990EA8 created file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 697, lock var 1
waiters flag 1
Mutex spin waits 69375442, rounds 76371569, OS waits 940402
RW-shared spins 6581324, rounds 134920002, OS waits 2488034
RW-excl spins 2402458, rounds 62313034, OS waits 903876
Spin rounds per wait: 1.10 mutex, 20.50 RW-shared, 25.94 RW-excl

TRANSACTIONS

Trx id counter 58278C705
Purge done for trx’s n:o < 58278C6A4 undo n:o < 3
History list length 502
LIST OF TRANSACTIONS FOR EACH SESSION:
—TRANSACTION 58278C6D1, not started, OS thread id 218044
MySQL thread id 23995, query id 4150839 localhost ::1 root Opening tables
SELECT MAX(DomainUID) FROM DomainTable
—TRANSACTION 58278C6E1, not started, OS thread id 283240
MySQL thread id 23989, query id 4150730 localhost ::1 root Opening tables
SELECT *

						FROM `userdomaintable` 

							JOIN domaintable As Domain ON (`userdomaintable`.`DomainUID` = `domain`.`DomainUID`)

							Where `Domain`.`Domain` = '[URL]http://www.my-art-print.de[/URL]'

—TRANSACTION 58278C6FE, not started, OS thread id 225356
MySQL thread id 23982, query id 4150933 localhost ::1 root Opening tables
SELECT d.Domain, d.DomainUID, ud.*

			FROM UserdomainTable as ud JOIN DomainTable as d 

			ON ud.DomainUID = d.DomainUID

			WHERE ud.UserUID = 739

			ORDER BY d.Domain

—TRANSACTION 0, not started, OS thread id 183672 updating table statistics
MySQL thread id 23965, query id 4150554 localhost ::1 root
SHOW TABLE STATUS FROM firma
—TRANSACTION 58278C6BB, not started, OS thread id 14316 returning various info to MySQL
mysql tables in use 1, locked 0
MySQL thread id 23923, query id 4150742 localhost ::1 root statistics
Select Domain from DomainTable Where DomainUID = ‘9416’
—TRANSACTION 58278B0CE, not started, OS thread id 144088
MySQL thread id 17020, query id 4150669 localhost 127.0.0.1 root
—TRANSACTION 58278644C, not started, OS thread id 39192
MySQL thread id 8118, query id 4150894 localhost ::1 root
—TRANSACTION 58278C704, ACTIVE 20 sec, OS thread id 84312 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s)
MySQL thread id 24032, query id 4150857 localhost ::1 root update
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '', 0, '', 'visit', 0)

—TRANSACTION 58278C703, ACTIVE 20 sec, OS thread id 184808 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
MySQL thread id 24042, query id 4150899 localhost ::1 root update
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '', 0, '', 'visit', 0)

—TRANSACTION 58278C702, ACTIVE 20 sec, OS thread id 91896 estimating records in index range
mysql tables in use 3, locked 0
MySQL thread id 24022, query id 4150835 localhost ::1 root statistics
SELECT trefcode.area_code as ref_area_code,turlcode.area_code as url_area_code,turltitle.title as url_title,treftitle.title as ref_title,turldom.domain as url_dom,turlpath.path as url_path,trefdom.domain as ref_dom,trefpath.path as ref_path,entrance,params,untouched FROM visitor_browser_urls INNER JOIN visitor_data_pages AS turl ON visitor_browser_urls.url=turl.id INNER JOIN visitor_data_pages AS tref ON visitor_browser_urls.referrer=tref.id INNER JOIN visitor_data_domains AS trefdom ON tref.domain=trefdom Trx read view will not see trx with id >= 58278C703, sees < 58278C6EB ---TRANSACTION 58278C701, ACTIVE 20 sec, OS thread id 45764 truncating table mysql tables in use 32, locked 32 MySQL thread id 23911, query id 4150243 localhost ::1 root TRUNCATE pagecrcfinal`
—TRANSACTION 58278C6FD, ACTIVE 20 sec, OS thread id 22664 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s)
MySQL thread id 24006, query id 4150931 localhost ::1 root update
INSERT INTO UserActivityLog (UserUID, IP, ActionUID, Label, Value, Time) VALUES (‘800’, ‘1419124466’, ‘2’, ‘’, ‘0’, ‘0’)
—TRANSACTION 58278C6FA, ACTIVE 20 sec, OS thread id 7376 preparing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
MySQL thread id 24031, query id 4150929 localhost ::1 root query end
INSERT INTO TrackingTable (CookieId, Action) VALUES (87455, ‘id allocation’)
—TRANSACTION 58278C6F6, ACTIVE 160 sec, OS thread id 240236 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s)
MySQL thread id 23966, query id 4150836 localhost ::1 root update
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (87454, '', 0, '', 'visit', 0)

—TRANSACTION 58278C6F5, ACTIVE 160 sec, OS thread id 135260 preparing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
MySQL thread id 24019, query id 4150794 localhost ::1 root query end
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '[URL]http://www.seo4wp.de/seo-extensions-google-chrome/[/URL]', 796, '', 'visit', 0)

—TRANSACTION 58278C6F4, ACTIVE 160 sec, OS thread id 180060 preparing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
MySQL thread id 24027, query id 4150824 localhost ::1 root query end
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '[URL="http://www.maxiklicks.de/crons/ziel.php?uid=16&bid=mLRP9wzQgkKF01QMbflH25F33kr3RZh4&sid=122&v1=e48c16da7c35c8eb69d442081390f956&var1=e48c16da7c35c8eb69d442081390f956"] http://www.maxiklicks.de/crons/ziel.php?uid=16&bid=mLRP9 wzQgkKF01QMbflH25F33kr3RZh4&sid=122&v1=e48c16da7c35c 8eb69d442081390f956&var1=e48c16da7c35c8eb69d442081390f95 6[/URL]', 0, '', 'visit', 0)

—TRANSACTION 58278C6F3, ACTIVE 160 sec, OS thread id 133740 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s)
MySQL thread id 24025, query id 4150815 localhost ::1 root update
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '', 0, '', 'visit', 0)

—TRANSACTION 58278C6F2, ACTIVE (PREPARED) 160 sec, OS thread id 211668 committing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
MySQL thread id 24014, query id 4150769 localhost ::1 root query end
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '', 0, '', 'visit', 0)

—TRANSACTION 58278C6EB, ACTIVE 242 sec, OS thread id 60552 preparing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
MySQL thread id 24010, query id 4150760 localhost ::1 root query end
INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

				VALUES (1, '', 0, '', 'visit', 0)

FILE I/O

I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: wait Windows aio (read thread)
I/O thread 6 state: wait Windows aio (read thread)
I/O thread 7 state: wait Windows aio (read thread)
I/O thread 8 state: wait Windows aio (read thread)
I/O thread 9 state: wait Windows aio (read thread)
I/O thread 10 state: wait Windows aio (read thread)
I/O thread 11 state: wait Windows aio (read thread)
I/O thread 12 state: wait Windows aio (read thread)
I/O thread 13 state: wait Windows aio (read thread)
I/O thread 14 state: wait Windows aio (read thread)
I/O thread 15 state: wait Windows aio (read thread)
I/O thread 16 state: wait Windows aio (read thread)
I/O thread 17 state: wait Windows aio (read thread)
I/O thread 18 state: wait Windows aio (write thread)
I/O thread 19 state: wait Windows aio (write thread)
I/O thread 20 state: wait Windows aio (write thread)
I/O thread 21 state: wait Windows aio (write thread)
I/O thread 22 state: wait Windows aio (write thread)
I/O thread 23 state: wait Windows aio (write thread)
I/O thread 24 state: wait Windows aio (write thread)
I/O thread 25 state: wait Windows aio (write thread)
I/O thread 26 state: wait Windows aio (write thread)
I/O thread 27 state: wait Windows aio (write thread)
I/O thread 28 state: wait Windows aio (write thread)
I/O thread 29 state: wait Windows aio (write thread)
I/O thread 30 state: wait Windows aio (write thread)
I/O thread 31 state: wait Windows aio (write thread)
I/O thread 32 state: wait Windows aio (write thread)
I/O thread 33 state: wait Windows aio (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 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
9036633 OS file reads, 1019489 OS file writes, 95688 OS fsyncs
0.23 reads/s, 16384 avg bytes/read, 0.13 writes/s, 0.13 fsyncs/s

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 100973, seg size 100975, 120916 merges
merged operations:
insert 1124658, delete mark 230351, delete 217314
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 144498583, node heap has 264947 buffer(s)
3.60 hash searches/s, 1.50 non-hash searches/s

LOG

Log sequence number 8870605216748
Log flushed up to 8870605211717
Last checkpoint at 8870605178275
0 pending log writes, 0 pending chkp writes
28023 log i/o’s done, 0.03 log i/o’s/second

BUFFER POOL AND MEMORY

Total memory allocated 74725720064; in additional pool allocated 0
Dictionary memory allocated 998876
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
–Thread 14316 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0000000140758C08 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
a writer (thread id 183672) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
Last time write locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
–Thread 14316 has waited at …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 303.00 seconds the semaphore:
S-lock on RW-latch at 0000000140758C08 created in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
a writer (thread id 183672) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
Last time write locked in file …....\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
Buffer pool size 4456448
Free buffers 193103
Database pages 7113405
Old database pages 2625866
Modified db pages 86
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 13765440, not young 0
0.13 youngs/s, 0.00 non-youngs/s
Pages read 9033196, created 650087, written 947081
0.09 reads/s, 0.04 creates/s, 0.00 writes/s
Buffer pool hit rate 995 / 1000, young-making rate 8 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 7113405, unzip_LRU len: 1703840
I/O sum[8]:cur[0], unzip sum[0]:cur[0]

ROW OPERATIONS

3 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Main thread id 215236, state: flushing log
Number of rows inserted 116357061, updated 777213, deleted 524, read 13818160521
0.23 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3.93 reads/s

END OF INNODB MONITOR OUTPUT

Topic		Replies	Views
Mutex issues in 4.1.20? Other MySQL® Questions	1	348	March 7, 2007
Deadlocks on InnoDB tables Other MySQL® Questions	0	391	February 21, 2008
Innodb Mutex Error?? Other MySQL® Questions	2	713	February 4, 2015
Xtradb 5.5.34 cluster is hung with semaphores for 30 mins Percona XtraDB Cluster 5.x	1	687	June 2, 2014
all mysql query thread ACTIVE waiting in InnoDB queue ,how to resulte it !!! Other MySQL® Questions	2	932	November 26, 2018

Innodb Threads Settings

Some semaphores innodb monitor outputs: 20 seconds:

SEMAPHORES

SEMAPHORES

This is a full innodb monitor output:

110314 13:25:32 INNODB MONITOR OUTPUT

Per second averages calculated from the last 20 seconds

BACKGROUND THREAD

srv_master_thread loops: 11373 1_second, 11372 sleeps, 1124 10_second, 405 background, 405 flush srv_master_thread log flush and writes: 11464

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 1508316, signal count 1925586 Mutex spin waits 64229942, rounds 98364059, OS waits 1458040 RW-shared spins 313502, rounds 1310927, OS waits 25321 RW-excl spins 32136, rounds 1545701, OS waits 20355 Spin rounds per wait: 1.53 mutex, 4.18 RW-shared, 48.10 RW-excl

TRANSACTIONS

WHERE Saved = 99 Limit 20300000, 100000 )

FILE I/O

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 261426, seg size 261428, 13571 merges merged operations: insert 83277, delete mark 459921, delete 58180 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 144498583, node heap has 83577 buffer(s) 94999.75 hash searches/s, 1993.50 non-hash searches/s

LOG

Log sequence number 9836204638037 Log flushed up to 9836204595512 Last checkpoint at 9835970245764 0 pending log writes, 0 pending chkp writes 11324 log i/o’s done, 1.10 log i/o’s/second

BUFFER POOL AND MEMORY

ROW OPERATIONS

2 queries inside InnoDB, 0 queries in queue 1 read views open inside InnoDB Main thread id 140360, state: sleeping Number of rows inserted 2259224, updated 1561336, deleted 1190, read 2729194687 65.40 inserts/s, 10.85 updates/s, 0.00 deletes/s, 96350.43 reads/s

END OF INNODB MONITOR OUTPUT

===================================== 110309 12:02:06 INNODB MONITOR OUTPUT

Per second averages calculated from the last 30 seconds

BACKGROUND THREAD

srv_master_thread loops: 17925 1_second, 17921 sleeps, 1701 10_second, 5612 background, 5606 flush srv_master_thread log flush and writes: 18214

SEMAPHORES

TRANSACTIONS

FILE I/O

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 100973, seg size 100975, 120916 merges merged operations: insert 1124658, delete mark 230351, delete 217314 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 144498583, node heap has 264947 buffer(s) 3.60 hash searches/s, 1.50 non-hash searches/s

LOG

Log sequence number 8870605216748 Log flushed up to 8870605211717 Last checkpoint at 8870605178275 0 pending log writes, 0 pending chkp writes 28023 log i/o’s done, 0.03 log i/o’s/second

BUFFER POOL AND MEMORY

ROW OPERATIONS

3 queries inside InnoDB, 0 queries in queue 2 read views open inside InnoDB Main thread id 215236, state: flushing log Number of rows inserted 116357061, updated 777213, deleted 524, read 13818160521 0.23 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3.93 reads/s

END OF INNODB MONITOR OUTPUT

Related topics

Some semaphores innodb monitor outputs:
20 seconds:

srv_master_thread loops: 11373 1_second, 11372 sleeps, 1124 10_second, 405 background, 405 flush
srv_master_thread log flush and writes: 11464

OS WAIT ARRAY INFO: reservation count 1508316, signal count 1925586
Mutex spin waits 64229942, rounds 98364059, OS waits 1458040
RW-shared spins 313502, rounds 1310927, OS waits 25321
RW-excl spins 32136, rounds 1545701, OS waits 20355
Spin rounds per wait: 1.53 mutex, 4.18 RW-shared, 48.10 RW-excl

Ibuf: size 1, free list len 261426, seg size 261428, 13571 merges
merged operations:
insert 83277, delete mark 459921, delete 58180
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 144498583, node heap has 83577 buffer(s)
94999.75 hash searches/s, 1993.50 non-hash searches/s

Log sequence number 9836204638037
Log flushed up to 9836204595512
Last checkpoint at 9835970245764
0 pending log writes, 0 pending chkp writes
11324 log i/o’s done, 1.10 log i/o’s/second

2 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 140360, state: sleeping
Number of rows inserted 2259224, updated 1561336, deleted 1190, read 2729194687
65.40 inserts/s, 10.85 updates/s, 0.00 deletes/s, 96350.43 reads/s

=====================================
110309 12:02:06 INNODB MONITOR OUTPUT

srv_master_thread loops: 17925 1_second, 17921 sleeps, 1701 10_second, 5612 background, 5606 flush
srv_master_thread log flush and writes: 18214

Ibuf: size 1, free list len 100973, seg size 100975, 120916 merges
merged operations:
insert 1124658, delete mark 230351, delete 217314
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 144498583, node heap has 264947 buffer(s)
3.60 hash searches/s, 1.50 non-hash searches/s

Log sequence number 8870605216748
Log flushed up to 8870605211717
Last checkpoint at 8870605178275
0 pending log writes, 0 pending chkp writes
28023 log i/o’s done, 0.03 log i/o’s/second

3 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Main thread id 215236, state: flushing log
Number of rows inserted 116357061, updated 777213, deleted 524, read 13818160521
0.23 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3.93 reads/s