-
-
Save wolfeidau/2478613 to your computer and use it in GitHub Desktop.
| 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 | |
Also, for comparison, here's my runtimes without DTrace:
paul@paulbookpro ~/code/webhack ⸩ time ruby -r active_record -e ActiveRecord::Base
ruby -r active_record -e ActiveRecord::Base 2.77s user 0.14s system 99% cpu 2.910 total
paul@paulbookpro ~/code/webhack ⸩ time ruby -r ./config/environment -e ActiveRecord::Base
ruby -r ./config/environment -e ActiveRecord::Base 1.74s user 0.34s system 99% cpu 2.090 total
2.9 seconds for just ActiveRecord. 2.0 seconds for ActiveRecord via Rails. Odd.
I have like 5 scripts now, will commit push it up to github so you can check it.
In short I found something is using a lot of CPU during this routine.
ActiveRecord::Base
This is illustrated by my total.d script.
My ideas with fopen being the cause were unfounded, also aside from a few odd balances in time I haven't been able to locate the cause, but because I knew it was in that routine i resorted to ruby_prof (see test.rb)
Will check push up my scratch project now.
Note till 4 hours ago I didn't know bugger all about dtrace either, aside from using other peoples scripts on Solaris systems :).
Just pushed up my hack project to https://github.com/wolfeidau/testloadstuff have a look at test.rb in the root of the project.
It outputs a massive profile report of that routine.
The report I generated on my system is located at ruby_prof.txt in the root directory.
The following two outputs were really intriguing as they illustrate that the active record base call is getting some big slugs of time scheduled on the CPU.
sudo dtrace -s total.d -c "/Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r active_record -e ActiveRecord::Base"
VS
sudo dtrace -s total.d -c "/Users/markw/.rbenv/versions/1.9.3-p125/bin/ruby -r ./config/environment -e ActiveRecord::Base"
Awesome. I’ll try and make some time to look around tomorrow.
Certainly keen to familiarize myself with DTrace now that it's in Ruby 1.9.3. I was inspired by re-reading http://tenderlovemaking.com/2011/12/05/profiling-rails-startup-with-dtrace/ a few weeks ago.
Bad news is it isn't :( http://bugs.ruby-lang.org/issues/2565
But good news is tenderlove has a fork which does have it which is located https://github.com/tenderlove/ruby/tree/probes
Yeah need to have a closer look at that profiler output I think it has another clue there somewhere.
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.
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.)
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.
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
Can you post your
syscallcount.d?(disclaimer: I've never worked with DTrace before)