Created
April 24, 2012 10:19
-
-
Save wolfeidau/2478613 to your computer and use it in GitHub Desktop.
strace of active record require and fopen calls.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| 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 | |
Author
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.
(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.)
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.
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/Code/Ruby/testloadstuff] time /Users/markw/.rbenv/versions/1.9.3-p125/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][
/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..
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
That said DTrace just told me a lot about the process which disproved some of my theories so well worth trying out, I am planning to use it for postgresql tracing and monitoring which is looks pretty awesome.