ちょっと前に、性能をみるために用意した 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 |
| クラス |
メソッド |
回数[#] |
合計時間[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 |
| クラス |
メソッド |
回数[#] |
合計時間[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
