Rails 2.2.2 Performance Problem/Bug

Question

I recently upgraded one of my applications to Rails 2.2.2. Having done that, I've encountered a strange performance bug that has caused renders that used to complete in a fraction of a second to take up to 10 seconds.

I've profiled the issue, and here are the results I've come up with. It looks like the issue is in the real_connect method of the Mysql class. My understanding is that the Ruby real_connect method is a wrapper around the C mysql_real_connect() function. This would lead me to believe that the issue must be with the database, since I've encountered the same problem when running the code on Windows and Linux (the database server is a separate system). I don't, however, believe this is the case, because when I roll back to a previous version (pre Rails 2.2.2) from my subversion repository, the performance issue goes away. This would seem the indicate that there is some kind of bug in ActiveRecord.

How do I go about identifying and fixing this bug? Does anyone have any insight? Is there something I'm missing?

Update: I just created a small profiler script to test the Mysql.real_connect method, and it appears that the problem isn't in Rails, but in the MySQL gem or the database server itself.

Upon running the following code:

result = RubyProf.profile do
  5.times do
    begin
     # connect to the MySQL server
     dbh = Mysql.real_connect(ip, user, pass, db)
     # get server version string and display it
     puts "Server version: " + dbh.get_server_info
    rescue Mysql::Error => e
     puts "Error code: #{e.errno}"
     puts "Error message: #{e.error}"
     puts "Error SQLSTATE: #{e.sqlstate}" if e.respond_to?("sqlstate")
    ensure
     # disconnect from server
     dbh.close if dbh
    end
  end
end

printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT, 0)

I came up with this performance result:

Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Thread ID: 18998180
Total: 50.402000

 %self     total     self     wait    child    calls  name
 99.99     50.40    50.40     0.00     0.00        5  <Class::Mysql>#real_connect (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00       10  IO#write (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  Mysql#get_server_info (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  Kernel#puts (ruby_runtime: 0}
  0.00      0.00     0.00     0.00     0.00        5  String#+ (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  Mysql#initialize (ruby_runtime:0}
  0.00     50.40     0.00     0.00    50.40        1  Integer#times (ruby_runtime:0}
  0.00     50.40     0.00     0.00    50.40        1  Global#[No method] (tmp/mysql_test/test.rb:12}
  0.00      0.00     0.00     0.00     0.00        5  Mysql#close (ruby_runtime: 0}

It seems as though the problem isn't in ActiveRecord, it's either in the MySQL gem or in the database. Where do I go from here?

Answer 1

I was able to track down the problem. I started by connecting to the host using the MySQL command from my development machine using the command mysql --host=ip --user=user --password=password db. This was very slow, so I ssh'ed into the server, and connected from there using the same command. This was also slow.

I changed the command to mysql --host=localhost --user=user --password=password db and I was able to connect instantaneously. I added an entry for my development system in the /etc/hosts file, and was able to connect instantaneously from that as well. Apparently the MySQL server was attempting to perform a reverse dns lookup to resolve the host name associated with the IP address, as is listed in the MySQL Manual, and was timing out.

I added the --skip-name-resolve option to the start section of the /etc/init.d/mysql script, so that this check is skipped, and restarted the server. When I run the profile script I created earlier, I get the following result:

Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Server version: 5.0.32-Debian_7etch3-log
Thread ID: 52978590
Total: 0.016000

 %self     total     self     wait    child    calls  name
 87.50      0.01     0.01     0.00     0.00        5  <Class::Mysql>#real_connect (ruby_runtime:0}
  6.25      0.00     0.00     0.00     0.00       10  IO#write (ruby_runtime:0}
  6.25      0.00     0.00     0.00     0.00        5  Mysql#close (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  Kernel#puts (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  Mysql#initialize (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  String#+ (ruby_runtime:0}
  0.00      0.02     0.00     0.00     0.02        1  Global#[No method] (tmp/mysql_test/test.rb:12}
  0.00      0.02     0.00     0.00     0.02        1  Integer#times (ruby_runtime:0}
  0.00      0.00     0.00     0.00     0.00        5  Mysql#get_server_info (ruby_runtime:0}