MySQL Performance Monitoring
"Step 0" Connect to Synapse production database
log in to platform aws account
go to S3 bucket called prod-default.sagebase.org / prod-defaults.properties and find:
# This is the password that will be used as the master password of the stack-isntances database.
org.sagebionetworks.stack.instance.db.default.password.plaintext=<datbase password>
Get URL, username for production database:
goto RDS in AWS console and click on "DB instances"
select current instance, e.g. if we are on stack "j" then its' prod-j-db
get the endpoint, e.g. prod-j-db.c5sxx7pot9i8.us-east-1.rds.amazonaws.com
get the Master Username, e.g. prodjuser
open mysql workbench
New Connection
fill in name, hostname (=endpoint from above), user name (=Master Username from above)
click Test Connection
in the pop up window, paste password from properties file above
click "save in keychain"
Click OK twice
double click new connection to start querying
What is MySQL currently doing?
When the MySQL database suddenly becomes unresponsive, the most important question: What is MySQL currently doing? One way to answer this question is with the following SQL:
SHOW FULL PROCESSLIST;
You should be able to run this command from your MySQL Workbench or a MySQL prompt. Much like the linux 'top' command it shows the current processes and what they are doing. Here is an example of the call:
In the above example, the database is fairly idle as most of the processes are sleeping (Command=Sleep) and have been for awhile. When the database is busy executing long running queries they will show up with a Command=Query. The 'Time' column tells you how long the query has been running in seconds.
Killing a Process
To kill a process simply run the following using the ID of the process you want to kill:
KILL 123;
Historically: What has been slow?
When the database has been sporadically slow, or seems to be getting slower the slow query log can be a useful tool in debugging the problem. By default, MySQL does not have the slow query log turned on, but on all of our AWS RDS instances we should have turn on this feature. At the time of this writing our RDS instances are configured to captures any query that takes longer than one second. The slow query log can be accessed through MySQL Workbench or a MySQL command prompt by querying the 'slow_log' table in the 'mysql' schema. You must connect with a user that has read permission to the 'mysql' schema (or database). Here is an example:
select * from mysql.slow_log where start_time > '2012-06-01 00:00:00' and db = 'prodC' order by start_time desc;
Here is an example of the above query:
In this example you can see we were having some problem with some very basic queries taking crazy amounts of time.
Engine Status
Another useful tool:
SHOW ENGINE INNODB STATUS;
This list various statistics and information about the database. See the Docs: http://dev.mysql.com/doc/refman/5.0/en/innodb-monitors.html. Here is an example of the output:
===================================== 120726 14:17:59 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 32 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 678 1_second, 678 sleeps, 65 10_second, 55 background, 55 flush srv_master_thread log flush and writes: 699 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 4974, signal count 9764 Mutex spin waits 45429, rounds 118951, OS waits 2373 RW-shared spins 4877, rounds 41456, OS waits 789 RW-excl spins 10259, rounds 96991, OS waits 1707 Spin rounds per wait: 2.62 mutex, 8.50 RW-shared, 9.45 RW-excl ------------------------ LATEST FOREIGN KEY ERROR ------------------------ 120726 13:07:30 Transaction: TRANSACTION 3E17B5, ACTIVE 0 sec, OS thread id 1624 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 4 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1 MySQL thread id 68, query id 210213 localhost 127.0.0.1 devhill updating DELETE FROM JDOUSERGROUP WHERE `ID` = '1938' Foreign key constraint fails for table `devhill`.`jdonode`: , CONSTRAINT `NODE_CREATED_BY_FK` FOREIGN KEY (`CREATED_BY`) REFERENCES `jdousergroup` (`ID`) Trying to delete or update in parent table, in index `PRIMARY` tuple: DATA TUPLE: 6 fields; 0: len 8; hex 8000000000000792; asc ;; 1: len 6; hex 0000003e17b5; asc > ;; 2: len 7; hex 240000014215bb; asc $ B ;; 3: len 8; hex 8000124cb8bbd025; asc L %;; 4: len 1; hex 01; asc ;; 5: len 45; hex 4e6f64654261636b75704d616e61676572496d706c4175746f77697265546573744074657374526573746f7265; asc NodeBackupManagerImplAutowireTest@testRestore;; But in child table `devhill`.`jdonode`, in index `NODE_CREATED_BY_FK`, there is a record: PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 8; hex 8000000000000792; asc ;; 1: len 8; hex 8000000000000793; asc ;; ------------------------ LATEST DETECTED DEADLOCK ------------------------ 120726 13:51:14 *** (1) TRANSACTION: TRANSACTION 3E4D73, ACTIVE 0 sec, OS thread id 5392 inserting mysql tables in use 1, locked 1 LOCK WAIT 25 lock struct(s), heap size 3112, 13 row lock(s), undo log entries 12 MySQL thread id 158, query id 361684 localhost 127.0.0.1 devhill update INSERT INTO JDOSTRINGANNOTATION(`OWNER_ID`, `ATTRIBUTE`, `VALUE`) VALUES (89362, 'startDate', '1323376053831') *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 11019 n bits 192 index `OWN1_ATT2_INDEX` of table `devhill`.`jdostringannotation` trx id 3E4D73 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 111 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 8000000000015d36; asc ]6;; 1: len 11; hex 636f6d6d616e644c696e65; asc commandLine;; 2: len 6; hex 000000013abc; asc : ;; *** (2) TRANSACTION: TRANSACTION 3E4D6F, ACTIVE 0 sec, OS thread id 1808 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 25 lock struct(s), heap size 3112, 13 row lock(s), undo log entries 12 MySQL thread id 159, query id 361690 localhost 127.0.0.1 devhill update INSERT INTO JDOSTRINGANNOTATION(`OWNER_ID`, `ATTRIBUTE`, `VALUE`) VALUES (89341, 'startDate', '1323375804822') *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 11019 n bits 192 index `OWN1_ATT2_INDEX` of table `devhill`.`jdostringannotation` trx id 3E4D6F lock_mode X locks gap before rec Record lock, heap no 111 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 8000000000015d36; asc ]6;; 1: len 11; hex 636f6d6d616e644c696e65; asc commandLine;; 2: len 6; hex 000000013abc; asc : ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 11019 n bits 192 index `OWN1_ATT2_INDEX` of table `devhill`.`jdostringannotation` trx id 3E4D6F lock_mode X locks gap before rec insert intention waiting Record lock, heap no 111 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 8000000000015d36; asc ]6;; 1: len 11; hex 636f6d6d616e644c696e65; asc commandLine;; 2: len 6; hex 000000013abc; asc : ;; *** WE ROLL BACK TRANSACTION (2) ------------ TRANSACTIONS ------------ Trx id counter 3E4F4B Purge done for trx's n:o < 3E4F4A undo n:o < 0 History list length 127 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 3E4F0D, not started, OS thread id 4444 MySQL thread id 169, query id 368638 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F12, not started, OS thread id 3344 MySQL thread id 168, query id 368655 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F48, not started, OS thread id 4088 MySQL thread id 167, query id 369099 localhost 127.0.0.1 devhill ---TRANSACTION 3E4E4E, not started, OS thread id 6008 MySQL thread id 163, query id 367326 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F07, not started, OS thread id 4440 MySQL thread id 165, query id 368480 localhost 127.0.0.1 devhill ---TRANSACTION 3E4EBF, not started, OS thread id 4544 MySQL thread id 162, query id 368072 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F32, not started, OS thread id 2456 MySQL thread id 161, query id 369044 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F46, not started, OS thread id 1016 MySQL thread id 160, query id 369096 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F11, not started, OS thread id 1808 MySQL thread id 159, query id 368662 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F1C, not started, OS thread id 1624 MySQL thread id 157, query id 368754 localhost 127.0.0.1 devhill ---TRANSACTION 3E4F4A, not started, OS thread id 4880 MySQL thread id 2, query id 369116 localhost 127.0.0.1 root SHOW ENGINE INNODB STATUS ---TRANSACTION 0, not started, OS thread id 3892 MySQL thread id 1, query id 369114 localhost 127.0.0.1 root -------- 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 (read thread) I/O thread 4 state: wait Windows aio (read thread) I/O thread 5 state: wait Windows aio (read thread) I/O thread 6 state: wait Windows aio (write thread) I/O thread 7 state: wait Windows aio (write thread) I/O thread 8 state: wait Windows aio (write thread) I/O thread 9 state: wait Windows aio (write thread) Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] , ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 625 OS file reads, 23672 OS file writes, 13061 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: size 1, free list len 5, seg size 7, 0 merges merged operations: insert 0, delete mark 0, delete 0 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 222149, node heap has 29 buffer(s) 0.00 hash searches/s, 0.00 non-hash searches/s --- LOG --- Log sequence number 3791725005 Log flushed up to 3791725005 Last checkpoint at 3791725005 0 pending log writes, 0 pending chkp writes 12616 log i/o's done, 0.00 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 114835456; in additional pool allocated 0 Dictionary memory allocated 195289 Buffer pool size 6848 Free buffers 4463 Database pages 2356 Old database pages 849 Modified db pages 0 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 113, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 486, created 1870, written 10740 0.00 reads/s, 0.00 creates/s, 0.00 writes/s No buffer pool page gets since the last printout Pages read ahead 0.00/s, evicted without access 0.00/s LRU len: 2356, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 1 read views open inside InnoDB Main thread id 2388, state: waiting for server activity Number of rows inserted 105937, updated 4951, deleted 59080, read 108048 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================
More information about transactions
SELECT * FROM information_schema.innodb_trx # See https://dev.mysql.com/doc/refman/5.7/en/innodb-trx-table.html