Skip navigation links

MySQL Forums :: Performance :: Sort_merge_passes increasing at 38 per minute...


Advanced Search

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.

Options: ReplyQuote


Subject Views Written By Posted
Sort_merge_passes increasing at 38 per minute... 1440 phil yune 12/18/2011 09:15AM
Re: Sort_merge_passes increasing at 38 per minute... 460 Jørgen Løland 12/19/2011 06:55AM
Re: Sort_merge_passes increasing at 38 per minute... 527 phil yune 12/19/2011 07:36AM
Re: Sort_merge_passes increasing at 38 per minute... 507 Jørgen Løland 12/20/2011 03:10AM
Re: Sort_merge_passes increasing at 38 per minute... 499 phil yune 12/20/2011 04:07PM
Re: Sort_merge_passes increasing at 38 per minute... 543 Jørgen Løland 12/21/2011 02:58AM
Re: Sort_merge_passes increasing at 38 per minute... 592 phil yune 12/21/2011 07:25PM
Re: Sort_merge_passes increasing at 38 per minute... 451 Jørgen Løland 12/22/2011 02:34AM
Re: Sort_merge_passes increasing at 38 per minute... 706 Rick James 12/22/2011 11:53PM
Re: Sort_merge_passes increasing at 38 per minute... 458 phil yune 12/23/2011 07:14AM
Re: Sort_merge_passes increasing at 38 per minute... 441 Rick James 12/24/2011 08:58AM


Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.