MySQL Troubleshooting
Contents
1. InnoDB Buffer Pool 0 0 18 00 20 00 22 00 00 00 02 00 04 00 06 00 08 00 10 00 12 00 14 00 16 00 B Pool Size Cur 2 5M E Database Pages Cur 2 3M Avg 2 2M Max 2 4M B Free Pages Cur 0 0 Avg 92 7k Max 2 4M B Modified Pages Cur 6 1k Avg 38 2k Max 176 4k InnoDB Checkpoint Age 300 M 200 M 100 M 0 18 00 20 00 22 00 00 00 02 00 04 00 06 00 08 00 10 00 12 00 14 00 16 00 B Uncheckpointed Bytes Cur 3 6M Avg 39 1M Max 243 6M WWW DerCona com InnoDB Row Operations 100 10MM KOPAR RPA EA 100 k M3811390 1801 0 InnoDB 1 0 100 z y f 4 Wa f lt eo dh l PW SJ E 0 JI au Vos in WU A WE kan WIT Nul 4 f ed UT LM InnoDB Buffer Pool Activity 800 600 mnm H 400 i HB I V 3 200 F i EN a AEW oA DM Al PAUMA L L N DAL AS A LA Mon 16 00 Mon 20 00 Tue 00 00 Tue 04 00 Tue 08 00 Tue 12 00 From 2008 05 19 15 29 41 To 2008 05 20 15 29 41 E Pages Created Current 25 89 Average 13 11 Max 60 35 D Pages Read Current 0 00 Average 327 Max 720 61 M Pages Written Current 12 91 Averade 15 87 Max 102 57 MySQL Query Response Time LOY MySQL Query Response Time Microseconds dI 130 130 1 100 07 40 08 00 08 20 08 40 09 00 From 2011 01 15 07 35 14 To 2011 01 15 09 02 01 B Query Time Total 00 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 H Query Time Total O1 Cur 202 3 Avg2. Proving is probably a lot more important than Knowing www percona com 17 What s interesting What s more interesting than drawing the stack is drawing the flow of information between each component of the stack t s important to be able to do this while users execute table7 www percona com 18 Following the flow For a given task measure the breakdown in time Database Server Submit Login Form Check if user exists l Return Results l Update Last Login Date Confirm Render page www percona com 19 Wait what Updating the last_login_date takes a sizeable amount of time For the value that it provides why are we spending so long on that sub task WWW DerCona com 20 My analysis Query is UPDATE users SET last login date NOW WHERE id N Schema is CREATE TABLE users id INT NOT NULL PRIMARY KEY auto increment username CHAR 32 NOT NULL last login date DATETIME UNIQUE username ENGINE MyISAM WWW DerCona com 21 mysql gt show processlist localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhost localhos
3. freeing items Sleep Query Connect Binlog Dump www percona com Filesystem Cache Issue We are seeing query pileups amp high disk IO activity at random times WWW DerCona com 86 Filesystem Cache Issue eConfigure pt stalk with threads_running gt 10 grep Writeback 2011 11 03 09 44 50 meminfo Writeback Writeback Writeback Writeback Writeback Writeback 13620 kB 13752 KB 248 kB 0 kB 0 kB 200 kB www percona com 87 Filesystem Cache Issue After adjusting pt stalk to trigger on filesystem cache writeback behavior triggers happen when binlogs get rotated rw r r 1 root root 91 Nov 2 15 15 2011 11 02 15 15 13 trigger rw r r 1 root root 91 Nov 2 16 17 2011 11 02 16 17 20 trigger rw r r 1 root root 91 Nov 2 17 38 2011 11 02 17 38 22 trigger rw rw 1 mysql mysql 1073742171 Nov 2 15 15 dbl bin 10g 003229 rw rw 1 mysql mysql 1073742976 Nov 2 16 17 dbl bin 10g 003230 rw rw 1 mysql mysql 1073742688 Nov 2 17 38 dbl bin 10g 003231 WWW DerCona com 88 Filesystem Cache Issue binary logs use filesystem cache to buffer writes unless sync_binlog N When a binary log was rotated the filesystem cache flushed the remaining part of binary log filesystem buffers 10 of RAM set vm dirty background ratio 1 Reducing binary log size from 1GB to 50MB resolved the spikes WWW percona com 89 Transaction Locking there is a lot of lock waits b
4. pt diskstats device busy in prg io s qtime stim sda 7 0 23 6 5 6 0 3 sda2 7 0 23 6 5 6 0 3 sdb 47 0 280 0 43 6 1 1 sdbl 47 0 280 0 43 6 1 1 WWW percona com 56 Example Slow DROP TABLE Problem eDatabase stalls when DROP TABLE is performed Known einnodb file per table on but already using XFS ext3 is slow in deleting files http www mysqlperformanceblog com 2009 06 16 slow drop table eCPU bound www percona com 57 eSHOW ENGINE INNODB STATUS SEMAPHORES OS WAIT ARRAY INFO reservation count 99807827 signal count 386610135 Thread 1409755456 has waited at buf0flu c line 1335 for 0 0000 seconds the __ semaphore S lock on RW latch at 0x2aab630da3f8 amp block lock a writer thread id 1846389056 has reserved it in mode exclusive nurber of readers 0 waiters flag 1 lock word fffffffffff00000 Last time read locked in file buf0flu c line 1335 Last time write locked in file btr btrObtr c line 1447 Thread 1462204736 has waited at rowpurge c line 665 for 52 000 seconds the semaphore S lock on RW latch at 0x10999a0 amp dict operation lock a writer thread id 1846389056 has reserved it in mode exclusive number of readers 0 waiters flag 1 lock word 0 Last time read locked in file rowOpurge c line 665 Last time write locked in file row rowOmysql c line 3212 Thread 1516517696 has waited at dictOboot ic line 45 for 52 000 seconds the semaphore at Ox2acael5eld18
5. 168 9m Max 210 3m Min 123 Query Time Total 02 Cur 170 5 Avg 40 9 Max 170 5 Min 18 7 H Query Time Total 03 Cur 175 8 Avg 154 8 Max 220 5 Min 139 1 Query Time Total 04 Cur 159 7 Avg 127 8 Max 186 0 Min 86 2 Query Time Total 05 Cur 38 7 Avg 83 8 Max 248 1 Min 37 1 Query Time Total 06 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 H Query Time Total 07 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 E Query Time TotalO8 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 H Query Time Total 09 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 H Query Time Total 10 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 www percona com MySQL Query Response Time MySQL Query Time Histogram Count J10YY H3I130 IJOL 1OC 0 05 40 06 00 06 20 06 40 07 00 07 20 07 40 08 00 08 20 08 40 09 00 09 20 Fr m 34 32 IO 201 DS H Query Time Count 00 Cur 16 7m Avg 12 7m Max 26 5m Min 88 9 H Query Time Count 01 Cur 20 0m Avg 22 3m Max 29 9m Min 16 6 H Query Time Count 02 Cur 861 3m Avg 15 Max 7 9 Min 547 3m H Query Time Count 03 Cur 466 6m 804 0m Max 7 7 Min 413 7 Query Time Count 04 Cur 267m Avg 111 2 m Max 1 8 Min 20 1m H Query Time Count 05 Cur 3 3m Avg 14 0m Max 221 9m Min 0 0 H Query Time Count 06 Cur 0 0 Avg 277 8u Max 6 6m Min 0 0 Bl Query Time Count 07 Cur 0 0 Avg 138 9u Max 3 3m Min 0 0 H Query Time Count 08 Cur 0 0 Avg 0 0 Max 0 0 Min 0 0 E Query Time Count 09 Cur 0 0 Avg 0 0
6. 255341 UPDATE users SET last login date NOW WHERE id 25397 UPDATE users SET last login date NOW WHERE id 1223432 UPDATE users SET last log W in date NOW WHERE AKON AUE APERI id 1001712 uptime 15 00 up 11 days 16 58 5 users load averages 0 88 0 61 0 44 www percona com 23 5 uptime 15 00 up 11 days 16 58 5 users load averages 0 88 0 61 0 44 mysql show global status like slow queriess a ee eer A ce eee Variable name Value Slow queries 3 2 T T 1 row in set 0 00 sec WWW percona com Guessing Is misleading Some problems come without load You cant accurately look at utilization rates to be able to tell where the problem is WWW percona com 25 Guessing edon t just trust your guess try to prove it ParSCORE T CT 2N iA TEST FORM 272 a s DIRECTIONS lt _ r gt gt lt There were two possible answer choices A True a 0 and B False You chose C for all 100 questions in te wU E P i le s r Related Concepts Load Utilization how much work is how much of a relationship incoming or how system s resources GA big is the backlog are used and R i l Capacity Throughput Concurrency how big can X go X how many how
7. search engine FROM tablel9 WHERE user agent Mozilla 4 0 compatible MSIE 7 0 Windows NT 5 1 CLR 1 0 3705 NG www percona com 71 pt query digest Item 1 3 41 QPS 0 97x concurrency ID OxABCE5AD2A2DD1BA1 at byte 288124661 This item is included in the report because it matches limit Scores Apdex 0 97 1 0 V M 19 02 Query time sparkline Time range 2011 04 05 16 12 13 to 16 14 45 A Attribute pet total min max avg 95 stddev median ee Count 0 519 Exec time 2 148s llus 33s 285ms 53ms 2s 26us Lock time 0 5ms 334us 9us 66us 32us 0 Rows sent 0 41 0 1 0 08 0 99 0 27 0 Rows examine 1 4 97M O 445 49k 9 80k 5 73k 49 33k 0 Rows affecte 0 2 0 1 0 00 0 0 06 0 Rows read 1 2 01M O 250 47k 3 96k 1 96 27 94k 0 99 Bytes sent O 241 20k 11 8 01k 475 89 918 49 689 98 258 32 Merge passes 0 0 0 0 0 0 0 0 0 Tmp tables 15 0 1 0 03 0 0 17 0 pt query digest Imp tbl size O 4 78k O 4 78k 9 43 O 211 60 0 Query size O 100 95k 19 2 71k 199 17 363 48 206 60 151 03 InnoDB r bytes 0 0 0 0 0 0 0 0 r ops 0 0 0 0 0 0 0 0 r wait 0 0 0 0 0 0 0 0 pages distin 1 67 99k O 10 64k 1 26k 3 88k 2 47k 31 70 queue wait 0 0 0 0 0 0 0 0 rec lock wai 0 0 0 0 0 0 0 0 Boolean Filesort yes 995 no Full scan 7 yes 92 no OC Hit 78 yes 21 no Tmp table 2 yes 97 no Tmp table on 0 yes 99 no www percona com Resolv
8. UPDATE users SET last login date NOW WHERE id 141037 UPDATE users SET last login date NOW WHERE id 1418038 UPDATE users SET last login date NOW WHERE id 1156819 UPDATE users SET last login date NOW WHERE id 165878 UPDATE users SET last login date NOW WHERE id 1345988 UPDATE users SET last login date NOW WHERE id 1783549 UPDATE users SET last login date NOW WHERE id 665358 UPDATE users SET last login date NOW WHERE id 168566 UPDATE users SET last login date NOW WHERE id 1531867 UPDATE users SET last login date NOW WHERE id 931161 UPDATE users SET last login date NOW WHERE id 342250 UPDATE users SET last login date NOW WHERE id 437672 UPDATE users SET last login date NOW WHERE id 976963 UPDATE users SET last login date NOW WHERE id 615735 UPDATE users SET last login date NOW WHERE id 1152889 UPDATE users SET last login date NOW WHERE id 1748237 UPDATE users SET last login date NOW WHERE id 652162 UPDATE users SET last login date NOW WHERE id 1067106 UPDATE users SET last login date NOW WHERE id 1920992 UPDATE users SET last login date NOW WHERE id 1698141 UPDATE users SET last login date NOW WHERE id 1649822 UPDATE users SET last login date NOW WHERE id 94358 UPDATE users SET last login date NOW WHERE id 983337 UPDATE users SET last login date NOW WHERE id 1091145 UPDATE users SET last login date NOW WHERE id
9. amp dict sys mutex lock var 1 walters flag 1 Thread 1976047936 has waited at dictOboot ic line 45 for 51 000 seconds the semaphore at Ox2acael5eld18 amp dict sys mutex lock var 1 walters flag 1 Thread 1614227776 has waited at dictOboot ic line 45 for 51 000 seconds the WWW percona com Slow DROP TABLE Massive contention on an InnoDB dictionary mutex Whats going on www percona com 59 Slow DROP TABLE pt pmp gdb stacktraces count what threads are doing http poormansprofiler org pt pmp 66 5 aio simulated handle fil aio wait io handler 4 do command handle one connection 1 select os thread sleep srv purge thread start thread clone 1 select handle connections sockets main 1 my net read cli safe read read event handle slave io 1 do sigwait Sigwait signal hand start thread clone 1 buf LRU invalidate tablespace fil delete tablespace row drop table for mysql ha innobase delete table ha delete table mysql rm table part2 mysql rm table mysql execute comma nd mysql parse Query log event do apply event apply event ap ply event and update pos exec relay log event handle slave sq l start thread clone WWW DerCona com 60 Slow DROP TABLE can show use where cpu time has been 157537 spent 56 0725 no vmlinux no vmlinux no vmlinux 11834143 42 1213 mysqld mysqld buf LRU invalidate tablespace 168823 0 6009 mysql mysql completion hash update 53667 0 1
10. many table without making table7 canbe done can we do at other things per unit of time once unacceptable www percona com 27 What 15 important R Time Task X Task Time Throughput Performance s the relationship between throughput utilization response time and capacity Queuing may occur R is the combination of service time and wait time www percona com 28 Measuring Errorlog GLOBAL STATUS ENGINE INNODB STATUS OS metrics memory cpu Measure Performance Response time In application webserver WWW DerCona com 29 Example kk ck ckockckockckckckckckckckckckckckckckck ck ck k kk b row k k k k k kkk kk kk k k k k k k k k x x ip 91 148 82 211 server ip web08 boardreader com page boardreader com s nba29k html f 47977 amp extended search 1 utime 0 129981 wtime 0 242401 mysql time 0 004417 sphinx time 0 083193 sphinx results time 0 078 mysql count queries 15 mysql queries sphinx count queries 3 sphinx real count queries 3 sphinx queries stime 0 008998 logged 2009 07 20 20 55 48 user agent Mozilla 4 0 compatible MSIE 7 0 Windows NT 5 1 GTB6 NET CLR 2 0 50727 InfoPath 2 referer http boardreader com fp FileForums 14910 PC Games CD 2 DVD Conversion 47977 html bot js cookie 1 page type search id 5ab03bc440ffa0c62610a62db988cb81 WWW percona com Available Instrumentation Tools Trending Cacti graphs ht
11. 2269 1 00 0 17 SELECT table8 table4 tablel4 table8 tablel8 i 6 iss 49 0330 2 3 15630 0 0031 1 00 0 00 ADMIN CONNECT T 9s 43 4990 2 0 274 0 1588 1 00 0 12 SELECT tablel9 S avs 30 0898 1 4 416 0 0723 1 00 0 07 SELECT tablel3 19 6506 0 9 13424 0 0015 1 00 0 01 UPDATE table20 www percona com pt query digest Query 1 17 06 OPS 1 92x concurrency ID 0x3928FBFF36663F33 at byte 1417466467 This item is included in the report because it matches limit Scores Apdex 1 00 1 0 V M 0 03 Time range 2010 11 29 09 14 30 052415 to 09 26 11 914796 Attribute pet total min max avg 95 stddev median ee Count 1 11976 Exec time 62 1350s 25ms 395ms 113ms 219ms 54ms 91ms Rows affecte 0 39 0 35 0 00 0 0 32 0 Query size 23 28 75M 2 46k 2 46k 2 46k 2 38k 0 2 38k Warning coun 11 51 51k O 12 80k 4 40 O 233 99 0 Boolean No index use 99 yes 0 no String Databases Errors none 273 99 1064 1 05 Hosts 172 20 101 178 www percona com pt query digest Query time distribution lus lOus 10015 lms dH 10ms d 100 5 1 1s 1051 Tables SHOW TABLE STATUS LIKE table19 G it SHOW CREATE TABLE 1801919 NG EXPLAIN 50100 PARTITIONS SELECT user agent id
12. 910 oprofiled oprofiled usr bin oprofiled 42116 0 1499 mysqld mysqld buf calc page new checksum 32107 0 1143 mysqld mysqld srv release threads 14624 0 0521 mysqld mysqld srv table get nth slot www percona com 61 Slow DROP TABLE when innodb file per table dropping a table causes innodb to run through LRU and delete all pages in that tablespaceid Fix in Percona Server innodb lazy drop table 1 http www mysglperformanceblog com 2011 04 20 drop table performance also fixed in 5 9 20 www percona com 62 Slow DROP TABLE eHowever another customer still had problems eusing pt mext you could see what was happening Innodb mem adaptive hash 16472598592 20889600 14925824 15056896 14811136 14909440 14876672 14827520 14827520 14909440 15089664 14827520 15024128 15024128 14958592 eAdaptive Hash Index was also invalidated at DROP TABLE fixed in 5 5 23 http ougs mysql com bug php Id 51325 WWW DerCona com 63 Optimizing Queries Example bad performance response time went up pt mext shows a large amount of handler read rnd next which means a lot of tablescans are being done Handler read first 47274 0 0 Handler read key 42993091324 34920 27522 Handler read next 19633194815 16911 10142 Handler read prev 2440127 0 0 Handler read rnd 488760449 40 12 Handler read rnd next 2731205271 86212518 65727868 how to find the queries that cause this slow query log www percona c
13. 9158357 211301010 3677 10277 9 11 294 5 21912350 100 164104 0 194 0 806 112 131 1 1 0 3 10 www percona com 51 pt mext Look at current global behavior of database Query Optimization necessary sorting 96 handler range 9o tmp table Innodb furious flushing WWW percona com 52 Disk Subsystem Statistics jostat commonly used Device roms was r s ws rsec s wsec s avgrg sz avgqu sz await svctm util sda 0 00 73 27 0 00 54 46 0 00 1061 39 19 49 4 84 88 80 18 36 100 00 sdal 0 00 0 00 0 00 0 00 0 00 0 00 0 00 0 00 0 00 0 00 0 00 sda2 0 00 73 27 0 00 54 46 0 00 1061 39 19 49 4 84 88 80 18 36 100 00 sdb 0 00 451 49 0 99 338 61 7 92 6368 32 18 78 144 23 420 93 2 94 100 00 sdol 0 00 451 49 0 99 338 61 7 92 6368 32 18 78 144 23 420 93 2 94 100 00 util how many of time at least one request was busy awalt svctm response time writes and reads combined WWW percona com 53 pt diskstats reads proc diskstats shows wr rd response time device rd s rd avkb rd mb s rd mrg rd cnc rd rt sda 0 1 4 0 0 0 0 0 5 0 sda2 0 1 4 0 0 0 0 0 0 5 0 sdb 119 8 0 6 0 5 4 1 o QU QU QU 0 5 4 1 O sdbl 119 8 5 3 0 6 www percona com 54 pt diskstats device wr s wr avkb wr mb s wr mrg wr cnc wr rt sda 23 5 35 6 0 8 89 1 2 5 9 sda2 2343 35 6 0 8 893 1 2 5 9 sdb 160 3 7 5 1 2 473 18 3 61 0 sdbl 160 3 7 5 1 2 47 18 3 61 0 WWW DerCona com 55
14. COW id 1 select type SIMPLE table title type eq ref possible keys PRIMARY title kind id exists key PRIMARY key len 4 ref imdb cast info movie id rows 1 Extra Using where 2 rows in set 0 00 sec www percona com SESSION STATUS mysql gt FLUSH STATUS s s CUN GQUCrY lt lt mysql show status like ha Variable name Value The number of times the first entry in an index was read Handler commit 0 hence ER J The number of requests to Hanse ECT read a row based on a key Handler prepare 0 Handler read first 1 Handler read key 13890229 The number of requests to Handler read next 14286456 read the next row in key order j Handler read rnd next Handler read prev 0 Haner PERC XTC A The number of requests to Handler F read the next row in the data file Handler savepoint 0 Handler savepoint rollback 0 The number of requests to Handler_update 0 insert a row in a table Handler write 2407001 EO GE X 15 rows in set 0 00 sec www percona com SHOW PROFILES SET profiling 1 run query SHOW PROFILES Query ID Duration Query 1 211 21064300 select STRAIGHT JOIN cou
15. Max 0 0 Min 0 0 M Query Time Count 10 Cur 0 0 Avg 00 Max 0 0 Min 0 0 www percona com pt mext percona machine pt mext r mysqladmin ext i 10 c 3 Binlog cache disk use 0 0 0 Binlog cache use 0 0 0 Bytes received 2875788973602 1738235 346057 Bytes sent 863929033790 588078 536398 Com begin 6298644573 3516 5102 Com delete 23121852 26 51 Com insert 4454794705 1518 3287 Com replace 527848577 197 121 Com select 6993291133 8114 7594 Com set option 5112076 250 262 Connections 7331059 250 262 Created tmp disk tables 113568 0 0 Created tmp files 7803 0 0 Created tmp tables 729281259 1816 479 www percona com 49 pt mext Handler commit 4002481284 Handler delete 7256841 Handler discover 0 Handler prepare 0 Handler read first 47274 Handler read key 42993091324 Handler read next 19633194815 Handler read prev 2440127 Handler read rnd 488760449 Handler read rnd next 2731205271 Handler rollback 5781 Handler savepoint 0 Handler savepoint rollback 0 Handler update 7022320034 Handler write 7334430104 5295 10 34920 16911 40 268 10047 1945 www percona com 4911 25 27522 10142 12 231 3329 3638 50 Ocache free blocks Ocache free memory Ocache hits Ocache inserts Ocache lowmem prunes Ocache not cached Ocache queries in cache Ocache total blocks Threads cached Threads connected Threads created Threads running Uptime pt mext 2899 519642808 325634530 978847229 1
16. ea of focus or put your in the wrong direction Dont trust computers humans and even yourself Have data to back up your thoughts Guessing might work but youre lying to yourself www percona com 10 Resolving MySQL Problems Quickly The Problem Instrumentation Individual Slow Query Global Performance Problems Intermittent Performance Problems WWW DerCona com 11 SURING like a boss CreateFunnyPictures com Instrumentation Instrumentation is the branch of mechanical engineering that deals with measurement and control You cant control what you can t measure Tom DeMarco Controlling Software Projects Management Measurement amp Estimation All cars give you some basic information How fast am going How far have gone At what rate am consuming fuel What is the engine temperature Do need oll www percona com 13 Why do we need to instrument a k a I already know where the problem is Do you really MySQL 15 second login www percona com 15 If you said that The Database You ll be right most of the time but you re not being 100 honest with yourself The database has more scalability challenges than the other components For the most part we can just add web servers www percona com 16 However We can lead ourselves into a real trap by guessing based on previous experience
17. er baron ginqer c baron ginger baron qginqer collected collected collected collected collected collactad collected collected collected collected pt sift IE IE IE IE IE d IE IE IE IE Sele 2011 07 21 10 14 58 2011 07 21 10 22 02 2011 07 21 10 44 47 2011 07 21 11 00 11 2011 07 21 11 06 13 2011 07 21 11 12 40 2011 67 21 11 19 09 2011 07 21 11 25 35 2011 07 21 11 32 03 2011 07 21 11 38 30 2011 07 21 10 16 49 2011 67 21 10 31 55 2011 07 21 10 54 48 2011 07 21 11 01 54 2011 07 21 11 08 20 2011 07 21 11 14 51 2011 07 21 11 21 16 2011 07 21 11 27 44 2011 07 21 11 34 12 2011 07 21 11 40 41 2011 07 21 10 19 16 2011 07 21 10 40 36 2011 07 21 10 57 36 2011 67 21 11 04 05 2011 07 21 11 10 31 2011 67 21 11 16 59 2011 07 21 11 23 27 2011 07 21 11 29 35 2011 07 21 11 36 23 ct a timestamp from the list 2011 07 21 11 40 41 www percona com Swpd ee buf f cache si so bi Te cs us sy id wa 15840 142084 16869724 0 36 116 142284 16911564 0 73 13053 3132 9 3 86 0 innodb txns LOxACTIVE 1s 310xnot 0s 0 queries inside InnoDB C queries in queue Main thread flushing buffer pool pages pending reads 1 writes 6 flush 8 Log lsn 1777474532609 chkp 1776282083670 chkp age 1192448939 Threads are waiting at Threads are waiting on processList State Sending data Has sent all binlog to slave waiting for binlog to be updated Reading from net
18. etween transactions in InnoDB Customer has no idea where it comes from what it causes use Percona Server with extended slow logging use pt stalk and trigger on transaction lock waits long running transactions configure to capture tcpdump data The tcodump data can then be converted with pt query digest Get the transaction session queries that causes that long running query www percona com 90 Transaction Locking TRANSACTION 0 1491496991 ACTIVE 14 sec process no 2441 OS thread id 1253165376 15 lock struct s heap size 3024 undo log entries 3 MySQL thread id 3657955 query id 1020342924 falcon website 192 168 100 8 web Trx read view will not see trx with id gt 0 1491496992 sees lt 0 1412169815 TRANSACTION 0 1491517002 ACTIVE 2 sec process no 2441 OS thread id 1198373184 83 lock struct s heap size 14320 undo log entries 138 MySQL thread id 3657956 query id 1020462952 falcon website 192 168 100 8 web Trx read view will not see trx with id gt 0 1491517003 sees lt 0 1412169815 TRANSACTION 0 1491525435 ACTIVE 2 sec process no 2441 OS thread id 1189742912 75 lock struct s heap size 14320 undo log entries 52 MySQL thread id 3657584 query id 1020513657 eagle website 192 168 100 7 web WWW percona com High Transaction Locking Problem was application bug a transaction was stuck in a loop The collected queries from that session helped developme
19. gger the tool Not too low You ll get false positives Not too high You ll miss the problem and it will hurt longer You ll diagnose the wrong problem www percona com The Threshold Threads running is very good Threads connected sometimes too Queries per second is hard to use You have to compare this vs previous sample PROCESSLIST works sometimes Too many queries with some status grep c Text in SHOW INNODB STATUS awk grep Other creative triggers www percona com What Value Should You Use S mysqladmin ext il awk Queries q 4 qp qp 4 Threads connected tc 4 Threads running printf 5d 5d 5d n q tc 4 2147483647 136 7 798 136 7 767 134 9 828 134 7 683 134 7 784 135 7 614 134 7 108 134 24 187 134 31 179 134 28 1179 134 1151 134 7 1240 135 7 1000 135 7 www percona com Configuring pt stalk Threshold 100 Collect GDB stacktraces collect gdb 0 Collect oprofile data collect oprofile 0 Collect strace data collect strace 0 Collect tcpdump data collect tcpdump 0 www percona com Capturing Data ot stalk stores data in var lib pt stalk There will be ALOT of data www percona com Did mention lots of data 2011 07 21 11 08 20 opentablesl 2011 07 21 11 08 20 opentables2 2011 07 7 21 11 08 20 output 2011 07 21 11 DB 20 pmap 2011 07 21 11 08 20 processlistl 2011 Ey Zu 11 IE 20 processlist2 2011 07 21 11 08 20 pr
20. ing MySQL Problems Quickly The Problem Instrumentation Individual Slow Query Global Performance Problems Intermittent Performance Problems www percona com 74 Diagnosing Intermittent Problems How to determine when it happens Tools Are Essential You need to measure the problem whether you can observe it or not Even if you see the problem happen you can t observe 45 things at once f you can t see it happen you can still capture diagnostic data Percona oolkit pt stalk pt sift www percona com 75 Using SHOW STATUS S mysqladmin ext il awk Queries q 4 qp qp 4 Threads connected tc 4 Threads running printf 5d 5d 5d n q tc 4 2147483647 136 7 798 136 7 767 134 9 828 134 7 683 134 7 784 135 7 614 134 7 108 134 24 Drop in Queries Per Second 187 134 31 Spike of Threads_running 179 134 28 Threads_connected doesn t change 1179 134 7 1151 134 7 1240 135 7 1000 135 7 www percona com Using The Slow Query Log awk Time print 3 4 c c 0 User ct slow query log 080913 21 52 17 51 080913 21 52 18 29 080913 21 52 19 34 080913 21 52 20 33 080913 21 52 21 38 080913 21 52 22 15 080913 21 52 23 47 080913 21 52 24 Spike followed by a 000913 21 52 25 c c on in queries per 080913 21 52 26 66 second 080913 21 52 27 37 080913 21 52 28 59 www percona com The Diagnostic Trigger Determine a reliable condition to tri
21. ion about global behavior Tools to use sysstat lostat mpstat vmstat pt mext pt diskstats pt ioprofile pt pmp pt query digest WWW DerCona com 41 MySQL Connections MySQL Connections 500 400 300 200 100 03 04 05 06 07 08 09 From 2011 04 02 17 16 16 To 2011 04 09 17 16 16 Max Connections Cur 500 0 Max Used Connections Cur 330 0 E Aborted Clients Cur 0 0 Avg 1 2m Max 21 7m E Aborted Connects Cur 3 3m Avg 3 5m Max 11 1m m Threads Connected Cur 178 1 Avg 194 0 Max 308 5 Connections Cur 5 1 8 1 Max 102 5 WWW percona com MySQL Replication MySQL Replication IOOLOHMH H3 MI 130 IJOL Wed Fri Sun Tue Thu Sat Mon Wed From 2010 03 02 09 02 00 To 2010 03 18 05 10 06 O Slave Running O Slave Stopped Mm Slave Lag Cur 706 5m Avg 15 4k Max 30 0k M Slave Open Temp Tables Cur 0 0 0 0 Max 0 0 M Slave Retried Transactions Cur 0 0 Avg 7 3u Max 1 4m www percona com MySQL Temporary Objects Temporary Objects 100 10MW 20 10 111310 1801 0 Mon 16 00 Mon 20 00 Tue 00 00 Tue 04 00 Tue 08 00 Tue 12 00 From 2008 05 19 15 29 41 To 2008 05 20 15 29 41 E Temp Tables Bl Temp Tables Current 948 04 m Average 1 47 Max 18 21 Bl Temp Disk Tables Current 0 00 Average 73 13 m Max 811 52 m B Temp Files Current 0 00 Average 2 34 m Max 52 00 m www percona com m gt a H m H a
22. nt as c person id FROM cast info FORCE INDEX person id INNER JOIN title ON cast info movie id title id WHERE title kind id 1 GROUP BY cast info person id ORDER by c DESC LIMIT 1 show profile for query 1 WWW DerCona com 36 SHOW PROFILES cont mysql gt show profile for query 1 me Duration starting checking permissions checking permissions Opening tables System lock init optimizing statistics preparing Creating tmp table Sorting for group executing l l l l l l l l l l l l OO O O O O O O O O O O 002133 000009 000009 000035 000022 000033 000020 000032 000031 000032 000021 000005 Copying to tmp table 25 rows in set 0 00 sec www percona com 113 862209 converting HEAP to MyISAM 0 200272 Copying to tmp table on disk 96 506704 Sorting result 0 634087 Sending data 0 000047 end 0 000006 removing tmp table 0 004839 end 0 000016 query end 0 000004 freeing items 0 000064 logging slow query 0 000004 logging slow query 0 000003 cleaning up 0 000006 ee SS SES s Slow Log Statistics GLOBAL long query time 0 SET GLOBAL log slow verbosity full This was executed on a machine with entirely Time 100924 13 58 47 User Host root root localhost cold caches Thread id 10 Schema imdb La
23. nt identify the problem in the application www percona com 92 Resolving MySQL Problems Quickly The Problem Find out what the problem is then look for data Don t guess or prove your guesses Instrumentation use trending collect data application performance monitoring Individual Slow Query go beyond explain Global Performance Problems look at global counters statistics Different problems require different tools IntermIttent Performance Problems pt stalk on a trigger that shows the behavior change analyze the data and adjust WWW DerCona com 93 Q amp A Useful Links http www mysqlperformanceblog com http www percona com http www percona com software percona server http www percona com software percona toolkit http www percona com software percona monitoring plugins kennv ar ercona com gt www percona com 94
24. ocstat 2011 07 21 11 08 20 procvmstat 2011 07 21 11 08 20 5 2011 215 11 IE 20 slabinfo 2011 67 Em 11 08 20 stacktrace 2011 07 21 11 08 20 sysctl 2117972151 B 2B 106 2011 07 21 11 08 20 trigger 2011 07 21 11 08 20 variables 2011 67 21 11 08 20 vmstat 2011 07 21 11 08 20 vmstat overall 2011 07 21 11 10 31 df 2011287721 1179180 31 018KS1 gu 2011 07 21 11 10 31 hostname 2011 07 21 11 10 3l innodbstatusl 2011 07 21 11 10 3l innodbstatus2 2011 0 7 21 11 10 3l interrupts 1 31 Tagt nt 2011 07 21 11 40 41 diskstats 2011 07 21 11 40 41 hostname 2011 07 21 11 40 41 innodbstatusl 2011 07 21 11 40 41 innodbstatus2 2011 0 7 21 11 40 41 interrupts 2011 21 11 40 41 iostat 2011 07 21 11 40 41 iostat overall 2011 07 21 11 40 41 log error 2011 07 21 11 40 41 lsof 2011 07 21 11 40 41 meminfo 2011 07 21 11 40 41 mpstat 2011 07 21 11 40 41 mpstat overall 2011 07 21 11 40 41 mutex statusl 2011 0 7 21 11 40 41 mutex status2 2011 07 21 11 40 41 mysqladmin 2011 07 21 11 40 41 netstat s 2011 07 21 11 40 41 opentablesl 2011 07 21 11 40 41 opentables2 2011 07 21 11 40 41 output 2011 07 21 11 40 41 pmap 2011 07 21 11 40 41 processlistl 2011 07 21 11 40 41 processlist2 2011 07 21 11 40 41 procstat 2011 07 21 11 40 41 procvmstat WWW percona com 8 1 baron aginger c baron ginger baron ginger c baron ginger baron ginger baron qinqer baron qginq
25. om 64 Enhanced Slow Log Statistics GLOBAL long query time 0 SET GLOBAL log slow verbosity full Time 100924 13 58 47 User Host root root localhost Thread id 10 Schema imdb Last errno 0 Killed 0 Query time 399 563977 Lock time 0 000110 Rows sent 1 Rows examined 46313608 Rows affected 0 Rows read 1 Bytes sent 131 Tmp tables 1 Tmp disk tables 1 Tmp table sizes 25194923 InnoDB trx id 1403 QC Hit No Full scan Yes Full join No Tmp table Yes Tmp table on disk Yes Filesort Yes Filesort on disk Yes Merge passes 5 InnoDB IO r ops 1064749 InnoDB IO r bytes 17444847616 InnoDB IO r wait 26 935662 InnoDB rec lock wait 0 000000 InnoDB queue wait 0 000000 InnoDB pages distinct 65329 SET timestamp 1285336727 select STRAIGHT JOIN count as c person id FROM cast info FORCE INDEX person id INNER JOIN title ON cast info movie id title id WHERE title kind id 1 GROUP BY cast info person id ORDER by c DESC LIMIT 1 WWW percona com pt query digest generate reports from slow query log pt query digest path to slow log binlog files processlist postgresql log files general log not so useful tcpdump files that captured traffic from mysql memcached http group by amp order by db ip host query time sum max min count WWW percona com 66 pt query digest store reports in db review review table8 enhanced filte
26. qua O Expert Iroubleshooting Resolving MySQL Problems Quickly Kenny Gryp lt kenny gryp percona com gt Netways Oks BL 2012 04 26 Resolving MySQL Problems Quickly The Problem Instrumentation Individual Slow Query Global Performance Problems Intermittent Performance Problems www percona com 2 Resolving MySQL Problems Quickly The Problem Instrumentation Individual Slow Query Global Performance Problems Intermittent Performance Problems www percona com 3 What is the problem Find out what the real problem is s not always what others say WWW percona com 4 Real Life Example Connections in CLOSE WAIT netstat tanp grep 8080 grep CLOSE WAIT wc 92 Connections to tomcat stay open WWW percona com 5 What is the problem echeck Isof Let s reduce TIME WAIT www percona com 6 So what s the real problem its a problem with the tomcat connection pool connections stay open www percona com 7 How do you know Nothing in any errorlog Well no problems then Where s the data to prove it www percona com 8 Getting to the problem Tomcat Doesn t Respond Almost there How do you know it does not respond he login pages keep on loading he problem www percona com 9 Things To Learn Find out what the real problem is Looking at vague problem definitions limit your ar
27. ring capabilities Sevent fingerprint m select Sevent Warning count gt 1 Sevent InnoDB IO r ops gt 50 event gt QC hit Yes Sevent gt Bytes gt m 1 048 576 www percona com 67 pt query digest 834 7s user time 9 15 system time 302 78M rss 392 96M vsz Current date Mon Nov 29 09 47 43 2010 Hostname servername Files STDIN Overall 670 66k total 1 73k unique 955 33 QPS 3 08x concurrency _ Time range 2010 11 29 09 14 29 955239 to 09 26 11 979320 Attribute total min max avg 95 stddev median H c Exec time 2163s 0 35 3ms 2ms 29ms 89us Rows affecte 18 58k 0 146 0 03 0 0 49 0 Query size 121 29M 6 21 55k 189 64 363 48 328 74 97 36 Warning coun 438 18k O 25 60k 0 67 O 122 19 0 Boolean No good inde 0 yes 995 no No index use 10 yes 89 no www percona com pt query digest Profile Rank QID Response time Calls R Call Apdx V M Item g 1 1349 6240 62 4 11976 0 1127 1 00 0 03 SELECT tablel table9 table2 table3 table4 2 114 9014 5 3 437 0 2629 1 00 0 50 SELECT table5 table6 table8 table7 table6 table8 tablelO i 3 wes 92 9441 4 3 791 0 1175 1 00 0 06 SELECT tablel3 4 wes 77 5712 3 6 43 1 8040 0 65 0 73 SELECT tablell tablel2 table9 table2 tablel4 tablel5 tablel6 tablel4 tablel7 D us 67 1673 3 15 296 0
28. st errno 0 Killed 0 Query time 399 563977 Lock time 0 000110 Rows sent 1 Rows ex mined 46313608 Rows affected 0 Rows read 1 Bytes sent 131 Tmp tables 1 Tmp disk tables 1 Tmp table sizes 25194923 InnoDB trx id 1403 Z QC Hit No Full scan Yes Full join No Tmp table Yes Trip table on disk Yes Filesort Yes Filesort on disk Yes Merge passes 5 InnoDB r ops 1064749 InnoDB IO r bytes 17444847616 InnoDB IO r wait 26 935662 InnoDB rec lock wait 0 000000 InnoDB queue wait 0 000000 InnoDB pages distinct 65329 SET timestamp 1285336727 select STRAIGHT JOIN count as c person id FROM cast info FORCE INDEX person id INNER JOIN title ON cast info movie id title id WHERE title kind id 1 GROUP BY cast info person id ORDER by c DESC LIMIT 1 WWW percona com Resolving MySQL Problems Quickly The Problem Instrumentation Individual Slow Query Global Performance Problems Intermittent Performance Problems WWW DerCona com 39 Global Performance Problems Example 95 response time increased from 40ms to 200ms What is going on Trending Use graphs Cacti templates http www percona com software percona monitoring plugins or it s variants https launchpad net percona ganglia mysql More granular or ad hoc Look at global statistics of db os hw during the performance problems www percona com 40 Performance Problems Gather informat
29. t localhost myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production myapp production N N N N N N N N N N N N N N N N N N NN N N N N N N N N N N N N N N O NULL Updating Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked Locked M H nn Info M I show processlist UPDATE users SET last login date NOW WHERE id 1657903 UPDATE users SET last login date NOW WHERE id 986755 UPDATE users SET last login date NOW WHERE id 607334 UPDATE users SET last login date NOW WHERE id 1802251 UPDATE users SET last login date NOW WHERE id 1076084
30. tp Awww percona com software percona monitoring plugins and their many variants APMs Basic http code google com p instrumentation for php Write your own www percona com 31 Resolving MySQL Problems Quickly The Problem Instrumentation Individual Slow Query Global Performance Problems Intermittent Performance Problems www percona com 32 Slow Query EXPLAIN SHOW SESSION STATUS e Recommended to run before and after the query e SHOW PROFILES e Available in 5 0 limited 5 1 e Breaks down the time taken on various steps of query execution e Huge amount of skew in any numbers it reports under Linux e Slow Query Log Extended Statistics Available in Percona Server Will let you know examined rows temp table on disk sort on disk how many IOPS in InnoDB etc WWW DerCona com 33 EXPLAIN mysql gt EXPLAIN select STRAIGHT JOIN count as c person id FROM cast info FORCE INDEX person id INNER JOIN title ON cast info movie id title id WHERE title kind id 1 GROUP BY cast info person id ORDER by c DESC LIMIT 1 G l COW ide 1 select type SIMPLE table cast_info type index possible keys NULL key person id key_len 8 ref NULL rows 8 Extra Using index Using temporary Using filesort 2
Download Pdf Manuals
Related Search