Announcement

Announcement Module
Collapse
No announcement yet.

very simple query but slow . "microslow" patches.

Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • 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 < 0 6208974 undo n < 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

  • #2
    What does iostat -d 10 2 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.

    Comment


    • #3
      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.

      Comment


      • #4
        pwlnw wrote on Sat, 04 April 2009 14:08


        I decrease disk io by changing innodb_flush_log_at_trx_commit=0 and seems slow queries go away.



        With innodb_flush_log_at_trx_commit = 1 (default), the query won't return until the changes have been committed to disk. If you set it to 0 or 2, it'll return as soon as it's been added to the write queue -- so you're not guaranteed that the data is written to disk in the case of a crash or power failure. Of course, if you have a battery-backed cache in your RAID card, you should be okay.

        Comment


        • #5
          i need explanation :
          if innodb_flush_log_at_trx_commit=0, can I lose enough old data older than a few minutes if mysqld crushed ? let OS NOT crashed and entire server are not rebooted.

          What period of time is "practically safe" ?

          Comment


          • #6
            Set it to:
            innodb_flush_log_at_trx_commit=2

            The performance difference between 0 and 2 is marginal and you get more safety with 2.

            And you at most loose 1 second of transactions.

            Comment


            • #7
              Don't know why, but perfomance difference are significant. I had two independent case with it.
              If innodb_flush_log_at_trx_commit=0 , I can loose SAME 1 second of transactions or MORE ?

              Comment


              • #8
                The MySQL manual explains the difference between 0 and 2. Basically, 2 will cause loss of unflushed transactions only in case the whole server crashes, and 0 can cause the loss if even mysqld crashes but the server keeps running.

                The slow query log does not show you why the query was slow at that time. But I would begin by logging ALL queries, and looking for an overall drop in throughput around that time. Other queries might also be suffering. See for example, http://www.xaprb.com/blog/2010/05/26/reacting-to-small-varia tions-in-response-time/

                Comment


                • #9
                  I need understand how old transations can be lost ?

                  Comment


                  • #10
                    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).

                    Comment

                    Working...
                    X