Document toolboxDocument toolbox

MySQL Performance Monitoring

Owned by John Hill
Last updated: May 03, 2017 by Xavier Schildwachter

"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