MySQL Proxy Query Profiling

Since I am now finally getting to play with MySQL Proxy, I am going to outline some recipes here that I have found/created/modified that may be useful to someone other than me. This is a recipe for profiling queries. It writes the information to the PROXY_LOG_FILE currently name mysql.log. It is a file that will be created in the directory that you run mysql-proxy from. The file itself is mostly commented and should therefore be pretty self-explanatory. It was adapted from the reference documentation listed at the bottom of this entry.

assert(proxy.PROXY_VERSION >= 0x00600,
  "You need to be running mysql-proxy 0.6.0 or greater")

 -- Set up the log file
 local log_file = os.getenv("PROXY_LOG_FILE")
 if (log_file == nil) then
    log_file = "mysql.log"
 end

 -- Open up our log file in append mode
 local fh = io.open(log_file, "a+")

 -- Set some variables
 local original_query = ""
 local executed_query = ""
 local replace = false
 local comment = ""

 -- For profilign
 local profile = 0

-- Push the query onto the Queue
function read_query( packet )
  if string.byte(packet) == proxy.COM_QUERY then
    query = string.sub(packet, 2)

    -- Pull out the comment and store it
    original_query = string.gsub(query, "%s*%*%*%*%s(.+)%s%*%*%*%s*",'')
    comment = string.match(query, "%s*%*%*%*%s(.+)%s%*%*%*%s*")

    -- Add the original packet to the query if we have a comment
    if (comment) then
        if string.match(string.upper(comment), '%s*PROFILE') then
          -- Profile types:
          --   ALL, BLOCK IO, CONTEXT SWITCHES, IPC,
          --        MEMORY, PAGE FAULTS, SOURCE, SWAPS

          -- Set it up for profiling
          -- Generate a new COM_QUERY packet
          --   and inject it with a new id (11)
          original_query = "SET PROFILING=1; " .. original_query
      end -- End if (PROFILE)
    end -- End if (comment)

    executed_query = original_query
    -- Check for a 'SELECT' typo
    if string.match(string.upper(original_query), '^%s*SLECT') then
        executed_query = string.gsub(original_query,'^%s*%w+', 'SELECT')
        replace = true;
    -- matches "CD" as first word of the query
    elseif string.match(string.upper(original_query), '^%s*CD') then
        executed_query = string.gsub(original_query,'^%s*%w+', 'USE')
        replace = true
    end

    -- Postpend the other profiling strings to the query
    if (comment and string.match(string.upper(comment), '%s*PROFILE')) then
        executed_query = executed_query .. "; SHOW " .. comment
    end

    -- Actually execute the query here
    proxy.queries:append(1, string.char(proxy.COM_QUERY) .. executed_query )
    return proxy.PROXY_SEND_QUERY
  else
    executed_query = ""
  end
end

function read_query_result (inj)
  local res = assert(inj.resultset)
  local num_cols = string.byte(res.raw, 1)
  if num_cols > 0 and num_cols < 255 then
     for row in inj.resultset.rows do
         row_count = row_count + 1
     end
  end
  
  -- Prepend the error tag in the log
  local error_status = "" 
  if res.query_status and (res.query_status < 0) then
     error_status = "[ERROR]"
  end
  
  -- Gets the rows affected by the actual query
  local row_count = 0
  if (res.affected_rows) then
     row_count = res.affected_rows
  end
  
  -- Prepend the comment line in the log
  if (comment) then
     fh:write( string.format("%s %6d -- [COMMENT] %s\n",
        os.date('%Y-%m-%d %H:%M:%S'), 
        proxy.connection.server["thread_id"],
        comment))
  end
  
  -- Prepend the typo in the log
  if (replace) then
     fh:write( string.format("%s %6d -- [REPLACEMENT] %s\n\t\t\t%s\n",
        os.date('%Y-%m-%d %H:%M:%S'), 
        proxy.connection.server["thread_id"],
        ("replaced " .. original_query),
        ("with " .. executed_query)))
  end
  
  -- Write the query adding the number of rows retrieved and query time
  fh:write( string.format("%s %6d -- %s %s {%d rows} {%d ms}\n",
     os.date('%Y-%m-%d %H:%M:%S'), 
     proxy.connection.server["thread_id"],
     error_status,
     executed_query,
     row_count,
     inj.query_time)
  )
  fh:flush()
end

To make this work, simply append 3 asterisks 'PROFILE <profile_type>' and then 3 more asterisks and you will have the profile information returned to you in your query:

*** PROFILE ALL *** SELECT * FROM foo_bar;

2 tables will be returned. Your results and then the profile of your results.

Reference: Writing LUA Scripts for MySQL Proxy

Posted in Lua. Tags: , . 4 Comments »
  • Idetrorce

    very interesting, but I don’t agree with you
    Idetrorce

  • http://www.php-trivandrum.org php trivandrum

    Excuse me if I am sounding bad..

    For interactive profiling information why would any one use the mysql-proxy and this much complicated lua script ?

    I happend to drop in because I was interested in getting the total no of queries, total query time, and time distribution in percentage with respect to any web page instance, and along with all these, the details of where bottlenecks could happen. All of these along with the advantage of being able to use on shared hosting.. the result was a php class, http://www.php-trivandrum.org/open-php-myprofiler

  • http://www.webhostings.in/ Hosting in India

    You have done a great job in this post. And Hope this code will work for me also.

  • Nikolay Lisienko

    I suggest to try windowed mysql profiler Neor Profile SQL http://www.profilesql.com