[LRUG] Request for assistance with Rails performance oddity

[John Winters]

I've been lurking on this list for quite a while, but I think this is
the first time I've posted.  Please re-direct me if this isn't an
appropriate place for my question.

I used to be a professional software developer (for about 20 years) but
nowadays I'm a maths teacher.  However, I've been wanting to keep my
hand in and to that end a couple of years ago I started teaching myself
Ruby.  I feel the demand for C gurus probably isn't as great as it was.

I've been working on a Rails application and have been making steady
progress with it.

Just recently I reached the point where I wanted to load quite a few
records into my back-end database (MySql) and to that end I wrote a Ruby
script which I run by means of script/runner.  It is loading some pretty
small records ( < 100 bytes each) into two tables.  These tables start
out empty and the script creates 1 record in the first table for every 3
it creates in the other one.

When I first run the script with empty database tables it runs at a
perfectly satisfactory rate.  Loading a total of 105171 records takes
1662s, or a rate of 63.3 records/second.  Further, it doesn't slow down
as it loads - the rate of loading is the same when there are 100,000
records loaded as it was at the beginning.

If however I let the script stop and then start it again to load a
second batch it runs far more slowly.  A small further batch of 1384
records takes 584s, or about 2.4 records/second.

There is no change in the source of the records (in fact it's the same
source - the records are just loaded with slightly different key fields).

The load does not seem to be anything to do with the database engine.
MySql is staring into space twiddling its fingers and clocking up
practically no CPU time (far less than it was clocking up on the first
run).  My Ruby script on the other hand is using 100% of the user mode
of a CPU.  Examining the Rails log shows that the few database queries
it's making are each taking a fraction of a millisecond to complete.

This is the exact same script on both occasions.  The only difference I
can discover is that for the first run the database tables start out
empty, whilst for the second they have between them about 100,000
records in them.

As far as I can see, the extra CPU time is being chewed up in
ActiveRecord, but I can't see why.  Can anyone offer me any pointers for
how to track this down?

I am using a rather old version of Rails - 2.2.2 - simply because that
was the current version when I started.  Could it be a bug in this old
version which has subsequently been fixed?  Would it be worth migrating
to a more current version?

Thanks in advance for any assistance which you can offer.

John