From: Jeremy Kemper Date: 2007-03-08T15:45:07+09:00 Subject: Re: High ActiveRecord CPU Utilization ------=_Part_212542_25214727.1173336304234 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Content-Disposition: inline On 3/7/07, Brian Adkins wrote: > zdennis wrote: > > On Mar 6, 10:30 pm, Brian Adkins wrote: > >> When running a test that primarily involves loading up a few MySQL > >> tables with ActiveRecord objects, I was surprised to see the Ruby CPU > >> utilization at 93% and the MySQL CPU utilization at 7%. I would expect > >> this workload to be heavier on MySQL than that. > > > > What is your script doing? Can you post it? > > I created a smaller test that I could post that exhibits the same > characteristics: > > class PerfTestController < ApplicationController > def index > t1 = Time.now > 3000.times do > member = Member.new > member.first_name = 'Fred' > member.last_name = 'Flintstone' > member.address1 = '123 High St.' > member.city = 'Reykjavik' > member.state = 'Michigan' > member.email = 'fred@flintstone.com' > member.save! > end > t2 = Time.now > puts "Time elapsed = #{t2-t1}" > end > end > > That took 35.7 seconds (84 inserts per second) on a dual core 2 GHz AMD > Opteron. It pegged Mongrel and MySQL didn't break a sweat. > > I just ran another test with a short ruby program inserting records > directly using the mysql gem and it only took 1.6 seconds (1,875 inserts > per second!), and the CPU utilization was as it should be - the MySQL > CPU was ten times as much as Ruby. So it definitely appears that > Rails/ActiveRecord is about 22 times as slow than a straight Ruby > program - wow! > > This result makes me feel much better since the performance of Ruby > seems fine. The fact that Rails/ActiveRecord is way slow isn't hurting > me yet, and there is hope it can be sped up since it doesn't appear to > be an inherent problem with Ruby. > > Here's the schema for Member: > > create table members ( > id int not null auto_increment, > created_at datetime not null, > updated_at datetime not null, > first_name varchar(30) null, > last_name varchar(30) null, > address1 varchar(50) null, > address2 varchar(50) null, > city varchar(30) null, > state varchar(5) null, > email varchar(100) null, > home_phone varchar(25) null, > primary key(id) > ) engine=InnoDB; Hi Brian, I wrapped this up in a simple script that anyone with MySQL or SQLite and the AR gem can run. It benchmarks AR create vs using the db connection directly. See attached. Excerpted results on a new MacBook Pro: user system total real raw quoted 0.460000 0.000000 0.460000 ( 0.480184) create 2.760000 0.080000 2.840000 ( 3.225227) (Nearly 7 times slower.) I haven't tried profiling the methods yet. In my experience with typical Rails apps, you'll hit a wall with ERB template rendering much sooner than with Active Record creation. This is an interesting pursuit nonetheless -- I'm interested to see what you all come up with. Best regards, jeremy ------=_Part_212542_25214727.1173336304234 Content-Type: application/octet-stream; name=ar_bench.rb Content-Transfer-Encoding: base64 X-Attachment-Id: f_ez0u2y1j Content-Disposition: attachment; filename="ar_bench.rb" IyEvdXNyL2Jpbi9lbnYgcnVieQpyZXF1aXJlICdiZW5jaG1hcmsnCgojIERvIHRoZSBnZW0gZGFu Y2UuCnJlcXVpcmUgJ3J1YnlnZW1zJwpnZW0gJ2FjdGl2ZXJlY29yZCcKcmVxdWlyZSAnYWN0aXZl X3JlY29yZCcKCgojIENvbm5lY3QgdG8gZGF0YWJhc2UsIGNyZWF0ZSBtZW1iZXJzIHRhYmxlLCBk ZWZpbmUgc29tZSBiZW5jaCBtZXRob2RzLgpjbGFzcyBNZW1iZXIgPCBBY3RpdmVSZWNvcmQ6OkJh c2UKICAjIEZhbGxiYWNrIHRvIGluLW1lbW9yeSBTUUxpdGUgaWYgTXlTUUwgbWVtYmVyX2JlbmNo IGlzbid0IGF2YWlsYWJsZS4KICBiZWdpbgogICAgZXN0YWJsaXNoX2Nvbm5lY3Rpb24gOmFkYXB0 ZXIgPT4gJ215c3FsJywgOmRhdGFiYXNlID0+ICdtZW1iZXJfYmVuY2gnLCA6dXNlciA9PiAncm9v dCcKICAgIGNvbm5lY3Rpb24ucGluZwogIHJlc2N1ZQogICAgZXN0YWJsaXNoX2Nvbm5lY3Rpb24g OmFkYXB0ZXIgPT4gJ3NxbGl0ZScsIDpkYXRhYmFzZSA9PiAnOm1lbW9yeTonCiAgZW5kCgogIGNv bm5lY3Rpb24uY3JlYXRlX3RhYmxlIHRhYmxlX25hbWUgZG8gfHR8CiAgICAldyhmaXJzdF9uYW1l IGxhc3RfbmFtZSBhZGRyZXNzMSBjaXR5IHN0YXRlIGVtYWlsKS5lYWNoIGRvIHxuYW1lfAogICAg ICB0LmNvbHVtbiBuYW1lLCA6c3RyaW5nCiAgICBlbmQKICBlbmQKCiAgRklYVFVSRSA9IHsgOmZp cnN0X25hbWUgPT4gJ0ZyZWQnLCA6bGFzdF9uYW1lID0+ICdGbGludHN0b25lJywKICAgICAgICAg ICAgICA6YWRkcmVzczEgPT4gJzEyMyBIaWdoIFN0LicsIDpjaXR5ID0+ICdSZXlramF2aWsnLAog ICAgICAgICAgICAgIDpzdGF0ZSA9PiAnTWljaGlnYW4nLCA6ZW1haWwgPT4gJ2ZyZWRAZmxpbnRz dG9uZS5jb20nIH0KCiAgIyBUaGUgc2ltcGxlc3Qgd2F5IHRvIGNyZWF0ZSBhIHJlY29yZC4KICBk ZWYgc2VsZi5jcmVhdGVfZml4dHVyZQogICAgY3JlYXRlISBGSVhUVVJFCiAgZW5kCgogICMgRXhw bG9kZWQgYSBsaXR0bGUuCiAgZGVmIHNlbGYuaW5pdGlhbGl6ZV9hbmRfc2F2ZV9maXh0dXJlCiAg ICBuZXcoRklYVFVSRSkuc2F2ZSEKICBlbmQKCiAgIyBFeHBsb2RlZCBhIGxpdHRsZSBtb3JlLgog IGRlZiBzZWxmLmluaXRpYWxpemVfc2V0X2FuZF9zYXZlX2ZpeHR1cmUKICAgIG1lbWJlciA9IG5l dwogICAgRklYVFVSRS5lYWNoIHsgfGtleSwgdmFsdWV8IG1lbWJlci5zZW5kKCIje2tleX09Iiwg dmFsdWUpIH0KICAgIG1lbWJlci5zYXZlIQogIGVuZAoKICBkZWYgc2VsZi5pbnNlcnRfdW5xdW90 ZWRfZml4dHVyZQogICAga2V5cyA9IEZJWFRVUkUua2V5cyAqICcsJwogICAgdmFsdWVzID0gRklY VFVSRS52YWx1ZXMubWFwIHsgfHZ8ICInI3t2fSciIH0gKiAnLCcKICAgIGNvbm5lY3Rpb24uaW5z ZXJ0ICJpbnNlcnQgaW50byAje3RhYmxlX25hbWV9ICgje2tleXN9KSB2YWx1ZXMgKCN7dmFsdWVz fSkiCiAgZW5kCgogIGRlZiBzZWxmLmluc2VydF9xdW90ZWRfZml4dHVyZQogICAga2V5cywgdmFs dWVzID0gW10sIFtdCgogICAgRklYVFVSRS5lYWNoIGRvIHxrZXksIHZhbHVlfAogICAgICBrZXlz IDw8IGNvbm5lY3Rpb24ucXVvdGVfY29sdW1uX25hbWUoa2V5KQogICAgICB2YWx1ZXMgPDwgY29u bmVjdGlvbi5xdW90ZSh2YWx1ZSwgY29sdW1uc19oYXNoW2tleV0pCiAgICBlbmQKCiAgICBjb25u ZWN0aW9uLmluc2VydCAiaW5zZXJ0IGludG8gI3t0YWJsZV9uYW1lfSAoI3trZXlzICogJywnfSkg dmFsdWVzICgje3ZhbHVlcy5qb2luKCcsJyl9KSIKICBlbmQKCiAgZGVmIHNlbGYuaW5zZXJ0X3F1 b3RlZF9maXh0dXJlX3dpdGhfY2FjaGVkX2Nvbm5lY3Rpb24KICAgIGtleXMsIHZhbHVlcyA9IFtd LCBbXQoKICAgIGNvbm4gPSBjb25uZWN0aW9uCiAgICBGSVhUVVJFLmVhY2ggZG8gfGtleSwgdmFs dWV8CiAgICAgIGtleXMgPDwgY29ubi5xdW90ZV9jb2x1bW5fbmFtZShrZXkpCiAgICAgIHZhbHVl cyA8PCBjb25uLnF1b3RlKHZhbHVlLCBjb2x1bW5zX2hhc2hba2V5XSkKICAgIGVuZAoKICAgIGNv bm4uaW5zZXJ0ICJpbnNlcnQgaW50byAje3RhYmxlX25hbWV9ICgje2tleXMgKiAnLCd9KSB2YWx1 ZXMgKCN7dmFsdWVzLmpvaW4oJywnKX0pIgogIGVuZAplbmQKCmlmIF9fRklMRV9fID09ICQwCiAg biA9IChBUkdWLnNoaWZ0IHx8IDMwMDApLnRvX2kKICBwdXRzICIoI3tufSBpdGVyYXRpb25zIHBl ciB0ZXN0KSIKCiAgQmVuY2htYXJrLmJtYm0gZG8gfHh8CiAgICB7ICdjcmVhdGUnICAgICAgICAg ID0+IDpjcmVhdGVfZml4dHVyZSwKICAgICAgIyduZXcrc2F2ZScgICAgICAgID0+IDppbml0aWFs aXplX2FuZF9zYXZlX2ZpeHR1cmUsCiAgICAgICMnbmV3K3NldCtzYXZlJyAgICA9PiA6aW5pdGlh bGl6ZV9zZXRfYW5kX3NhdmVfZml4dHVyZSwKICAgICAgIydyYXcgcXVvdGVkK2Nvbm4nID0+IDpp bnNlcnRfcXVvdGVkX2ZpeHR1cmVfd2l0aF9jYWNoZWRfY29ubmVjdGlvbiwKICAgICAgIydyYXcg dW5xdW90ZWQnICAgID0+IDppbnNlcnRfdW5xdW90ZWRfZml4dHVyZSwKICAgICAgJ3JhdyBxdW90 ZWQnICAgICAgPT4gOmluc2VydF9xdW90ZWRfZml4dHVyZQogICAgfS5lYWNoIGRvIHxuYW1lLCBi ZW5jaHwKICAgICAgIyAuZHVwIGJlY2F1c2UgYmVuY2htYXJrIHdhbnRzIHRvIG1vZGlmeSB0aGUg ZnJvemVuIHN0cmluZywgd3RmCiAgICAgIHgucmVwb3J0IG5hbWUuZHVwIGRvCiAgICAgICAgbi50 aW1lcyB7IE1lbWJlci5zZW5kIGJlbmNoIH0KICAgICAgZW5kCiAgICAgIE1lbWJlci5kZWxldGVf YWxsCgogICAgICB4LnJlcG9ydCAiI3tuYW1lfSB0eG4iIGRvCiAgICAgICAgTWVtYmVyLnRyYW5z YWN0aW9uIGRvCiAgICAgICAgICBuLnRpbWVzIHsgTWVtYmVyLnNlbmQgYmVuY2ggfQogICAgICAg IGVuZAogICAgICBlbmQKICAgICAgTWVtYmVyLmRlbGV0ZV9hbGwKICAgIGVuZAogIGVuZAplbmQK ------=_Part_212542_25214727.1173336304234--