Wednesday, April 6, 2011

Tracking long running transactions in MySQL

 Sometimes I want to trace transactions that have taken long time to execute. If a transaction is holding row locks for 30 seconds, all other clients requesting locks for the same rows will be blocked for up to 30 seconds (or will get Lock Wait Timeout errors if you set innodb_lock_wait_timeout lower). This is serious.

 The important step to solve such issues is identifying what kinds of queries are executed by problematic transactions. But tracking long running transactions is not as easy as tracking just slow queries. Suppose you execute the following transaction.
[client1]$ mysql --host=mysql_server db1
mysql> BEGIN;
... (do nothing for 10 seconds)
mysql> UPDATE t1 SET value=20 WHERE id=2;
mysql> COMMIT;
 This transaction takes more than 10 seconds to complete, but each query finishes very quickly. So nothing is written to the slow query log. Analyzing slow query logs is not helpful in this case.

 If you enable general query log, all queries including above are written. But this hurts performance (writing to general query log is serialized inside MySQL), and logging all queries makes log file size huge. Analyzing too big log files is not so fun. In addition, neither query execution time nor error code is written to the general query log. So just analyzing general query log is not enough to verify whether the above SELECT .. FOR UPDATE took 10 seconds or finished quickly.

 How about analyzing statement based binary logs? Unfortunately this is not always helpful. First, uncommitted transactions are not written to the binary log. There are many cases that transactions take long time and finally do rollback. Second, SELECT statements (including SELECT ... FOR UPDATE/LOCK IN SHARE MODE) are not written to the binary log. When you use locking reads, lots of transactions will be likely to be blocked. You probably want to identify which SELECT statement has caused the problem.

 Using SHOW ENGINE INNODB STATUS? SHOW ENGINE INNODB STATUS prints active transactions like below.
---TRANSACTION 1B43B50, ACTIVE 24 sec, process no 7388, OS thread id 1235609920 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 23, query id 140396660 root Updating
update t1 set value=100 where id=2
RECORD LOCKS space id 0 page no 213041 n bits 80 index `PRIMARY` of table `test`.`t1`
trx id 1B43B50 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000002; asc ;;
1: len 6; hex 000001b43b4e; asc ;N;;
2: len 7; hex 810000012d011c; asc - ;;
3: len 4; hex 80000002; asc ;;

---TRANSACTION 1B43B4F, ACTIVE 34 sec, process no 7388, OS thread id 1096673600
2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 22, query id 140396658 root
 You can identify that a client from was executing "update t1 set value=100 where id=2" and was waiting for 24 seconds to get some locks. But there is no information about what queries held the lock. A client from (1B43B4F) was running a transaction for 34 seconds, so this was probably the one holding the lock. But there is no information about why it was running for 34 seconds. In this case I want to get all queries that the 1B43B4F executed so far.

 If you can modify application programs, tracing long running transactions is not so difficult. Adding below logics will help.

1. Checking transaction start time (t1)
2. Pushing queries (and current timestamp) by the transaction into some in-memory queue
3. Checking transaction end time (t2)
4. If (t2 - t1) exceeds N seconds, printing all queries that the transaction executed
5. Deleting the in-memory queue

 The problem is that this approach is not feasible in many cases. Because long running transactions may be executed from every client, you have to implement tracing logic on all application servers. Modifying core database access codes and re-deplying on all application servers is not fun. If you use O/R mappers, things become more difficult. Modifying database driver programs on all application servers? I don't want to do that.

 Based on the above reasons, I thought that the most practical approach is tracing slow transactions on MySQL servers, without modifying any existing program (including client programs and MySQL servers). Hopefully there is a way to do that: capturing MySQL packets and tracking transactions and queries. The above 1-5 tracing algorithm should work.
I implemented the tool "MySlowTranCapture" and published at GitHub. Here is an example output.
[mysql-server]# myslowtrancapture -i eth0
Monitoring eth0 interface..
Listening port 3306..
Logging transactions that take more than 4000 milliseconds..

2011/02/23 09:12:17.258307 ->
2011/02/23 09:12:17.258354 <-
2011/02/23 09:12:17.264797 ->
select * from diary where diary_id=100 for update
2011/02/23 09:12:17.265087 <-
2011/02/23 09:12:17.277622 ->
select 1
2011/02/23 09:12:17.277713 <-
2011/02/23 09:13:01.232620 ->
update diary set diary_date=now() where diary_id=100
2011/02/23 09:13:01.232960 <-
2011/02/23 09:13:17.360993 ->

2011/02/23 09:12:20.969288 ->
2011/02/23 09:12:20.969483 <-
2011/02/23 09:12:20.977699 ->
update diary set diary_date=now() where diary_id=100
2011/02/23 09:13:11.300935 <-
GOT_ERR:Lock wait timeout exceeded; try restarting transaction
2011/02/23 09:13:13.136967 ->
 It is easy to identify that the first transaction caused problems. The first transaction held an exclusive lock for diary_id=100 at 09:12:17.264797, and didn't release until 09:13:17.360993. All queries by the transaction completed within a millisecond, so the first transaction was probably sleeping, or took long time to do other logics (i.e. accessing to remote servers and taking long time there) before closing the transaction.

 MySlowTranCapture uses libpcap to capture network packets, like tcpdump. Since libpcap loses packets sometimes, it is not guaranteed to capture 100% transactions.
 MySlowTranCapture approximately uses 10-30% CPU resources of mysqld process. This is not bad for short-term analyzing purposes (when I tested tcpdump, it used 140% CPU resources of mysqld, and most of CPU time seemed to be spent for writing network packets to local files).
 I sometimes use this tool for debugging, too. Sometimes developers execute unnecessarily many SQL statements within single transaction. MySlowTranCapture is useful to trace such transactions on development servers, by setting -t lower (i.e. 50ms).


Baron said...

This is a great tool for this purpose. I wrote about this problem recently here, too: I have found that long-running transactions is one of the most common causes of downtime for our customers. I have usually used some combination of shell scripts and tcpdump to solve this -- now I will update our internal wiki to point here :-)

RS Gold said...

If you enable the general query log, all matters, including the above. But it affects the performance (to write general query log serialized inside MySQL), and log all requests will logfile enormous size. Analysis of large logs is not as fun. Moreover, neither the execution time of queries or fault code written for the general query log. So just the analysis of the general query log is not enough to check if the SELECT above .. FOR UPDATE took 10 seconds and finished quickly.

A new game,tera meet us this year,like WOW Gold,Tera Gold become a hot toppic to players !!can we get Cheap WOW Gold,the price can near to WOW Items and WOW Gear,whatever Tera Gold will be so important like RS Gold to runescape player.

Runescape Gold said...

Genuinely amazed! Things quite, clear, open is a outline of your dilemma. It contains the details.

Android app development said...

Excellent pieces. Keep posting such kind of information on your blog. I really impressed by your blog.
Android app development| Android app developer| Android apps development|

wedding dresses 2012 said...

Lace, lace, lace…Call me Grace. A figuration of delicacy and intricacy, lace wedding dresses casts her spell on every female beating-heart, with the treatment ranging from tucked decoration details to an avalanche of lace appliqué throughout the torso. Our simple wedding dresses collection normally features with pearls, beading, sequins and embroidery, and subsequently blooms into an astounding Mermaid silhouette.

how to cunnilingus said...

I will bookmark this site and visit again. It is very informative. Thanks for sharing.
cervical mucus
ovulation symptoms

suhail11 said...

This is a great tutorial …one of the best I’ve seen from you yet. I really appreciate you sharing your inside tips and tricks. Ecommerce Software
Thanks for explaining the repeatedly asked Question.about E commerce shopping cart.Ecommerce Shopping Cart

john said...

Thanks for sharing this great info

tarjetas de débito prepagadas said...

Some of the predictions and comments made about the market by the pundits in those articles are pretty insightful because they are right on the mark and timely made.

hugginss jetterees said...

The composition of cheap gold helps make farming rather considerably less possible, but in the earlier mentioned stated illustration aided by the bear, it is actually doable in the event the player is aware which mobs to search out.

Jeremy Lee said...

Most trusted rs gold online shop for cheap runescape gold so far as I find. I have bought cheap runescape gold there a lot. Always safe and cheap!

soft said...

If you enable the general query log, all matters, including the above. But it affects the performance (to write general query log serialized inside MySQL), and log all requests will logfile enormous size. Analysis of large logs is not as fun. Moreover, neither the execution time of queries or fault code written for the general query log. So just the analysis of the general query log is not enough to check if the SELECT above .. FOR UPDATE took 10 seconds and finished quickly.

Cheap GW2 gold|cheap GW2 Gold

geetha said...

wonderful information, I had come to know about your blog from my friend nandu , hyderabad,i have read atleast 7 posts of yours by now, and let me tell you, your website gives the best and the most interesting information. This is just the kind of information that i had been looking for, i'm already your rss reader now and i would regularly watch out for the new posts, once again hats off to you! Thanks a ton once again, Regards, MySql online trainingamong the MySql in Hyderabad. Classroom Training in Hyderabad India

GuildWars2Items said...

It takes strength to be polite to someone when that person has been rude to you Cheap Diablo 3 Gold, It takes strength to build for the future Diablo 3 Gold Sale, It takes strength to resist temptations and distractions Diablo 3 Gold Sale.

GuildWars2Items said...

The past is gone and static. Nothing we can do will change it.Runescape Gold, the future is before us and dynamic. Everything we do will affect it rs gold, You laugh at meRunescape Gold for being different , but I laugh at you for being the same.

bruno berk said...

Hello Sir good article i really love it i have reading this article is awesome so good work keep working.A big thank you for your blog post.Really thank you! Fantastic.Professional Dissertation Proposal ^Cheap Custom Essays Online ^Essay writers Online ^Writing essays for university

de wo said...

In the fifth floor, brutal collision capacities have been reduced guild wars 2 gold. It allows your stun duration of blow and the surprise attack for zero point five to one second, the cooling time of blow reduces five to ten seconds. Wild Heart was adjusted to the fifth floor. Your intellect rises by four to twenty percent in WOW

Doris Eudora said...

This post truly made my day. You can’t imagine just how much time I had spent for this information! Thanks. logo creator

hazel Blossom said...

Blogs are good in which we get lots of information and convert that information to knowledge. definition writing

king 9k5 said...

ePageWiz will be considered a program that also converts html pages to a remain-alone EXE post. This ebook software offers full support of multimedia contents (HTML Pages, Java Scripts, Flash Files, VB Scripts, Graphic Files, Video Files Fashion Sheets, Sound Files and etc). This ebook software also gets the ability to assist password protect your post from copyright violators and the capability to be able to add 'trial limitation' which require users to register to be able to have full reach to be able to the manuscript.

Chris Westerfield said...

Thanks a lot. It was interesting to read even if it's too difficult for me to do it myself. I'm only beginner

sse said...

I’ve read your things before and you are just too awesome. I adore what you have got right here. You make it entertaining and you still manage to keep it smart. This is truly a great blog. Thanks for sharing. VPN service

Cahaya Mandiri said...

Great Post. I have not been visiting the site recently. Took a visit again and there were some great comments on the site. Excellent post. Keep up the good work.
tips cara agar cepat hamil l CARA BELAJAR BAHASA INGGRIS l the best acne treatment l how to lose weight fast easy
margahayuland l BISNIS ONLINE l tips cepat hamil l how to get rid of acne home remedies l
home remedies for acne l how to cure acne fast l
baju batik modern l toko sepatu online l grosir jam tangan online l
jual jam tangan l toko jam tangan murah peluang usaha online l is acne no more for you l how to get rid of acne naturally
how to clear acne l cure acne naturally
best natural remedies for acne l acne no more l tempat belajar bisnis online
peluang usaha rumahan l cara mendapatkan uang dari internet
makanan sehat agar cepat hamil l penyebab tidak bisa hamil lcara agar cepat hamil

sse said...

I would like to recommend you that traffic show most people study weblogs on Monday. So it should motivate blog writer to create new create ups over the few days mainly. belleville boots

sse said...

Hello, an amazing article dude. Thanks But Were issues in your rss . Dont know why Unable to subscribe to it. Could there be others having similar RSS trouble? Anybody nobody can assist please reply. Thnx! location de voiture casablanca

sse said...

So many people who can appreciate the work someone could easily give an award of commendation for the people. You can do this to yourself. renters insurance agent lake city

Roovi Kusnandar said...

This post truly made my day. You can’t imagine just how much time I had spent for this information! Thanks.

Andriani Rahmawati said...

Mysql is the lesson make headache.., thanks for share..

Bromo Tour| Paket wisata Bromo | Wisata Bromo | Paket Tour Bromo | Paket wisata Bromo | Wisata Malang | Wisata Batu Malang | Bromo Tour | <Bromo Tour Travel

Bell Brown said...

The blog was absolutely fantastic! Lot of great information which can be helpful in some or the other way. Keep updating the blog,
looking forward for more contents...Great job, keep it up.
Defect Bug Tracking

hazel Blossom said...

Its superb article! Thank you for this great information, you write very well which i like very much. I am really impressed by your post. Thanks for share this post. what is definition essay

jimmy wilson said...

Exceptional write-up I enjoy your post; enjoy how we outlined everything, what you are doing an excellent task many of people just like you by means of that will form of informative weblogs supply attention in order to us relevant to many things. My partner and i understand various other fascinating blogs out of your sites in addition to My business is a whole lot engaged along with your writing a blog expertise, My spouse and i in addition begun to generate article which form discussion truly assist us out. When i currently book marked your current webpage and also shared ones internet sites for you to our fellow workers not simply us but all of them such as your own running a blog abilities, wish people generate much more intriguing blogs similar to this one particular along with all the best . to your upcoming information sites.
Jimmy Wilson-Distressed leather Jacket Men Brown

jimmy wilson said...

Superb publish I enjoy your own article; love how we identified things, what you are doing a terrific task many of other folks that you by way of that type of educational information sites provide consciousness to us all associated with many points. I examine some other useful websites from your internet sites along with My business is a whole lot serious together with your running a blog ability, When i in addition begun to compose article and this form conversation definitely aid everyone out and about. We currently book marked ones web page as well as contributed your websites to my friends not just me however them all including ones blogging expertise, trust anyone produce more exciting information sites similar to this just one as well as best of luck on your long term information sites.
Jimmy Wilson from Harley Davidson Motorcycle Jacket

Brendon Taylor said...

These queries are a great tool to avoid problematic issues. custom coursework | buy coursework online | do my coursework

Jess said...

You know that when you are playing Runescape, you can make use of the cheap runescape gold tools. Where can you find the tools for Runescape? Here you come to the Runescape toolbar. You can download the tools you like or ffxiv gil you need. The tools are designed to help the players gain experience and play the game efficiently.

James Lawton said...

Really like this queries are executed by problematic transactions and right now i see more queries for your blog.. essay help by writingspot | dissertation writing service uk | assignment writers uk

Charlie Jonathan said...

It's quite brilliant quires you have upload on this article and i very helpful for reading this codes and guidance.. buy assignment from assignmentvilla | economics assignment guide

Lorena Alice said...

Excellent pieces. Keep posting such kind of information on your blog. I really impressed your article is very helpful for reading this codes and guidance. write my dissertation- elitedissertation

maegan meredith said...

These MySQL queries are new for me. It's so useful for me or those students who are developing my research paper for me , professional research paper writers/

stuart gorrez said...

After read this blog I have an idea about how to track a long running transactions. That's so nice of you for sharing this valuable information with us.dissertation writing online , coursework writers online.

Dean Jones said...

Example output certainly looks applicable and can be feasible in many cases. dissertation labs | buy dissertation at dissertationlabs | dissertation proposal – dissertation labs | dissertation editors at dissertation lab

Jasmine Peyton said...

In my mind direction, you are absolutely right saying to this topic. dissertation proposal help – || dissertation writing uk

Helen Dina said...

Is a long-running transaction. If a transaction remains open for a very long time without committing, and has modified data, then other. Transactions pose a problem. More interesting are open transactions which are known to hold locks. I will improve the view to include such info. pay for essay -

justin Reuban said...

This debate will not be over we should start it again.....maths coursework writers || science coursework writers

ravi said...


i used the tool and i get the below result

[wcuser@wc-devc-vm12 ~]$ sudo /usr/local/bin/myslowtrancapture
Monitoring any interface..
Listening port 3306..
Logging transactions that take more than 4000 milliseconds..

there are txn that are lock wait time outing (from the java server exception) and on db we configured the lock wait timeout to 20 seconds. However we dont see the tool capture such queries on the db server; any clues?

Acker Reuben said...

Of course, in some cases it’s actually easy to figure out what the long-running transaction is doing. The most obvious is if it’s a long-running query.
plagiarism free assignment writers | pay someone to do your assignment | order assignment

Andrew Alpert said...

If you are looking for English coursework writing service so check Essay Palace I have good experience with this company so far. Cheers.

akram irhal said...

I was very pleased to find this site.I wanted to thank you for this great read!! I definitely enjoying every little bit of it and I have you bookmarked to check out new stuff you post. Visit Simple Cash Code

akram irhal said...

Binary German Robot norbert and German mystery broker exhibited incalculable individuals exchanging double choices. That is the reason we do a survey of german binary robot. Norbert R. is a rebel German broker who has instructed individuals around the dreamland of his German exchanging method binary alternatives Banker mystery.

The Commodity Robot Review is a new product , you can chose different modul like Commodity Robot Gold or The Robot OF Commodity Silver or Commodity Robot Oil...ect, and you don't worry about trying this big system because you are protected by "60 Day Money Back" Guarentee.

Jerukukuk said...

Great Post. I have not been visiting the site recently. Took a visit again and there were some great comments on the site. Excellent post. Keep up the good work.
jam tangan original jam tangan alexandre christie
jam tangan couple

sadia sulaman said...

Excellent read, Positive site, where did u come up with the information on this posting?I have read a few of the articles on your website now, and I really like your style.jpburnside |

rhinomoto |

ebayshopdesigner |

vegan-candles |

oxygenediving |

montagupe |

ne7es |

happymondayscomedy |

mmmmh |

eskyhobby |

Post a Comment