Log query before executing it.

Question

Hi, I've run into a problem where I run some query and the mysqld process starts using 100% CPU power, without ending. I want to pinpoint this query. The problem is that log/development.log contains only queries that have finished. Any idea?

Answer 1

You could take a look at running/unfinished statements via the

show processlist;

command.

Answer 2

I think you have a few options for this. The first is really taking a look at your development.log and seeing which actions are causing it. Take a look at the queries you're asking rails to run and try to pinpoint that particular query. If it's taking a large amount of time it probably means you're doing something like returning n+1 queries, missing indexes or some other performance killer.

You say that the dev log only has queries that have finished. Can't you work out what the next query to run would be?

Your other options involve starting mysqld with a log (i think the names of some of these have changed):

mysqld --log[=file_name] --log-slow-queries[=file_name]

Showing the current statement list using processlist from within mysql:

show processlist;

To prevent stuff like this happening again you could also take some time to look at a rails performance monitor like RPM from New Relic (http://www.newrelic.com/).

I hope this helps!

Answer 3

If you have assess to MySQL, consider the SQL query

SHOW PROCESSLIST

Or from the command line:

mysqladmin processlist

Alternatively, the most powerful way is to override the 'execute' method of the ActiveRecord::Base connection instance. This article shows the general approach:

http://www.misuse.org/science/2006/12/12/sql-logging-in-rails/

You put this code into application.rb:

# define SQL_LOG_FILE, SQL_LOG_MAX_LINES

connection = ActiveRecord::Base.connection
class << connection
    alias :original_exec :execute
    def execute(sql, *name)
        # try to log sql command but ignore any errors that occur in this block
        # we log before executing, in case the execution raises an error
        begin
            lines = if File::exists?(SQL_LOG_FILE) then IO::readlines(SQL_LOG_FILE) else [] end
            log = File.new(SQL_LOG_FILE, "w+")
            # keep the log to specified max lines
            if lines.length > SQL_LOG_MAX_LINES
                lines.slice!(0..(lines.length-SQL_LOG_MAX_LINES))
            end
            lines << Time.now.strftime("%x %I:%M:%S %p")+": "+sql+"n"
            log.write(lines)
            log.close
            $sql_log = sql
        rescue Exception => e
            ;
        end
        # execute original statement
        original_exec(sql, *name)
    end # def execute
end # class <<