Bug #31275 slow querries
Submitted: 28 Sep 2007 10:13 Modified: 28 Sep 2007 10:49
Reporter: Edwin Deutschl Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.0.21 OS:Windows (XP, SP2)
Assigned to: CPU Architecture:Any

[28 Sep 2007 10:13] Edwin Deutschl
Description:
All our querries require usually less than 2sec.
But about once per day, the databsae seems to slow down.
Querries need a few minutes.

 
The .err file shows the following report:
070927 13:17:50 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 72 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 855890, signal count 855356
--Thread 3524 has waited at .\btr\btr0cur.c line 424 for 255.00 seconds the semaphore:
X-lock on RW-latch at 167EA300 created in file .\buf\buf0buf.c line 490
a writer (thread id 3524) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1
Last time read locked in file .\buf\buf0flu.c line 576
Last time write locked in file .\btr\btr0cur.c line 424
--Thread 4012 has waited at .\buf\buf0flu.c line 402 for 162.00 seconds the semaphore:
Mutex at 01390880 created file .\trx\trx0sys.c line 104, lock var 1
waiters flag 1
--Thread 3180 has waited at .\fsp\fsp0fsp.c line 2732 for 141.00 seconds the semaphore:
X-lock on RW-latch at 01371EC8 created in file .\fil\fil0fil.c line 1051
a writer (thread id 4012) has reserved it in mode  exclusive
number of readers 0, waiters flag 1
Last time read locked in file not yet reserved line 0
Last time write locked in file .\fsp\fsp0fsp.c line 2580
Mutex spin waits 139189, rounds 873744, OS waits 22307
RW-shared spins 1649907, OS waits 823952; RW-excl spins 7512, OS waits 2979
------------
TRANSACTIONS
------------
Trx id counter 0 17158844
Purge done for trx's n:o < 0 17158684 undo n:o < 0 0
History list length 105
Total number of lock structs in row lock hash table 2
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 17158563, not started, OS thread id 3520
MySQL thread id 19, query id 437070 rscvsp1 150.1.43.135 root
---TRANSACTION 0 17158686, not started, OS thread id 3516
MySQL thread id 6, query id 437571 rscvsv1 150.1.43.137 root
---TRANSACTION 0 17158843, ACTIVE 141 sec, OS thread id 3180 updating or deleting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
2 lock struct(s), heap size 320
MySQL thread id 2, query id 437430 rscvss 150.1.43.103 root Updating
UPDATE TProducts SET nLightBarrierConfigId = 10, strLightBarrierSignalLines = 'Vector[5,(100,50780,117448,171178,240000)]' WHERE nProductId = 11174
---TRANSACTION 0 17158839, ACTIVE 164 sec, OS thread id 4012 updating or deleting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
2 lock struct(s), heap size 320, undo log entries 1
MySQL thread id 21, query id 437403 rscvsp2 150.1.43.136 root Updating
UPDATE TAcqData SET nProductId = 11174, nFrameNr = 41, blobImage = 'ÿØÿà\0JFIF\0\0\0\0\0\0ÿþ\0-Intel(R) JPEG Library, version [2.0.18.50]\0ÿÛ\0C\0		\n	\nÿÛ\0CÿÄ\0Ò\0\0\0\0\0\0\0\0\0\0	\n\0\0\0}\0!1AQa\"q2‘¡#B±ÁRÑð$3br‚	\n\Z%&\'()*456789:CDEFGHIJSTUVWXYZcdefghijstuvwxyzƒ„…†‡ˆ‰Š’“”•–—˜™š¢£¤¥¦§¨©ª²³´µ¶·¸¹ºÂÃÄÅÆÇÈÉÊÒÓÔÕÖ×ØÙÚáâãäåæçèéêñòóôõö÷øùúÿÀ\0\0ð\0\0ÿÚ\0\0\0\0?\0„nZ5’[#üõæ˜dùR12£œœ¹\'×?â*Á`ûÍ$dgh=Á•<v˜ˆ
---TRANSACTION 0 17158700, ACTIVE 255 sec, OS thread id 3524 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
2 lock struct(s), heap size 320
MySQL thread id 20, query id 437239 rscvsp1 150.1.43.135 root update
INSERT INTO TDirisObjects (nProductId, nXPosMm, nYPosMm, nXSizeMm, nYSizeMm, nClassCode, nGradingType, blobFeaVect) VALUES (11174, 1656, 16288, 56, 208, 1, 1, '\0\0\0\0\0\0\0\0\0\0\0\0\0à©@\0\0\0\0\0Ðß@\0\0\0\0\0\0\\@\0\0\0\0\0\0z@\0\0\0\0\0@P@\0\0\0\0\0\0\0\0\0\0\0\0\0€L@\0\0\0\0\0€]@\0\0\0\0\0 i@\0\0\0\0\0ÀV@Z Z @\0\0\0\0\0€r@´n0E>[J@‚#óø?\0\0\0\0\0ÀW@–^ÂÐ@öó?\0\0\0\0\0\0\0\0\0\0\0\0\0\0@Ý&›l²	\'@\0\0\0\0\0\0\0\0\0\0\0\0\0\0 @‘?\0\0\0\0\0\0\0\0'),(11174, 1208, 16320, 48, 80, 1, 1, '\0\0\0\0\0\0\0\0\0\0\0\0\0à¢@\0\0\0\0\0àß@\0\0\0\0\0\0X@\0\0\0\0\0\0d@\0\0\0\0\0\01@\0\0\0\0\0\0\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 (write thread)
Pending normal aio reads: 0, aio writes: 1,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
4936136 OS file reads, 4604293 OS file writes, 294350 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 1, free list len 0, seg size 2, is empty
Ibuf for space 0: size 1, free list len 0, seg size 2,
248 inserts, 248 merged recs, 248 merges
Hash table size 1407101, used cells 196, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 441 2130432504
Log flushed up to   441 2128143215
Last checkpoint at  441 1953030342
0 pending log writes, 0 pending chkp writes
198041 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 394534352; in additional pool allocated 393472
Buffer pool size   21696
Free buffers       0
Database pages     21695
Modified db pages  10889
Pending reads 0
Pending writes: LRU 2, flush list 7, single page 0
Pages read 4936125, created 269651, written 4324096
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
3 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 1012, state: flushing buffer pool pages
Number of rows inserted 56978, updated 106836, deleted 0, read 5619220
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 3524 has waited at .\btr\btr0cur.c line 424 for 273.00 seconds the semaphore:
X-lock on RW-latch at 167EA300 created in file .\buf\buf0buf.c line 490
a writer (thread id 3524) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1
Last time read locked in file .\buf\buf0flu.c line 576
Last time write locked in file .\btr\btr0cur.c line 424
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

How to repeat:
Don't know. It happens about once per day.
[28 Sep 2007 10:49] Hartmut Holzgraefe
We're sorry, but the bug system is not the appropriate forum for asking help on using MySQL products. Your problem is not the result of a bug.

Support on using our products is available both free in our forums at http://forums.mysql.com/ and for a reasonable fee direct from our skilled support engineers at http://www.mysql.com/support/

Thank you for your interest in MySQL.