Re: Sort_merge_passes increasing at 38 per minute...
Posted by:
phil yune
Date: December 21, 2011 07:25PM
It's looking unlikely that's it's a contention issue, here's what I am able to log (notice that there are no other calls around that time in which the transaction is updating the same auction_id):
The numbers are in seconds.
2011-12-22 06:31:25 BB Auction 5858 Bid took 0.055315017700195
2011-12-22 06:31:29 BB Auction 5852 Bid took 0.042392015457153
2011-12-22 06:31:29 BB Auction 5852 Bid took 0.00056099891662598
2011-12-22 06:31:29 BB Auction 5852 Bid took 0.053886890411377
2011-12-22 06:31:29 BB Auction 5863 Bid took 0.007857084274292
2011-12-22 06:31:34 BB Auction 5863 Bid took 0.00052690505981445
2011-12-22 06:31:34 BB Auction 5865 Bid took 0.012217044830322
2011-12-22 06:31:36 SLOW QUERY | CALL Bid(5865, 0.10,265.60,0, 66014, '00:00:13', @var_return) | 2.2577700614929
2011-12-22 06:31:36 BB Auction 5865 Bid took 2.2881109714508
2011-12-22 06:31:36 Auction 5864 Bid took 0.033728122711182
2011-12-22 06:31:37 Auction 5863 Bid took 0.025584936141968
2011-12-22 06:31:39 Auction 5864 Bid took 0.03214693069458
2011-12-22 06:31:39 Auction 5863 Bid took 0.040162801742554
2011-12-22 06:31:40 BB Auction 5852 Bid took 0.041141986846924
2011-12-22 06:31:40 BB Auction 5852 Bid took 0.00043392181396484
2011-12-22 06:31:40 BB Auction 5852 Bid took 0.0042738914489746
2011-12-22 06:31:40 BB Auction 5858 Bid took 0.014311075210571
2011-12-22 06:31:44 BB Auction 5852 Bid took 0.00057196617126465
2011-12-22 06:31:44 BB Auction 5858 Bid took 0.00067496299743652
2011-12-22 06:31:44 BB Auction 5852 Bid took 0.0011391639709473
2011-12-22 06:31:44 BB Auction 5852 Bid took 0.0010890960693359
BTW, a read in that row will not lock or hurt performance right? I am just logging transactions here, there can be a few more reads at the same time.
Also, below are the outputs from innodb status an hour apart. Nothing stands out as far as I can tell (http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-status-walk-through/).
Thanks!
First snapshot:
=====================================
111222 8:00:47 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 14 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2353131, signal count 2340402
Mutex spin waits 0, rounds 169008878, OS waits 209806
RW-shared spins 4112117, OS waits 1778764; RW-excl spins 1029531, OS waits 72696
------------
TRANSACTIONS
------------
Trx id counter 0 257622248
Purge done for trx's n:o < 0 257622237 undo n:o < 0 0
History list length 10
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 28797, OS thread id 1082882368
MySQL thread id 16575710, query id 457316092 localhost admin
show innodb status
---TRANSACTION 0 257622246, not started, process no 28797, OS thread id 1237817664
MySQL thread id 16575686, query id 457316090 275870-db1.netshopperhk.com 120.136.46.149 netshopper_prod
---TRANSACTION 0 257622247, not started, process no 28797, OS thread id 1230096704
MySQL thread id 16575684, query id 457316091 275870-db1.netshopperhk.com 120.136.46.149 netshopper_prod
---TRANSACTION 0 257622240, not started, process no 28797, OS thread id 1217583424
MySQL thread id 16575678, query id 457316065 275870-db1.netshopperhk.com 120.136.46.149 netshopper_prod
--------
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 (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
293 OS file reads, 15939166 OS file writes, 11689837 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 1.07 writes/s, 0.79 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 138401, used cells 4816, node heap has 8 buffer(s)
5914.58 hash searches/s, 252.55 non-hash searches/s
---
LOG
---
Log sequence number 1 39840810
Log flushed up to 1 39840810
Last checkpoint at 1 39840426
0 pending log writes, 0 pending chkp writes
8114912 log i/o's done, 0.50 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 94956296; in additional pool allocated 8388608
Buffer pool size 4096
Free buffers 3649
Database pages 439
Modified db pages 3
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 331, created 108, written 6606674
0.00 reads/s, 0.00 creates/s, 0.43 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 28797, id 1170725184, state: sleeping
Number of rows inserted 2828, updated 6093531, deleted 1083, read 117795402093
0.00 inserts/s, 0.36 updates/s, 0.00 deletes/s, 5833.23 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
Second snapshot an hour later (numbers don't go up very high)
=====================================
111222 9:00:16 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 59 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2353512, signal count 2340783
Mutex spin waits 0, rounds 169023222, OS waits 209831
RW-shared spins 4112826, OS waits 1779099; RW-excl spins 1029614, OS waits 72698
------------
TRANSACTIONS
------------
Trx id counter 0 257633480
Purge done for trx's n:o < 0 257633464 undo n:o < 0 0
History list length 10
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 28797, OS thread id 1177647424
MySQL thread id 16577730, query id 457363789 localhost admin
show innodb status
---TRANSACTION 0 257633465, not started, process no 28797, OS thread id 1220245824
MySQL thread id 16578100, query id 457363717 275870-db1.netshopperhk.com 120.136.46.149 netshopper_prod
---TRANSACTION 0 257633479, not started, process no 28797, OS thread id 1235953984
MySQL thread id 16578101, query id 457363788 275870-db1.netshopperhk.com 120.136.46.149 netshopper_prod
---TRANSACTION 0 257633477, not started, process no 28797, OS thread id 1181374784
MySQL thread id 16578099, query id 457363783 275870-db1.netshopperhk.com 120.136.46.149 netshopper_prod
--------
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 (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
293 OS file reads, 15942096 OS file writes, 11691957 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.93 writes/s, 0.64 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 138401, used cells 4816, node heap has 8 buffer(s)
6076.12 hash searches/s, 257.69 non-hash searches/s
---
LOG
---
Log sequence number 1 40232390
Log flushed up to 1 40232390
Last checkpoint at 1 40232390
0 pending log writes, 0 pending chkp writes
8116316 log i/o's done, 0.41 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 94956296; in additional pool allocated 8388608
Buffer pool size 4096
Free buffers 3649
Database pages 439
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 331, created 108, written 6607886
0.00 reads/s, 0.00 creates/s, 0.42 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 28797, id 1170725184, state: sleeping
Number of rows inserted 2828, updated 6094547, deleted 1083, read 117817547029
0.00 inserts/s, 0.29 updates/s, 0.00 deletes/s, 6573.21 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
----------------------------------+
1 row in set, 1 warning (0.00 sec)
Edited 2 time(s). Last edit at 12/21/2011 07:36PM by phil yune.