scaffold アプリのなかでコストの高いメソッド

Rails DTrace

ちょっと前に、性能をみるために用意した ActiveScaffold とふつうの scaffold によるアプリに、DTrace をかけてみました。50 リクエストを処理するのに、数百万のメソッド呼び出しが観測されます。(DTrace の変数領域の都合上、あまり多くのリクエストはかけられませんでした...)

実行回数が多く、トータルとしてコストがかかっているメソッド、あるいは 1回あたりのコストが大きいので、呼び出される回数は少ないものの性能に寄与してくるメソッドなどがわかると思います。ひとまず、上位 10メソッドを並べてみました。

絶対値としてはあまり意味がないでしょうが、相対的にボトルネックとなっている箇所は見えてくる...かと?


# はてな記法の表形式が左寄せになってしまうのをなんとかしたい... orz


ActiceScaffold アプリ

  • メソッドの実行時間の合計
クラス メソッド 回数[#] 合計時間[us]
Class connection 10072 12129396
Object sleep 26 12587050
ActiveScaffold::DataStru field_name 9464 14661475
Array select 9420 16179970
Hash [] 374137 18212681
Object respond_to? 157024 18807037
Class authorized_for? 7103 21688979
Object authorized_for? 9349 25392729
Array each 45242 26868825
Object send 17841 28908327
  • メソッドの実行時間の平均 (1回の呼び出しあたりの時間)
クラス メソッド 回数[#] 平均時間[us]
Array collect! 49 9505
Class read 1222 9783
Object javascript_include_tag 98 15536
ActiveRecord::Connection result_as_array 97 16389
Object active_scaffold_include 49 24731
PostgresPR::RowDescripti parse 119 28505
Object _run_erb_app47views47la 47 44197
Object render 47 46681
ActionView::Template render_template 47 46747
Object sleep 24 478806
  • メソッドの CPU 使用時間の合計
クラス メソッド 回数[#] 合計時間[us]
Class read 1220 3795811
Range each 1947 4184595
Object respond_to? 157015 4378954
Array each_index 780 4507770
Hash [] 374134 4588348
PGresult ftype 4881 4771809
Class authorized_for? 7103 5178246
Object authorized_for? 9346 6037146
Object send 17835 6743344
Array each 45226 8896915
  • メソッドの CPU 使用時間の平均 (1回の呼び出しあたりの時間)
クラス メソッド 回数[#] 平均時間[us]
Class read 1219 3232
Object collect 953 3371
Object javascript_include_tag 98 3478
Object active_scaffold_include 47 5746
Array each_index 777 5767
ActiveRecord::Connection result_as_array 99 6845
Object _run_erb_app47views47la 45 10198
Object render 44 10748
ActionView::Template render_template 44 10761
PostgresPR::RowDescripti parse 117 17140

ふつうの scaffold アプリ

  • メソッドの実行時間の合計
クラス メソッド 回数[#] 合計時間[us]
Object person_path 1467 11946751
Object __send__ 5014 12988984
ActionController::UrlRew rewrite_url 2217 13000439
ActionController::UrlRew rewrite 2215 13172309
ActionController::Base url_for 2211 13883287
Object send 5352 15917858
Object polymorphic_url 1464 16378164
Object polymorphic_path 1464 16528890
Object link_to 2401 20567438
Object url_for 4617 33290132
    • メソッドの実行時間の平均 (1回の呼び出しあたりの時間)
クラス メソッド 回数[#] 平均時間[us]
Object collect 956 8772
Object render 50 9185
ActionView::Template render_template 50 9252
Array collect! 47 9534
Class read 1219 9816
Object polymorphic_url 1456 11211
Object polymorphic_path 1455 11315
ActiveRecord::Connection result_as_array 93 15871
PostgresPR::RowDescripti parse 121 27688
Object sleep 19 461348
    • メソッドの CPU 使用時間の合計
クラス メソッド 回数[#] 合計時間[us]
Object send 5366 3633977
Class read 1220 3864177
Range each 1986 3936521
Object polymorphic_url 1464 3938339
Object polymorphic_path 1463 3971707
Array each_index 781 4374570
PGresult ftype 4879 4611030
Array each 11184 4764152
Object link_to 2398 5037025
Object url_for 4624 7931197
    • メソッドの CPU 使用時間の平均 (1回の呼び出しあたりの時間)
クラス メソッド 回数[#] 平均時間[us]
Class create 1281 2666
PostgresPR::Message parse 1233 2729
Object polymorphic_url 1458 2735
Object polymorphic_path 1458 2759
PGresult initialize 150 2837
Class read 1212 3184
Object collect 944 3372
Array each_index 783 5575
ActiveRecord::Connection result_as_array 99 6782
PostgresPR::RowDescripti parse 116 15876


以下、作業ログです。
まずは ActiveScaffold の場合。

DTrace なしで ab を実行

ab -c 10 -n 50 http://127.0.0.1:3000/addressbooks
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient).....done


Server Software:        Mongrel
Server Hostname:        127.0.0.1
Server Port:            3000

Document Path:          /addressbooks
Document Length:        35564 bytes

Concurrency Level:      10
Time taken for tests:   4.241 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      1806412 bytes
HTML transferred:       1778200 bytes
Requests per second:    11.79 [#/sec] (mean)
Time per request:       848.207 [ms] (mean)
Time per request:       84.821 [ms] (mean, across all concurrent requests)
Transfer rate:          415.95 [Kbytes/sec] received

DTrace ありで ab を実行

% ab -c 10 -n 50 http://127.0.0.1:3000/addressbooks
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient).....done


Server Software:        Mongrel
Server Hostname:        127.0.0.1
Server Port:            3000

Document Path:          /addressbooks
Document Length:        35564 bytes

Concurrency Level:      10
Time taken for tests:   239.593 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      1806500 bytes
HTML transferred:       1778200 bytes
Requests per second:    0.21 [#/sec] (mean)
Time per request:       47918.642 [ms] (mean)
Time per request:       4791.864 [ms] (mean, across all concurrent requests)
Transfer rate:          7.36 [Kbytes/sec] received

メソッド呼び出しの timestamp の合計をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
0      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
0      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         SUM(us)
Mongrel::HttpResponse    send_header                    1             340
Mongrel::HttpResponse    send_status                    1             607
Time                     sec                           50             819
...
(snip)
...
Object                   sort_by                     3998         1929457
Object                   _run_erb_app47views47la       44         1947405
HashWithIndifferentAcces include?                   10045         2010132
String                   concat                    101950         2039496
Object                   render                        44         2056458
ActionView::Template     render_template               44         2059361
ActiveRecord::Connection type_cast                   1493         2077280
ActionController::Routin extra_keys                  3997         2093944
Array                    map                         8092         2117290
Object                   find                        4595         2120321
Buffer                   read                       12739         2194795
Person                   updated_at                   744         2210650
HashWithIndifferentAcces convert_value              18543         2225686
Person                   created_at                   746         2235688
ActiveSupport::TimeWithZ time                        2994         2239695
HashWithIndifferentAcces []=                         5495         2307979
Object                   active_scaffold_config     16644         2373210
String                   to_s                      131350         2447820
#<Class:0x20e0bd0>       type_oid                    4900         2475849
Module                   camelize                   12341         2479162
ActiveScaffold::Config:: sorting                     3846         2484856
ActiveSupport::TimeWithZ respond_to?                 1494         2586702
Object                   to_query                    5743         2642831
Array                    include?                   23749         2721977
Symbol                   to_s                      142001         2742388
Object                   readn                       8133         2774000
PostgresPR::RowDescripti parse                        112         2801539
HashWithIndifferentAcces initialize                  2834         2988097
ActiveScaffold::DataStru get_clause                  4496         2991373
Object                   ==                        100194         3116201
Array                    pack                       12050         3127508
Object                   read_attribute              1491         3146788
ActiveRecord::Connection connection                 10096         3155768
ActionController::Routin build_expiry                3995         3205052
HashWithIndifferentAcces dup                         2745         3232613
HashWithIndifferentAcces convert_key                31486         3268178
Class                    generated_methods?         18895         3282978
String                   gsub                      120597         3354551
ActiveSupport::Multibyte []                          1091         3369642
ActiveScaffold::DataStru sorts_on?                   4246         3425501
Module                   underscore                 12292         3503161
ActionController::Routin generate_raw                3996         3554555
ActiveSupport::CoreExten camelcase                  12291         3949552
ActionController::Routin build_query_string          3989         4085062
Object                   image_tag                    846         4098640
Object                   underscore                 12288         4151591
ActionController::Routin append_query_string         3989         4497852
Object                   loading_indicator_tag        845         4532138
BinaryReaderMixin        read_int32_network          5779         4659796
Object                   symbolize_keys              9339         4750525
Object                   params_for                  1839         4832794
HashWithIndifferentAcces default                    17737         4996812
ActionView::Base         params_for                  1839         5036220
HashWithIndifferentAcces update                      5530         5226183
ActiveScaffold::DataStru ==                         21889         5276140
PGresult                 ftype                       4887         5304703
ApplicationController    authorized_for?             2391         5387647
Array                    each_index                   782         5482011
Object                   tag_options                 4133         5573572
Object                   ru_swap                     7971         5938866
PostgresPR::DataRow      parse                        834         5962661
HashWithIndifferentAcces merge                       2688         6173230
ActiveRecord::Connection retrieve_connection_poo    20241         6393593
Module                   constantize                12331         6953826
Class                    new                        19256         7043262
Object                   truncate                    1483         7290802
Object                   constantize                12328         7598050
Hash                     each                       16886         7738805
Object                   collect                      949         7751311
Object                   inject                     15936         7957787
Object                   active_scaffold_column_     1483         8135723
PostgresPR::Message      parse                       1245         8916104
Class                    create                      1445         9248525
Object                   get_column_value            1483         9541063
Hash                     each_pair                   9565         9552417
ActiveRecord::Connection retrieve_connection        10077         9968233
Range                    each                        1936        10320188
ActionController::Routin generate                    3980        10885970
Class                    retrieve_connection        10073        11557242
Class                    read                        1215        11617862
Object                   __send__                    9130        11851207
Class                    connection                 10072        12129396
Object                   sleep                         26        12587050
ActiveScaffold::DataStru field_name                  9464        14661475
Array                    select                      9420        16179970
Hash                     []                        374137        18212681
Object                   respond_to?               157024        18807037
Class                    authorized_for?             7103        21688979
Object                   authorized_for?             9349        25392729
Array                    each                       45242        26868825
Object                   send                       17841        28908327
Total                    out                      4450882       757583541
Total                    in                       4627510       757583541

メソッド呼び出しの timestamp の平均をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
0      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
1      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         AVG(us)
Float                    +                            250              16
Time                     sec                           50              16
Fixnum                   *                            250              16
...
(snip)
...
Object                   loading_indicator_tag        843            5372
ActionController::Abstra prepare!                      50            5425
Object                   active_scaffold_column_     1484            5433
ActionController::MimeRe method_missing               250            5439
ActionController::CgiReq stale_session_check!          32            5443
ActionController::Routin recognize                     26            5446
ActionController::CgiReq session                       32            5578
Range                    each                        1950            5588
ActionController::Base   send_response                 50            5656
Array                    reverse_each                  48            5841
ActionController::Base   assign_shortcuts_withou       30            5922
Object                   get_column_value            1481            6377
Class                    create                      1448            6779
Array                    each_index                   780            6934
PostgresPR::DataRow      parse                        829            7159
Object                   assign_shortcuts              25            7196
PostgresPR::Message      parse                       1248            7599
ActionController::Base   log_processing                30            7960
Object                   collect                      956            8638
Class                    construct_calculation_s       50            8798
Class                    construct_finder_sql          50            8869
Proc                     call                         149            9095
Array                    collect!                      49            9505
Class                    read                        1222            9783
Object                   javascript_include_tag        98           15536
ActiveRecord::Connection result_as_array               97           16389
Object                   active_scaffold_include       49           24731
PostgresPR::RowDescripti parse                        119           28505
Object                   _run_erb_app47views47la       47           44197
Object                   render                        47           46681
ActionView::Template     render_template               47           46747
Object                   sleep                         24          478806

メソッド呼び出しの vtimestamp の合計をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
0      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
0      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                                    ______ ELAPSED ______
CLASS                    METHOD                   COUNT      SUM(us)
Mongrel::HttpResponse    send_header                    1             139
Mongrel::HttpResponse    send_status                    1             156
Exception                exception                     50             238
...
(snip)
...
HashWithIndifferentAcces default                    17734         1035481
Object                   params_for                  1834         1048529
ActionController::Routin build_query_string          3992         1071147
Object                   underscore                 12290         1074070
String                   gsub                      120600         1075977
Object                   loading_indicator_tag        843         1095558
ActionView::Base         params_for                  1832         1101977
HashWithIndifferentAcces update                      5527         1120125
ActionController::Routin append_query_string         3991         1130348
ActiveScaffold::DataStru ==                         21891         1136120
BinaryReaderMixin        read_int32_network          5780         1169999
Object                   symbolize_keys              9341         1272903
ActiveRecord::Connection retrieve_connection_poo    20244         1275769
ApplicationController    authorized_for?             2390         1297371
HashWithIndifferentAcces merge                       2684         1303440
Object                   tag_options                 4138         1458747
PostgresPR::DataRow      parse                        835         1497952
Object                   ru_swap                     7967         1525183
ActiveRecord::Connection retrieve_connection        10087         1660413
Module                   constantize                12327         1687978
Object                   truncate                    1485         1728485
Object                   constantize                12327         1826855
PostgresPR::RowDescripti parse                        111         1842758
Class                    retrieve_connection        10083         1892302
Class                    new                        19255         1909816
Object                   active_scaffold_column_     1483         1947303
Class                    connection                 10081         2005320
Hash                     each                       16877         2092661
Object                   inject                     15928         2142388
Object                   get_column_value            1480         2253958
Hash                     each_pair                   9568         2270442
#<Class:0x20e0bd0>       type_oid                    4900         2336779
ActiveScaffold::DataStru field_name                  9475         2359203
ActionController::Routin generate                    3980         2652835
Object                   __send__                    9129         2850685
Object                   collect                      953         3245131
PostgresPR::Message      parse                       1245         3384283
Class                    create                      1445         3461615
Array                    select                      9416         3762721
Class                    read                        1220         3795811
Range                    each                        1947         4184595
Object                   respond_to?               157015         4378954
Array                    each_index                   780         4507770
Hash                     []                        374134         4588348
PGresult                 ftype                       4881         4771809
Class                    authorized_for?             7103         5178246
Object                   authorized_for?             9346         6037146
Object                   send                       17835         6743344
Array                    each                       45226         8896915
Total                    out                      4450850       197006005
Total                    in                       4627489       197006005

メソッド呼び出しの vtimestamp の平均をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
0      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
0      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         AVG(us)
Struct::Tms              cstime                       100               4
Struct::Tms              cutime                       100               4
Struct::Tms              stime                        100               4
String                   empty?                     22750               4
...
(snip)
...
Object                   options_for_ajax             396            1057
Object                   truncate                    1487            1165
Object                   image_tag                    841            1165
ActionController::Routin recognize                     23            1187
Mongrel::HttpResponse    send_body                      2            1246
ActionController::CgiReq stale_session_check!          33            1247
Array                    reverse_each                  49            1261
ActionController::Abstra prepare!                      48            1265
Mongrel::HttpResponse    finished                       1            1275
ActionController::CgiReq session                       33            1275
Object                   loading_indicator_tag        840            1299
ActionController::Base   send_response                 48            1302
Object                   active_scaffold_column_     1487            1313
ActionController::Base   assign_shortcuts_withou       33            1331
Object                   get_column_value            1484            1525
Object                   assign_shortcuts              26            1605
ActionController::MimeRe method_missing               245            1621
Class                    digest                        50            1699
ActionController::Base   log_processing                24            1742
CGI::Cookie              initialize                    50            1791
Class                    construct_finder_sql          46            1791
PostgresPR::DataRow      parse                        836            1799
CGI::Session::CookieStor write_cookie                  50            1885
Class                    construct_calculation_s       49            1914
Array                    collect!                      49            2039
Range                    each                        1950            2135
CGI::Session::CookieStor close                         50            2158
CGI::Session             close                         50            2182
ActionController::Base   close_session                 50            2207
ActionController::Base   process_cleanup_without       50            2220
Object                   process_cleanup_without       49            2331
Object                   process_cleanup               49            2344
Class                    create                      1451            2500
Proc                     call                         145            2655
PostgresPR::Message      parse                       1253            2835
PGresult                 initialize                   149            2903
Class                    read                        1219            3232
Object                   collect                      953            3371
Object                   javascript_include_tag        98            3478
Object                   active_scaffold_include       47            5746
Array                    each_index                   777            5767
ActiveRecord::Connection result_as_array               99            6845
Object                   _run_erb_app47views47la       45           10198
Object                   render                        44           10748
ActionView::Template     render_template               44           10761
PostgresPR::RowDescripti parse                        117           17140


次にふつう scaffold の場合。

DTrace なしで ab を実行

% ab -c 10 -n 50 http://127.0.0.1:3000/people
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient).....done


Server Software:        Mongrel
Server Hostname:        127.0.0.1
Server Port:            3000

Document Path:          /people
Document Length:        15165 bytes

Concurrency Level:      10
Time taken for tests:   1.485 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      784651 bytes
HTML transferred:       758250 bytes
Requests per second:    33.67 [#/sec] (mean)
Time per request:       297.004 [ms] (mean)
Time per request:       29.700 [ms] (mean, across all concurrent requests)
Transfer rate:          515.99 [Kbytes/sec] received

DTrace ありで ab を実行

% ab -c 10 -n 50 http://127.0.0.1:3000/people
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient).....done


Server Software:        Mongrel
Server Hostname:        127.0.0.1
Server Port:            3000

Document Path:          /people
Document Length:        15165 bytes

Concurrency Level:      10
Time taken for tests:   66.607 seconds
Complete requests:      50
Failed requests:        0
Write errors:           0
Total transferred:      784750 bytes
HTML transferred:       758250 bytes
Requests per second:    0.75 [#/sec] (mean)
Time per request:       13321.302 [ms] (mean)
Time per request:       1332.130 [ms] (mean, across all concurrent requests)
Transfer rate:          11.51 [Kbytes/sec] received

メソッド呼び出しの timestamp の合計をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
1      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
1      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         SUM(us)
Thread                   initialize                     1             228
Mongrel::HttpResponse    send_header                    1             311
Mongrel::HttpResponse    send_status                    1             469
Float                    /                             50             796
...
(snip)
...
Buffer                   write                       4499          986509
Object                   pw                          2897         1023068
ActiveRecord::Connection type_cast                    749         1038280
ActiveSupport::TimeWithZ time                         742         1089951
ActionController::Routin extra_keys                  2300         1152680
ByteOrder                byteorder                   7997         1251414
ActiveSupport::TimeWithZ to_s                         741         1441976
Object                   method_javascript_funct      745         1444529
Object                   read_attribute               749         1574240
ActiveRecord::Connection result_as_array               97         1593731
ActionController::Routin generate_raw                2296         1746928
BinaryReaderMixin        read_int16_network          2194         1796596
Object                   build_named_route_call      1499         1817282
ActionController::Routin build_expiry                2297         1881047
Object                   convert_options_to_java      895         1891441
Class                    new                         7251         2057934
ERB::Util                h                           2989         2143881
Buffer                   read                       12737         2219477
Person                   created_at                   747         2226666
#<Class:0x20d8a48>       type_oid                    4900         2385054
Object                   symbolize_keys              4791         2497200
Object                   readn                       8133         2809972
Hash                     []                         84948         2934306
PostgresPR::RowDescripti parse                        119         3202265
ActionController::Routin generate                    2294         3911035
Hash                     each                        8535         3989012
Object                   inject                     10335         4439279
BinaryReaderMixin        read_int32_network          5771         4705483
PGresult                 ftype                       4886         5089918
Array                    each_index                   785         5301481
PostgresPR::DataRow      parse                        827         5972588
Object                   ru_swap                     7968         6010549
Object                   edit_person_path             733         6021765
Object                   collect                      951         8153286
ActionController::Routin generate                    2232         8989920
Object                   sleep                         22         9064493
PostgresPR::Message      parse                       1245         9326013
Class                    create                      1294         9568962
Array                    each                       11186         9880625
Range                    each                        1997        10849185
ActionController::UrlRew rewrite_path                2220        11788786
Class                    read                        1216        11942478
Object                   person_path                 1467        11946751
Object                   __send__                    5014        12988984
ActionController::UrlRew rewrite_url                 2217        13000439
ActionController::UrlRew rewrite                     2215        13172309
ActionController::Base   url_for                     2211        13883287
Object                   send                        5352        15917858
Object                   polymorphic_url             1464        16378164
Object                   polymorphic_path            1464        16528890
Object                   link_to                     2401        20567438
Object                   url_for                     4617        33290132
Total                    out                      1205969       416820493
Total                    in                       1214823       416820493

メソッド呼び出しの timestamp の平均をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000
Password:
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
0      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
0      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         AVG(us)
Float                    +                            250              15
Float                    /                             50              16
Fixnum                   <                           8550              16
...
(snip)
...
Object                   set_session_options           31            4675
ActionController::CgiReq stale_session_check!          34            5221
ActionController::UrlRew rewrite_path                2219            5293
ActionController::CgiReq session                       34            5356
ActionController::Routin recognize                     26            5357
ActionController::Abstra prepare!                      50            5385
Range                    each                        1998            5528
ActionController::Base   send_response                 50            5620
ActionController::Base   assign_shortcuts_withou       34            5684
ActionController::UrlRew rewrite_url                 2215            5845
ActionController::UrlRew rewrite                     2213            5929
Array                    reverse_each                  48            5931
ActionController::Base   url_for                     2208            6262
Object                   _run_erb_app47views47la       50            6665
Array                    each_index                   784            6777
Object                   assign_shortcuts              29            6872
Class                    construct_finder_sql          47            7189
Object                   url_for                     4605            7198
PostgresPR::DataRow      parse                        827            7224
Class                    create                      1297            7496
PostgresPR::Message      parse                       1247            7599
ActionController::Base   log_processing                30            8094
Object                   edit_person_path             734            8139
Object                   person_path                 1467            8158
Class                    construct_calculation_s       48            8272
Object                   link_to                     2394            8512
Object                   collect                      956            8772
Object                   render                        50            9185
ActionView::Template     render_template               50            9252
Array                    collect!                      47            9534
Class                    read                        1219            9816
Object                   polymorphic_url             1456           11211
Object                   polymorphic_path            1455           11315
ActiveRecord::Connection result_as_array               93           15871
PostgresPR::RowDescripti parse                        121           27688
Object                   sleep                         19          461348

メソッド呼び出しの vtimestamp の合計をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
0      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
0      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         SUM(us)
Mongrel::HttpResponse    send_header                    1              98
Mongrel::HttpResponse    send_status                    1             168
Fixnum                   <=                            50             239
...
(snip)
...
PGresult                 initialize                   148          411874
Object                   build_named_route_call      1497          441301
BinaryReaderMixin        read_int16_network          2191          454190
ActionController::Routin generate_raw                2298          459932
ActionController::Routin build_expiry                2294          477907
ERB::Util                h                           2992          491816
Array                    map                         2447          497894
Person                   created_at                   743          545922
Buffer                   read                       12740          612775
ActiveRecord::Connection result_as_array               98          667425
Object                   symbolize_keys              4790          679480
Object                   readn                       8132          746697
Hash                     []                         84950          803011
ActionController::Routin generate                    2295          873134
Class                    new                         7256          874521
Hash                     each                        8536         1085655
BinaryReaderMixin        read_int32_network          5762         1176401
Object                   inject                     10336         1205810
Object                   edit_person_path             735         1416156
PostgresPR::DataRow      parse                        821         1483268
Object                   ru_swap                     7956         1537059
PostgresPR::RowDescripti parse                        113         1738528
ActionController::Routin generate                    2231         2079986
#<Class:0x20d8a48>       type_oid                    4900         2260592
ActionController::UrlRew rewrite_path                2224         2765001
Object                   person_path                 1474         2863491
Object                   collect                      938         2984373
ActionController::UrlRew rewrite_url                 2223         3055872
ActionController::UrlRew rewrite                     2223         3081932
Object                   __send__                    5024         3082082
ActionController::Base   url_for                     2221         3212055
PostgresPR::Message      parse                       1233         3264624
Class                    create                      1282         3318057
Object                   send                        5366         3633977
Class                    read                        1220         3864177
Range                    each                        1986         3936521
Object                   polymorphic_url             1464         3938339
Object                   polymorphic_path            1463         3971707
Array                    each_index                   781         4374570
PGresult                 ftype                       4879         4611030
Array                    each                       11184         4764152
Object                   link_to                     2398         5037025
Object                   url_for                     4624         7931197
Total                    out                      1205922       118370056
Total                    in                       1214781       118370056

メソッド呼び出しの vtimestamp の平均をトレースした結果

% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000
dtrace: script 'rb_functime_ext2.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
1      1                           :BEGIN Tracing... Hit Ctrl-C to end.

^C
0      2                             :END ELAPSED TIME DISTRIBUTION,
___ OVERLAP TIMES: ___                              ______ ELAPSED ______
CLASS                    METHOD                     COUNT         AVG(us)
Fixnum                   <=>                          150               4
Fixnum                   >                          22100               4
Struct::Tms              cutime                       100               4
...
(snip)
...
Object                   set_session_options           37            1012
Object                   stylesheet_link_tag           50            1042
ActionController::Abstra prepare!                      49            1179
ActionController::Routin recognize                     20            1198
ActionController::Base   send_response                 49            1215
Array                    reverse_each                  49            1260
ActionController::CgiReq stale_session_check!          27            1263
ActionController::UrlRew rewrite_path                2224            1273
ActionController::CgiReq session                       26            1293
ActionController::Base   assign_shortcuts_withou       26            1353
ActionController::UrlRew rewrite_url                 2221            1404
ActionController::UrlRew rewrite                     2220            1416
ActionController::Base   url_for                     2219            1476
Class                    construct_finder_sql          49            1509
Object                   _run_erb_app47views47la       49            1585
Object                   assign_shortcuts              20            1642
Class                    construct_calculation_s       48            1727
Object                   url_for                     4621            1743
CGI::Cookie              initialize                    50            1748
ActionController::Base   log_processing                35            1761
PostgresPR::DataRow      parse                        820            1806
CGI::Session::CookieStor write_cookie                  50            1844
Object                   edit_person_path             739            1924
Object                   person_path                 1467            1988
Array                    collect!                      47            2045
Object                   link_to                     2397            2068
Range                    each                        1993            2077
CGI::Session::CookieStor close                         50            2110
CGI::Session             close                         50            2136
Object                   render                        49            2149
ActionController::Base   close_session                 50            2160
ActionView::Template     render_template               49            2161
ActionController::Base   process_cleanup_without       50            2172
Object                   process_cleanup_without       50            2265
Object                   process_cleanup               50            2279
Object                   sleep                         36            2496
Class                    create                      1281            2666
PostgresPR::Message      parse                       1233            2729
Object                   polymorphic_url             1458            2735
Object                   polymorphic_path            1458            2759
PGresult                 initialize                   150            2837
Class                    read                        1212            3184
Object                   collect                      944            3372
Array                    each_index                   783            5575
ActiveRecord::Connection result_as_array               99            6782
PostgresPR::RowDescripti parse                        116           15876