Loading my rails codebase in dev mode is taking ages

One of my rails apps is a rails 2.2 app with a large codebase. All of a sudden, it seems to be incredibly slow in dev mode. This is specifically due to the

config.cache_classes = false

option in config/environments/development.rb - when i set this to true, then it goes back to normal. I'd expect the lack of caching to slow it down, but the amount of slowdown i'm seeing is ridiculous: sometimes there will be a 30 second wait before anything starts happening in the log! Once i see stuff starting to happen in the log file then the page building proceeds as normal. I think this just started happening recently but i don't know what i could have done to trigger it.

Does anyone know how i could investigate this problem? All i have 开发者_运维百科to go on now is a 30 second period of nothing happening in the log file.

grateful for any pointers - max

EDIT - just noticed, that when i shut down mongrel_rails (which i use to run the app in dev mode) i get this message: Mon Jul 25 16:28:06 +0100 2011: Reaping 5 threads for slow workers because of 'shutdown'

This might explain the crazy slowdown, but i don't know why there would be 5 threads running.

EDIT2 - this app is running in a ruby 1.8.6 rvm, but switching back to the system ruby (also 1.8.6) didn't help.

EDIT3 - just did an experiment and a reload! in my console takes 28 seconds. So that's definitely the problem. I just don't understand why it's taking so long.

I found what was causing it, and it's quite surprising.

SHORT VERSION OF ANSWER:

The path to my app had gotten very long, and this making a regex somewhere take a long time to test a string containing that filepath.

LONG VERSION OF ANSWER:

One mad debugging quest* later i found the offending line: it's in lib/localization.rb, line 56:

  filename =~ /(([a-z]+_?)+)\.yaml$/

It runs this line twice for me, once for each yaml file in the lang folder. What's really nuts is that the values for 'filename' are

"/home/max/work/rails_apps/e_learning_resource_container/e_learning_resource/lang/en.yaml"

and

"/home/max/work/rails_apps/e_learning_resource_container/e_learning_resource/lang/localizations.yaml"

and, if i run the regex against this in my console, i get a massive delay there as well. So, the problem is testing the regex against those particular strings. I just did some experiments into how long it takes the regex to complete, and you can see that it's doubling in time with each extra letter: from irb (so nothing to do with my app, just plain irb)

ruby-1.8.6-p420 :023 > 10.times do |i|
ruby-1.8.6-p420 :024 >     string = "#{string1}#{"a"*i}#{string2}"
ruby-1.8.6-p420 :025?>     time = Time.now
ruby-1.8.6-p420 :026?>     string =~ /(([a-z]+_?)+)\.yaml$/
ruby-1.8.6-p420 :027?>     puts "#{string} -> #{Time.now - time}s"
ruby-1.8.6-p420 :028?>   end
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_/lang/en.yaml -> 0.133935s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_a/lang/en.yaml -> 0.149782s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aa/lang/en.yaml -> 0.198117s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaa/lang/en.yaml -> 0.316208s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaaa/lang/en.yaml -> 0.501882s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaaaa/lang/en.yaml -> 0.896808s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaaaaa/lang/en.yaml -> 1.707035s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaaaaaa/lang/en.yaml -> 3.322242s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaaaaaaa/lang/en.yaml -> 6.613822s
/home/max/work/rails_apps/e_learning_resource/e_learning_resource_aaaaaaaaa/lang/en.yaml -> 13.399231s

So, the regex is starting to really struggle with the string. If i change the regex so that it's

/([a-z]+_?)\.yaml$/

instead of

/(([a-z]+_?)+)\.yaml$/

, ie removing the ( +) around the inner brackets, then it's fine: super fast.

Adding to the mystery, in localization.rb this offending line is useless! Here's the whole block containing this line:

Dir[RAILS_ROOT + '/lang/*.yaml'].each do |filename|
  filename =~ /(([a-z]+_?)+)\.yaml$/
  hash = YAML::load(File.read(filename))
  file_charset = hash['file_charset'] || 'ascii'
  lang = $1

  # convert string keys to symbols
  symbol_hash = Hash.new
  Iconv.open(CONFIG[:web_charset], file_charset) do |i|
    hash.each do |key, value|
      symbol_hash[key.to_sym] = i.iconv(value)
      if key =~ /^active_record_errors_(.*)/
        I18n.t("activerecord.errors.messages")[$1.to_sym] =
          symbol_hash[key.to_sym]
      end
    end
  end

The regex on line 2 here tests the string but doesn't do anything with the result. Ie, it's not saying

if filename =~ etc
   ...do something

it just tests it for no apparent reason. So, we've got a regex that blows up with long strings being used for no reason whatsoever. DOUBLE FAIL. This is probably an old version of this module, i don't even know how it got into our codebase to be honest. Off to git to make a pull request for my fixed version (which just deletes that line).

*in case anyone's wondering what my mad debugging quest consisted of, i did the following to add a debug line to the start and end of every rb file in my app.

#get every rb file in the working folder
old_filecount = nil
files = []
fstring = "*/"
count = 0
folder = "./"
while old_filecount != files.size
  old_filecount = files.size
  files += Dir[File.join(folder,fstring*count, "*.rb")]
  count += 1
end  
#spam debugging into start and end of every file
files.each do |file|
  `sed '1i\\\nputs \"#\{Time.now} - #\{__FILE__}:#\{__LINE__}\"\' #{file} > tmp.txt;mv tmp.txt #{file}`
  `echo \";puts \\\"#\{Time.now} - #\{__FILE__}:#\{__LINE__}\\\"\" >> #{file}`
end

hacky eh.