Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

All of a sudden this morning I have a load spike on my server hitting up to 10. Which is unusual as it used to be below 1.

Below is what I figure, in innodb engine status. Any thoughts if anything looks bad in this?

mysql> show engine innodb status \G  
*************************** 1. row ***************************
Status: 
=====================================
121117 16:04:24 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 53 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 830893788, signal count 532132777
--Thread 1175492928 has waited at btr0sea.c line 773 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x2aaaeb1a50b8 created in file btr0sea.c line 139
number of readers 4, waiters flag 0
Last time read locked in file btr0sea.c line 773
Last time write locked in file btr0sea.c line 516
--Thread 1298495808 has waited at btr0sea.c line 773 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x2aaaeb1a50b8 created in file btr0sea.c line 139
a writer (thread id 1182681408) has reserved it in mode  wait exclusive
number of readers 0, waiters flag 0
Last time read locked in file btr0sea.c line 773
Last time write locked in file btr0sea.c line 1267
Mutex spin waits 0, rounds 203550824060, OS waits 473478907
RW-shared spins 349053415, OS waits 78380817; RW-excl spins 514677483, OS waits 20821824
------------------------
LATEST DETECTED DEADLOCK
------------------------
121116 21:26:58
*** (1) TRANSACTION:
TRANSACTION 0 1780664112, ACTIVE 0 sec, process no 4145, OS thread id 
    1226877248 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1216, undo log entries 1
MySQL thread id 58254357, query id 564520818 108.68.9.18 crystalduuser Updating
UPDATE subscriptionhistory set `status` = 'processing' WHERE idhistory = 4846881
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 15492964 n bits 240 index `PRIMARY` of table `crystal_du_sm/subscriptionhistory` trx id 0 1780664112 lock_mode X locks rec but not gap waiting
Record lock, heap no 170 PHYSICAL RECORD: n_fields 18; compact format; info bits 0
 0: len 8; hex 800000000049f521; asc      I !;; 1: len 6; hex 00006a22c72e;     asc   j" .;; 2: len 7; hex 0000cac03e20f7; asc     >  ;; 3: len 8; hex     800000000001138e; asc         ;; 4: len 4; hex 508a7246; asc P rF;; 5: len 4; hex 5093adb6; asc P   ;; 6: len 4; hex 00004040; asc   @@;; 7: len 8; hex 8000000000002760; asc       '`;; 8: len 4; hex 508a7246; asc P rF;; 9: len 4; hex 5093acc6; asc P   ;; 10: len 6; hex 616374697665; asc active;; 11: len 1; hex 02; asc  ;; 12: len 4; hex 80000003; asc     ;; 13: len 1; hex 01; asc  ;; 14: len 1;     hex 80; asc  ;; 15: len 9; hex 73757370656e646564; asc suspended;; 16: len 1; hex 02; asc  ;; 17: len 8; hex 8000000000000001; asc         ;;

*** (2) TRANSACTION:
TRANSACTION 0 1780664110, ACTIVE 0 sec, process no 4145, OS thread id     1078765888 fetching rows, thread declared inside InnoDB 481
mysql tables in use 2, locked 2
9 lock struct(s), heap size 1216, undo log entries 1
MySQL thread id 58254375, query id 564520798 108.68.9.18 crystalduuser     Sending data
UPDATE  subscriptionhistory AS sh, renewalqueue AS rq SET sh.status='active'     ,rq.status='failure' 
WHERE sh.idhistory = rq.idhistory AND sh.status='processing' AND     sh.idhistory=4846881
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 15492964 n bits 240 index `PRIMARY` of table     `crystal_du_sm/subscriptionhistory` trx id 0 1780664110 lock_mode X locks rec but     not gap
Record lock, heap no 170 PHYSICAL RECORD: n_fields 18; compact format; info     bits 0
 0: len 8; hex 800000000049f521; asc      I !;; 1: len 6; hex 00006a22c72e;     asc   j" .;; 2: len 7; hex 0000cac03e20f7; asc     >  ;; 3: len 8; hex 800000000001138e; asc         ;; 4: len 4; hex 508a7246; asc P rF;; 5: len 4; hex     5093adb6; asc P   ;; 6: len 4; hex 00004040; asc   @@;; 7: len 8; hex 8000000000002760; asc       '`;; 8: len 4; hex 508a7246; asc P rF;; 9: len 4; hex 5093acc6; asc P   ;; 10: len 6; hex 616374697665; asc active;; 11: len 1; hex 02; asc  ;; 12: len 4; hex 80000003; asc     ;; 13: len 1; hex 01; asc  ;; 14: len 1; hex 80; asc  ;; 15: len 9; hex 73757370656e646564; asc suspended;; 16: len 1; hex 02; asc  ;; 17: len 8; hex 8000000000000001; asc         ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 14456565 n bits 360 index
`idx_rq_history_transid` of table `crystal_du_sm/renewalqueue` trx id 0 1780664110     lock_mode X waiting
Record lock, heap no 59 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 800000000049f521; asc
I !;; 1: len 30; hex
396464303766616434373135656136323836363439656433393337643365; asc
9dd07fad4715ea6286649ed3937d3e;...(truncated); 2: len 8; hex 000000000118a3cc; asc;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 0 1787041889
Purge done for trx's n:o < 0 1779729277 undo n:o < 0 1
History list length 1749083
Total number of lock structs in row lock hash table 35
--------
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: 0
Pending flushes (fsync) log: 0; buffer pool: 0
21710781 OS file reads, 336513222 OS file writes, 5594248 OS fsyncs
17.36 reads/s, 16651 avg bytes/read, 167.36 writes/s, 1.75 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 40175, free list len 23224, seg size 63400,
47274274 inserts, 41207331 merged recs, 10248524 merges
Hash table size 25499819, used cells 12836683, node heap has 26321 buffer(s)
522407.60 hash searches/s, 109824.10 non-hash searches/s
---
LOG
---
Log sequence number 240 1520989635
Log flushed up to   240 1520967362
Last checkpoint at  239 2777566435
0 pending log writes, 0 pending chkp writes
316135640 log i/o's done, 158.13 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 14330057522; in additional pool allocated 16029184
Buffer pool size   786432
Free buffers       0
Database pages     760111
Modified db pages  451626
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 32028848, created 7809334, written 41821350
18.04 reads/s, 2.62 creates/s, 18.58 writes/s  
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
10 queries inside InnoDB, 0 queries in queue
17 read views open inside InnoDB
Main thread process no. 4145, id 1165642048, state: sleeping
Number of rows inserted 241838205, updated 75023424, deleted 40, read 183252813758
49.96 inserts/s, 37.34 updates/s, 0.00 deletes/s, 1461310.64 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.06 sec)
share|improve this question
    
You're sure it's MySQL generating the load? –  Mat Nov 17 '12 at 14:00
    
yes its just mysql and no other process in ps -ef –  Mannoj Nov 17 '12 at 14:11
    
Check the Queries which are causing the Deadlocks, this might be a reason, where your server Load bump up. –  Gopinath Nov 17 '12 at 20:03
    
true the deadlock disappeared after the activity time and now the server is back normal. But still worried on why deadlock appeared first of all.. as this is a regular day today activity. –  Mannoj Nov 19 '12 at 5:12

3 Answers 3

Using show innodb status is one way to find out what's happening in MySQL but it is won't tell you everything you need to know. Monitoring the activity on your server both at the OS level and the MySQL level over time are essential in uncovering the origins of unexpected and ofcourse undesirable activity.

There are several things you can do to monitor what's going on both at the server level and at the InnoDB level. Linux provides sysstat which is available via the depots in both Debian and Redhat distros.

sysstat

Centos

yum install sysstat
chkconfig sysstat on
service sysstat start

Debian

apt-get install sysstat
vi /etc/default/sysstat
set sadc collect variable to true by changing the line to ENABLED=“true”.
/etc/init.d/sysstat start

Then using tools like ksar: http://sourceforge.net/projects/ksar/ you can review the statistical information collected by sysstat to display your server activity as graphs: memory, cpu , network activity and over a given period of time. This will help you to understand at exactly what time, the load on your server began to increase.

enter image description here

InnoDB

As for InnoDB, looking at your question sent me out searching for a way to monitor InnoDB lock activity. So I found innotop: http://www.xaprb.com/blog/2006/07/31/how-to-analyze-innodb-mysql-locks/

I followed their instructions for installation.

On my Fedora 16, I had to install ExtUtils first

sudo yum install perl-ExtUtils-MakeMaker
wget http://sourceforge.net/projects/innotop/files/latest/download
tar -zxvf innotop-1.9.0.tar.gz
cd innotop-1.9.0/
perl Makefile.PL
make 
sudo make install

Following their instructions, I deliberately caused a deadlock

http://www.xaprb.com/blog/2006/08/08/how-to-deliberately-cause-a-deadlock-in-mysql/

This gave me a very nice description of what was going on in an easy to read format.

enter image description here

With sysstat to monitor your server and innotop monitoring Innodb, you will already have much more information at your disposal than just show innodb status.

Using these types of utilities, may help to uncover at what time the load spikes are occuring and what queries if any may be causing those deadlocks in your example. Knowing when can be just as important as knowing why.

Another tool I often use to monitor what's going on with MySQL is Jet Profiler: http://www.jetprofiler.com/download/. This would provide you with a more detailed explanation, graphs and history of what kind of activity is being executed on MySQL. It may also uncover configuration problems such as not having enough memory allocated to your buffer pool.

enter image description here

Just some ideas to help you play detective and get to the origins of those load spikes and deadlocks from your question.

share|improve this answer

Using MONyog- MySQL Monitor you can monitor CPU Usage and Load Average of a machine where MySQL server is running

enter image description here MONyog latest version has Real-Time tab It tells you what’s happening on your MySQL server RIGHT NOW. It details key metrics like top 200 queries, slow queries, locked queries, locking queries, tables, databases, users, hosts and thread states, all of this in real-time as it happens. Information is retrieved from the server every one second. And the best part is that you can get started with real-time with just a click of a button without the overhead of enabling logs. enter image description here

share|improve this answer
    
Nope .. But I use it everyday also there are other products listed here hence thought of replying also user's question was related to load average which is being pointed out as a screenshot –  Mahesh Patil Dec 21 '12 at 11:30

The most likely place for the answer is in the slowlog. Set long_quer_time=1 and run for a while. Then use pt-query-digest. Then show us the query together with SHOW CREATE TABLE, SHOW TABLE STATUS, and EXPLAIN SELECT.

InnoDB STATUS is unlikely to be of use in detecting a CPU/load/IO spike.

MEM might be helpful, if you have purchased that.

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.