Skip to content

Instantly share code, notes, and snippets.

@wolfeidau

wolfeidau/gist:2478613

Created April 24, 2012 10:19
Show Gist options
  • Save wolfeidau/2478613 to your computer and use it in GitHub Desktop.
Save wolfeidau/2478613 to your computer and use it in GitHub Desktop.
Download ZIP
strace of active record require and fopen calls.
Raw
gistfile1.txt
markw@markw-VirtualBox:~/Code/Ruby/testloadapp$ strace -eopen ruby -r active_record -e ActiveRecord::Base 2>&1 | wc -l
3462
markw@markw-VirtualBox:~/Code/Ruby/testloadapp$ strace -eopen ruby -r ./config/environment -e ActiveRecord::Base 2>&1 | wc -l
30873
markw@markw-VirtualBox:~/Code/Ruby/testloadapp$
https://gist.github.com/2478613
markw@markw-VirtualBox:~/Code/Ruby/testloadapp$ time ruby -r active_record -e ActiveRecord::Base
real 0m0.269s
user 0m0.224s
sys 0m0.044s
markw@markw-VirtualBox:~/Code/Ruby/testloadapp$ time ruby -r ./config/environment -e ActiveRecord::Base
real 0m1.231s
user 0m1.120s
sys 0m0.116s
time sudo dtrace -s syscallcount.d -c "/Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r ./config/environment -e ActiveRecord::Base"
dtrace: script 'syscallcount.d' matched 439 probes
dtrace: pid 52944 has exited
__disable_threadsignal 1
__semwait_signal 1
access 1
bsdthread_create 1
bsdthread_terminate 1
exit 1
getrusage 1
mkdir 1
pipe 1
select 1
shm_open 1
thread_selfid 1
write 1
issetugid 2
__sysctl 3
fcntl 6
getrlimit 6
mprotect 9
read_nocancel 9
sigaction 14
pread 27
fstatfs64 28
chdir 30
munmap 33
__pthread_sigmask 34
fcntl_nocancel 45
close_nocancel 49
getdirentries64 58
open_nocancel 69
mmap 118
lseek 179
stat64 554
getgid 812
getuid 812
getegid 813
geteuid 814
close 1908
ioctl 1984
read 2165
sigprocmask 2342
sigaltstack 2343
madvise 3211
fstat64 3968
lstat64 11366
open 28352
sudo dtrace -s syscallcount.d -c 0.87s user 0.31s system 95% cpu 1.232 total
# cat syscalltime.d
syscall:::entry
{
k = probefunc;
}
tick-5000hz
/k != 0/
{
@[k] = count();
}
time sudo dtrace -s syscallcount.d -c "/Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r active_record -e ActiveRecord::Base"
dtrace: script 'syscallcount.d' matched 439 probes
dtrace: pid 52956 has exited
__disable_threadsignal 1
__semwait_signal 1
__sysctl 1
access 1
bsdthread_create 1
bsdthread_terminate 1
exit 1
getrusage 1
pipe 1
select 1
shm_open 1
thread_selfid 1
write 1
fcntl_nocancel 2
fstatfs64 2
issetugid 2
getdirentries64 5
close_nocancel 6
fcntl 6
getrlimit 6
open_nocancel 7
read_nocancel 9
sigaction 14
munmap 18
pread 18
mmap 75
lseek 87
getgid 345
getuid 345
getegid 346
geteuid 346
__pthread_sigmask 509
close 816
ioctl 861
read 937
sigprocmask 1020
sigaltstack 1021
fstat64 1693
madvise 2739
open 2894
stat64 3761
lstat64 4801
sudo dtrace -s syscallcount.d -c 2.15s user 0.18s system 99% cpu 2.353 total
sudo dtrace -s syscalltime.d -c "/Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r active_record -e ActiveRecord::Base"
dtrace: script 'syscalltime.d' matched 440 probes
dtrace: pid 54941 has exited
bsdthread_create 1
cltat64 1
exit 1
getattrlist 1
getppid 1
getrusage 1
psynch_cvbroad 1
psynch_mutexdrop 1
sigaltstvwait 1
thread_selfid 1
geteuid 2
getuid 2
lseek 2
open_nocancel 2
sem_post 2
psynch_mutexwait 3
read_nocancel 3
__mac_syscall 4
bsdthread_terminate 4
sigaction 4
getegid 5
write 5
proc_info 6
sigprocmask 6
getrlimit 7
getdirentries64 9
getgid 10
fstat64 27
close_nocancel 29
psynch_cvsignal 30
gettimeofday 31
sigsuspend 35
poll 46
mmap 48
__sysctl 59
pread 60
ioctl 61
munmap 63
workq_kernreturn 86
sigaltstack 101
__pthread_sigmask 102
__semwait_signal 104
open 155
stat64 401
select 756
close 915
kevent 1135
madvise 1818
read 2257
psynch_cvwait 3957
lstat64 4208
sudo dtrace -s syscalltime.d -c "/Users/markw/.rbenv/versions/1.9.2-p290/bin/ruby -r active_record -e ActiveRecord::Base"
dtrace: script 'syscalltime.d' matched 440 probes
dtrace: pid 54980 has exited
fstat64 1
getdirentries64 1
getrlimit 1
gpen 1
opea 1
open_nocancel 1
pread 1
psynch_cvsignal 1
read_nocancel 1
sigprostack 1
__sysctl 2
getgid 2
proc_info 2
close_nocancel 3
sigprocmask 3
issetugid 4
mmap 4
sigaltstack 4
madvise 5
__semwait_signal 8
getegid 8
__pthread_sigmask 11
ioctl 12
munmap 15
sigaction 19
stat64 22
workq_kernreturn 27
select 38
kevent 75
open 85
psynch_cvwait 119
close 132
read 380
lstat64 1727
@pda
Copy link

pda commented Apr 24, 2012

Oh — I thought this output meant that there are DTrace probes in Ruby…

paul@paulbookpro ~ ⸩ sudo dtrace -l | grep ruby
17528   ruby3289   libruby.1.dylib                          rb_call0 function-entry
17529   ruby3289   libruby.1.dylib                          rb_call0 function-return
17530   ruby3289   libruby.1.dylib                   garbage_collect gc-begin
17531   ruby3289   libruby.1.dylib                   garbage_collect gc-end
17532   ruby3289   libruby.1.dylib                           rb_eval line
17533   ruby3289   libruby.1.dylib                      rb_obj_alloc object-create-done
17534   ruby3289   libruby.1.dylib                      rb_obj_alloc object-create-start
17535   ruby3289   libruby.1.dylib                   garbage_collect object-free
17536   ruby3289   libruby.1.dylib                        rb_longjmp raise
17537   ruby3289   libruby.1.dylib                           rb_eval rescue
17538   ruby3289   libruby.1.dylib                 ruby_dtrace_probe ruby-probe
46553   ruby1040   libruby.1.dylib                          rb_call0 function-entry
46554   ruby1040   libruby.1.dylib                          rb_call0 function-return
46555   ruby1040   libruby.1.dylib                   garbage_collect gc-begin
46556   ruby1040   libruby.1.dylib                   garbage_collect gc-end
46557   ruby1040   libruby.1.dylib                           rb_eval line
46558   ruby1040   libruby.1.dylib                      rb_obj_alloc object-create-done
46559   ruby1040   libruby.1.dylib                      rb_obj_alloc object-create-start
46560   ruby1040   libruby.1.dylib                   garbage_collect object-free
46561   ruby1040   libruby.1.dylib                        rb_longjmp raise
46562   ruby1040   libruby.1.dylib                           rb_eval rescue
46563   ruby1040   libruby.1.dylib                 ruby_dtrace_probe ruby-probe

Anyway, good to know there’s a branch to try it against.

@pda
Copy link

pda commented Apr 24, 2012

(I guess that libruby.1.dylib comes from the ruby 1.8.7 (2010-01-10 patchlevel 249) [universal-darwin11.0] that ships with Mac OS X.)

@wolfeidau
Copy link
Author

Yepo for some reason they removed them, around the same time a lot of the debugging and profiling stuff broke I gather :)

Those are in the system ruby from what I understand.

I will give Aaron Patterson's version a shot tommorow, looks like a bit of a hack but I should be able to get it compiled.

@wolfeidau
Copy link
Author

So I built ruby trunk and got these results.

[master][/Code/Ruby/testloadstuff] time /Users/markw/.rbenv/versions/2.0.0-p1/bin/ruby -r active_record -e ActiveRecord::Base
/Users/markw/.rbenv/versions/2.0.0-p1/bin/ruby -r active_record -e 0.23s user 0.03s system 98% cpu 0.264 total
[master][/Code/Ruby/testloadstuff] time /Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r active_record -e ActiveRecord::Base
/Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r active_record -e 2.13s user 0.06s system 93% cpu 2.356 total

So it looks like the issue is with something in 1.9.3 which active record is using..

@pda
Copy link

pda commented Apr 25, 2012

For the record, @wolfeidau pinned this down to the RubyGems version.

# RubyGems 1.8.11, Ruby 1.9.3p0: 2.88 seconds

paul@paulbookpro ~/tmp ⸩ time ruby -r active_record -e ActiveRecord::Base
ruby -r active_record -e ActiveRecord::Base  2.74s user 0.13s system 99% cpu 2.882 total

paul@paulbookpro ~/tmp ⸩ time ruby -r ./config/environment -e ActiveRecord::Base
ruby -r ./config/environment -e ActiveRecord::Base  1.78s user 0.39s system 89% cpu 2.410 total

# RubyGems 1.8.23, Ruby 1.9.3p0: 0.82 seconds

paul@paulbookpro ~/tmp ⸩ time ruby -r active_record -e ActiveRecord::Base
ruby -r active_record -e ActiveRecord::Base  0.69s user 0.13s system 99% cpu 0.824 total

paul@paulbookpro ~/tmp ⸩ time ruby -r ./config/environment -e ActiveRecord::Base
ruby -r ./config/environment -e ActiveRecord::Base  2.22s user 0.42s system 99% cpu 2.644 total

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment