MySQL Query Logging

MySQL has an option to log all queries to a log file, stupidly though you need to restart the server to start/stop this log, its a bit lame, it also adds a lot of overhead to your box. I had the idea some time ago to use libpcap to figure out what gets sent to the server and started the code, I've mostly finished this now.

The MySQL protocol is undocumented but there is a reverse engineered protocol doc here. It is a tad outdated and I've found some queries that does not get parsed perfectly using the info there, I'll look into those some more.

Here are some sample outputs from my code:

# ./mysqldump.pl -i mysql.cap
17:08:44: SET autocommit=1
17:08:44: SELECT last_insert_id()
17:08:44: rollback

It also has a more verbose option:

# ./mysqldump.pl -i mysql.cap -v
MySQL Packet:
        Length          : 24
        Packet Number   : 0
        Packet Command  : 3
        SQL Command     : SELECT last_insert_id()
Packet Header:
        Source   : 192.168.1.1
        Dest     : 192.168.1.2
        S.Port   : 47241
        D.Port   : 3306
        Length   : 77
        Timestamp: 1150128523.750337

I could make the script do its own dumping using libpcap it's pretty easy but I prefer to only let it read tcpdump files, we get a LOT of queries (> 600 per second) and I don't want slow perl code to affect the servers, tcpdump is pretty fast and efficient.

I use Net::Pcap and NetPacket::TCP to extract the packets from the file, decoding the MySQL commands is pretty easy then:

$plen = ord(substr($pkt, 66, 3));
$pnum = ord(substr($pkt, 69, 1));
$pcmd = ord(substr($pkt, 70, 1));
$cmd  = substr($pkt, 71);

The offsets etc is defined in the documentation linked too above, $cmd will now hold the actual query ran against the server, but only where $pcmd == 3.

I'll upload the code for this in the next few days just letting a few people do some beta testing for me first.

UPDATE: You can now get the code here.

4 Comments

If you're running this on an OS that supports DTrace , it might be easier to do it in real-time.

http://blogs.sun.com/roller/page/bmc?entry=dtrace_on_rails

Bryan Cantrill shows a DTrace script he used to monitor Rails, but as a side effect, shows how he counted the top N MySQL queries. Tweaking that script to print out the queries in real-time should probably not be that hard.

That's pretty kewl, will check it out thanks :)

This is pretty nice. I have been looking around the internet for a tool that could monitor mysql queries and how long they take. Using PCAP this is the only thing I found.

Have you done any work on this since?

Hi,
What params do i need to launch tcpdump with so that the generated file is readable by your program ?
for now, when I launch the program on a tcpdump file
I got :

First Packet: Mon Sep 15 13:28:40 2008
Last Packet : Mon Sep 15 13:30:03 2008

Leave a comment

Recent Entries

  • flashpolicyd 2.0

    I wrote a multi threaded server for Adobe Flash Policy requests, some background from Adobe:Since policy files were first introduced, Flash Player has recognized /crossdomain.xml...

  • Adventures with Ruby

    Some more about my continuing experiences with ruby, in my last post I saidthe language does what you'd expect and as you'll see in my...

  • New programming language of choice - Ruby

    I have fallen out of love with Perl some time ago, I cannot point to one specific thing about it that put me off, I...

  • On working from home

    I've not been posting much here, work has been incredibly manic the last while, especially I need to still finish off my SSO posts with...

  • Rework of puppet facts for /etc/facts.txt

    Previously I blogged a custom fact that reads /etc/facts.txt to build up some custom facts for use in Puppet manifests, well I've since learned a...

Close