Wow, that’s a long title. I just upgraded my wp theme to a wider layout, and I’m wallowing in the available space.

Anyway, this week I was tracking down a tricky mysql CPU issue and I wanted to take a closer look at what mysql was working on. Initially, I experimented with mk-query-digest –processlist, which was completely awesome but couldn’t really give me the full picture because it polls. Finally I decided that I wanted to log all the queries going through mysql. This can easily be done with mysql, but it took me a while to put all the pieces together.

Here’s what I ended up doing:

• Install mysql-proxy. This was relatively easy, though I had to use an older version on our production machine. Don’t forget to edit /etc/default/mysql-proxy if you’re running on Debian/Ubuntu!
• Create a lua script to log all the queries. There were a few different scripts in the repository, but ended up crafting my own. My version has a few important features:
  • No buffering. This is important when your server is running with many threads.
  • Tab delimited, with whitespace normalization. Duh.
  • Logs connect/disconnect. Handy for tracking down cron jobs gone wild.
  • Logs query execution time. I wasn’t looking for long running queries, just general load issues. Note that queries are written to the log when they complete.

  Here’s the lua code:

  
  local fh = io.open("/tmp/mysql_proxy.log", "a+")
  fh:setvbuf("no")
  
  function log_line(s, tm)
     if tm == nil then
        tm = 0
     end
     s = string.gsub(s, "[\n\t ]+", " ")
     s = string.format("%s\t%d\t%d\t%s\n", os.date("%Y-%m-%d:%H:%M:%S"),
                       proxy.connection.server.thread_id, tm, s)
     fh:write(s)
  end
  
  function read_handshake(auth)
     if auth then
        log_line("CONNECT " .. auth.client_addr, nil) -- for 0.6.1
     else
        log_line("CONNECT " .. proxy.connection.client.src.name, nil)
     end
  end
  
  function read_query(packet)
     if string.byte(packet) == proxy.COM_QUERY then
        proxy.queries:append(1, string.sub(packet, 2))
     end
  end
  
  function read_query_result(i)
     log_line(i.query, i.query_time)
  end
  
  function disconnect_client()
     log_line("DISCONNECT", nil)
  end
  

• There’s a great recipe for turning on the proxy with an iptables rule that redirects external connections from port 3306 to port 4040. I wrote a script to turn the rule on and off. Without the script, I kept installing the rule twice and confusing myself. Here’s the script:

  
  #!/usr/bin/ruby -w
  
  # turn mysql-proxy iptables rule on/off
  
  def run(command)
    system(command)
    raise "#{command} failed : #{$?}" if $? != 0
  end
  
  if `whoami`.strip != 'root'
    puts "must be run as root"
    exit 1
  end
  
  # is it on or off?
  rules = `iptables -t nat -L`
  is_on = rules =~ /^REDIRECT .* 4040/
  puts "mysql_proxy_iptables is currently #{is_on ? 'ON' : 'OFF'}."
  
  case ARGV.first
  when "on"
    if !is_on
      puts "Turning on..."
      run "iptables -t nat -I PREROUTING ! -s 127.0.0.1 -p tcp --dport mysql -j REDIRECT --to-ports 4040"
    end
  when "off"
    if is_on
      puts "Turning off..."
      run "iptables -t nat -D PREROUTING ! -s 127.0.0.1 -p tcp --dport mysql -j REDIRECT --to-ports 4040"
    end
  else
    puts "Usage: mysql_proxy_iptables [on|off]"
    exit 1
  end
  

• Note that existing connections won’t go through the proxy – the iptables rule only applies to new connections. You’ll have to restart rails to use the proxy.

Here’s some sample output:

2009-11-25:14:02:18	2470	0	CONNECT 127.0.0.1:55509
2009-11-25:14:02:18	2470	253	select @@version_comment limit 1
2009-11-25:14:02:20	2470	365	SELECT DATABASE()
2009-11-25:14:02:20	2470	547	show databases
2009-11-25:14:02:20	2470	100371	show tables
2009-11-25:14:02:22	2470	1147	select * from user
2009-11-25:14:02:40	2470	489	select * from event
2009-11-25:14:02:42	2470	19067	select * from db
2009-11-25:14:02:46	2470	0	DISCONNECT