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