very simple query but slow . "microslow" patches.

I using percona debian builds with long_query_time = 0.5
and see strange slow_log. Please explain me WHY this simple query so slow ?
data in b_stat_searcher_day and b_stat_session exactly 1 row of data.
I have big enough ibdata and iblog files, big innodb pools.
Turning off query_cache not help me.
this queries does not read much data and does not wait for locks.
here is slow log :

Time: 090328 13:50:12# User@Host: user[user] @ localhost []# Thread_id: 760 Schema: innodb# Query_time: 0.898621 Lock_time: 0.000039 Rows_sent: 0 Rows_examined: 0 Rows_affected: 1 Rows_read: 2# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No# Filesort: No Filesort_on_disk: No Merge_passes: 0# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000# InnoDB_pages_distinct: 4use innodb;SET timestamp=1238237412;UPDATE b_stat_searcher_day SET DATE_LAST = now(), TOTAL_HITS = TOTAL_HITS + 1 WHERE SEARCHER_ID=‘12’ and DATE_STAT = CURRENT_DATE;# Time: 090328 15:05:12# User@Host: user[user] @ localhost []# Thread_id: 1255 Schema: innodb# Query_time: 0.697079 Lock_time: 0.000046 Rows_sent: 0 Rows_examined: 0 Rows_affected: 1 Rows_read: 2# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No# Filesort: No Filesort_on_disk: No Merge_passes: 0# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000# InnoDB_pages_distinct: 4SET timestamp=1238241912;UPDATE b_stat_searcher_day SET DATE_LAST = now(), TOTAL_HITS = TOTAL_HITS + 1 WHERE SEARCHER_ID=‘48’ and DATE_STAT = CURRENT_DATE;# Time: 090328 15:20:10# User@Host: user[user] @ localhost []# Thread_id: 1444 Schema: innodb# Query_time: 0.973846 Lock_time: 0.000049 Rows_sent: 0 Rows_examined: 0 Rows_affected: 1 Rows_read: 2# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No# Filesort: No Filesort_on_disk: No Merge_passes: 0# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000# InnoDB_pages_distinct: 4SET timestamp=1238242810;UPDATE b_stat_session SET USER_ID = ‘’, USER_AUTH = ‘N’, USER_AGENT = ‘Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)’, DATE_LAST = now(), IP_LAST = ‘3.4.5.4’, IP_LAST_NUMBER = 3588942786 WHERE ID=‘5660’

this is data between 13:50 and 15:20 and there are no other high load tasks, no disk load.
top output also not busy :

top - 23:37:17 up 3 days, 22:31, 2 users, load average: 0.11, 0.36, 0.38Tasks: 111 total, 2 running, 109 sleeping, 0 stopped, 0 zombieCpu(s): 1.7%us, 0.4%sy, 0.0%ni, 94.2%id, 3.6%wa, 0.0%hi, 0.0%si, 0.0%stMem: 4056376k total, 3980464k used, 75912k free, 341544k buffersSwap: 999992k total, 108k used, 999884k free, 2537844k cached

MySQL 5.0.77-b13-log uptime 0 10:55:56 Sat Mar 28 23:38:05 2009__ Key _______________________________________________________________Buffer used 1.87M of 300.00M %Used: 0.62 Current 54.21M %Usage: 18.07Write hit 99.61%Read hit 98.76% Questions _______________________________________________________Total 6.37M 161.8/s DMS 6.19M 157.3/s %Total: 97.22 QC Hits 141.78k 3.6/s 2.23 Com 25.98k 0.7/s 0.41 COM_QUIT 10.26k 0.3/s 0.16 -Unknown 877 0.0/s 0.01Slow 500 ms 118 0.0/s 0.00 %DMS: 0.00 Log: ONDMS 6.19M 157.3/s 97.22 SELECT 6.16M 156.6/s 96.78 99.55 UPDATE 17.64k 0.4/s 0.28 0.28 INSERT 9.96k 0.3/s 0.16 0.16 DELETE 131 0.0/s 0.00 0.00 REPLACE 123 0.0/s 0.00 0.00Com 25.98k 0.7/s 0.41 change_db 9.74k 0.2/s 0.15 set_option 7.07k 0.2/s 0.11 show_fields 4.98k 0.1/s 0.08 SELECT and Sort ___________________________________________________Scan 9.58k 0.2/s %SELECT: 0.16Range 705 0.0/s 0.01Full join 26 0.0/s 0.00Range check 0 0/s 0.00Full rng join 0 0/s 0.00Sort scan 676.83k 17.2/sSort range 22.10k 0.6/sSort mrg pass 0 0/s Query Cache _______________________________________________________Memory usage 57.59M of 64.00M %Used: 89.99Block Fragmnt 8.69%Hits 141.78k 3.6/sInserts 5.78M 146.9/sInsrt:Prune 1.01:1 0.7/sHit:Insert 0.02:1 Table Locks _______________________________________________________Waited 0 0/s %Total: 0.00Immediate 24.68M 627.0/s Tables ____________________________________________________________Open 874 of 2000 %Cache: 43.70Opened 1.24k 0.0/s Connections _______________________________________________________Max used 5 of 100 %Max: 5.00Total 10.26k 0.3/s Created Temp ______________________________________________________Disk table 676.58k 17.2/sTable 682.12k 17.3/s Size: 64.0MFile 5 0.0/s Threads ___________________________________________________________Running 1 of 1Cached 4 of 8 %Hit: 99.95Created 5 0.0/sSlow 0 0/s Aborted ___________________________________________________________Clients 4 0.0/sConnects 319 0.0/s Bytes _____________________________________________________________Sent 15.02G 381.6k/sReceived 3.24G 82.3k/s InnoDB Buffer Pool ________________________________________________Usage 221.12M of 400.00M %Used: 55.28Read hit 100.00%Pages Free 11.45k %Total: 44.72 Data 13.23k 51.70 %Drty: 0.06 Misc 918 3.59 Latched 0.00Reads 304.82M 7.7k/s From file 5.22k 0.1/s 0.00 Ahead Rnd 8 0.0/s Ahead Sql 139 0.0/sWrites 234.77k 6.0/sFlushes 21.68k 0.6/sWait Free 0 0/s InnoDB Lock _______________________________________________________Waits 0 0/sCurrent 0Time acquiring Total 0 ms Average 0 ms Max 0 ms InnoDB Data, Pages, Rows ____________________________________________Data Reads 5.64k 0.1/s Writes 53.64k 1.4/s fsync 36.98k 0.9/s Pending Reads 0 Writes 0 fsync 0Pages Created 278 0.0/s Read 12.96k 0.3/s Written 21.68k 0.6/sRows Deleted 280 0.0/s Inserted 34.66k 0.9/s Read 134.37M 3.4k/s Updated 16.68k 0.4/s

show innodb status

090328 23:41:51 INNODB MONITOR OUTPUT=====================================Per second averages calculated from the last 16 seconds----------BACKGROUND THREAD----------fsync callers: 4328 buffer pool, 0 other, 0 checkpoint, 1501 log aio, 31756 log sync, 0 archive----------SEMAPHORES----------OS WAIT ARRAY INFO: reservation count 13342, signal count 13280Mutex spin waits 0, rounds 278112, OS waits 1313RW-shared spins 23547, OS waits 1793; RW-excl spins 57540, OS waits 10095--------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: 0Pending flushes (fsync) log: 0; buffer pool: 05642 OS file reads, 54399 OS file writes, 37540 OS fsyncs0.00 reads/s, 0 avg bytes/read, 2.75 writes/s, 2.12 fsyncs/s-------------------------------------INSERT BUFFER AND ADAPTIVE HASH INDEX-------------------------------------Ibuf: size 1, free list len 0, seg size 2,14 inserts, 14 merged recs, 13 mergesHash table size 830173, used cells 438043, node heap has 918 buffer(s)6905.57 hash searches/s, 280.61 non-hash searches/s—LOG—Log sequence number 0 627106811Log flushed up to 0 627106811Last checkpoint at 0 627101630Max checkpoint age 66764760Modified age 5181Checkpoint age 51810 pending log writes, 0 pending chkp writes33262 log i/o’s done, 1.94 log i/o’s/second, 31756 syncs, 2538 checkpointslog sync callers: 21936 buffer pool, background 34831 sync and 0 async, 0 internal, checkpoint 2538 sync and 0 async, 0 archive, commit 27148 sync and 0 asynclog sync syncers: 466 buffer pool, background 4209 sync and 0 async, 0 internal, checkpoint 1 sync and 0 async, 0 archive, commit 27080 sync and 0 async----------------------BUFFER POOL AND MEMORY----------------------Total memory allocated 534450146; in additional pool allocated 18878976Internal hash tables (constant factor + variable factor) Adaptive hash index 21686104 (6641384 + 15044720) Page hash 415928 Dictionary cache 8918832 (4983000 + 3935832) File system 83808 (82672 + 1136) Lock system 1156680 (1156312 + 368) Recovery system 0 (0 + 0) Threads 83016 (82696 + 320) innodb_io_pattern 0 (0 + 0)Buffer pool size 25600Buffer pool size, bytes 419430400Free buffers 11446Database pages 13236Modified db pages 16Pending reads 0Pending writes: LRU 0, flush list 0, single page 0Pages read 12957, created 279, written 219360.00 reads/s, 0.00 creates/s, 0.69 writes/sBuffer pool hit rate 1000 / 1000--------------ROW OPERATIONS--------------0 queries inside InnoDB, 0 queries in queue1 read views open inside InnoDBMain thread process no. 30573, id 1082419536, state: sleepingNumber of rows inserted 34870, updated 16947, deleted 280, read 1368862680.94 inserts/s, 0.87 updates/s, 0.00 deletes/s, 6597.78 reads/s------------TRANSACTIONS------------Trx id counter 0 6209093Purge done for trx’s n:o < 0 6208974 undo n:o < 0 0History list length 57Total number of lock structs in row lock hash table 0LIST OF TRANSACTIONS FOR EACH SESSION:—TRANSACTION 0 0, not started, process no 30573, OS thread id 1102629200MySQL thread id 10367, query id 6374720 localhost debian-sys-maintshow innodb status

What does show? You might have to install the sysstat package.

That will give a true indication of your disk activity. Keep in mind that a 7200 RPM disk is limited to about 167 transactions per second. As the transactions per second approach the limit of the disk, the latency will shoot up. Using RAID allows you to increase this limit.

It’s possible that activity elsewhere in the system caused a spike of disk activity, which delayed MySQL. I’d check for cron jobs that were running at the time the latency occurred.

Your top output does indicate some disk activity: 3.6% of the time, a runnable thread was waiting on the disk.

If the latency is unacceptable, I’d suggest running keeping your data on separate disk(s) from the rest of the system.

My hardware is LSISAS1068. This is not fast card of course and i know about it.
Now I have a full load

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtnsda 52.00 76.80 806.40 384 4032

I can see what was long time ago when slow queries are logged with atsar -D program ( 2009-03-28 15:20)

00:00:01 partition busy read/s Kbyt/r write/s Kbyt/w avque avserv part…14:50:01 sda (8-0) 3% 0.03 38.2 2.89 11.7 12.80 9.42 ms sda3 0.05 22.2 8.44 4.015:00:01 sda (8-0) 5% 0.04 7.8 4.88 12.1 12.87 9.38 ms sda3 0.04 7.8 14.73 4.015:10:01 sda (8-0) 4% 0.41 44.8 4.23 12.6 15.61 8.55 ms sda3 1.10 16.6 13.30 4.0…

now at full load i have :

23:30:02 sda (8-0) 84% 2.38 9.2 65.92 10.1 7.04 12.34 ms sda2 0.00 0.0 0.75 4.0 sda3 2.91 7.5 165.21 4.023:40:02 sda (8-0) 86% 2.71 10.8 66.39 9.7 7.48 12.37 ms sda3 3.25 9.0 160.67 4.023:50:02 sda (8-0) 88% 3.22 8.3 68.08 9.6 7.68 12.35 ms sda2 0.00 0.0 0.02 4.0 sda3 3.64 7.3 163.16 4.0
this is really big io-load and i consider with you.

But why slow query was before?
I decrease disk io by changing innodb_flush_log_at_trx_commit=0 and seems slow queries go away.

Yes the time span of about 1 second is the same for both 0 and 2.

With 0 a possible MySQL crash will cause you to loose transaction data.
While with 2 it will survive a MySQL crash but you might still loose data in an OS crash.
And with 1 it will survive even an OS crash (hence why it is default).