丁稚な日々

Rubyで遊んだ日々の記録。あくまで著者視点の私的な記録なので、正確さを求めないように。
Rubyと関係ない話題にはその旨注記しているはず。なので、一見関係無いように見える話題もどこかで関係あるのかもしれません。または、注記の書き忘れかもしれません...

[直前] [最新] [直後] [Top]

Sep.24,2009 (Thu)

Revision: 1.1 (Sep.24,2009 12:43)

[mswin32] select

_ 先日に続いて、1.8の方は、先日の改修時に入れちゃったバグ1点と、p173のあたりからあったらしいIO.select(nil, nil, nil, 0)が結構な確率で遅くなる問題を修正してみた。
前者はともかく、後者は例の問題と関係あるかもしれない。ないかもしれないけど。

Sep.25,2009 (Fri)

Revision: 1.5 (Sep.25,2009 11:27)

[mswin32] 1.8 select問題の確認

_ InstantRailsを使って、問題の現象を確認してみることにした。

静的ページの場合

_ ベンチマークにはApacheのabを使用。1000リクエストで試すことにした。

_ まず、InstantRails 2.0添付のruby(1.8.6-p111)から。

Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /
Document Length:        7557 bytes

Concurrency Level:      1
Time taken for tests:   3.360000 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      7750000 bytes
HTML transferred:       7557000 bytes
Requests per second:    297.62 [#/sec] (mean)
Time per request:       3.360 [ms] (mean)
Time per request:       3.360 [ms] (mean, across all concurrent requests)
Transfer rate:          2252.38 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.5      0       1
Processing:     2    3   2.7      3      50
Waiting:        1    1   2.8      2      48
Total:          2    3   2.7      3      50

Percentage of the requests served within a certain time (ms)
  50%      3
  66%      3
  75%      3
  80%      3
  90%      4
  95%      4
  98%      4
  99%      4
 100%     50 (longest request)

実行してから気づいたけど、Rails動かしてるマシンと同じマシンでab動かすのはどうなのよ、って感じだな。ま、傾向見るのが目的だからいいか。

_ 続いて、InstantRailsのrubyを1.8.7-p174で上書きして再実験。最初の方は毎回同じなので省く。

Concurrency Level:      1
Time taken for tests:   13.518000 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      7750000 bytes
HTML transferred:       7557000 bytes
Requests per second:    73.98 [#/sec] (mean)
Time per request:       13.518 [ms] (mean)
Time per request:       13.518 [ms] (mean, across all concurrent requests)
Transfer rate:          559.85 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.7      0       2
Processing:     3   12   3.3     13      60
Waiting:        2   11   3.0     12      59
Total:          4   13   3.2     14      60

Percentage of the requests served within a certain time (ms)
  50%     14
  66%     14
  75%     14
  80%     14
  90%     14
  95%     15
  98%     15
  99%     16
 100%     60 (longest request)

確かに速度は落ち込んでるが、1/4程度。確かに問題ではあるが、世間の人が言うほど劇的でもないんだよなあ。1/100になるとかいう話もあったんだけど。
document rootで試してるのがよくないのかなあ。まあいいや。

_ さて、これをさらにruby_1_8 HEAD(1.8.8dev r23613)に置き換えるとどうなるか。

Concurrency Level:      1
Time taken for tests:   3.266000 seconds
Complete requests:      1000
Failed requests:        0
Write errors:           0
Total transferred:      7750000 bytes
HTML transferred:       7557000 bytes
Requests per second:    306.18 [#/sec] (mean)
Time per request:       3.266 [ms] (mean)
Time per request:       3.266 [ms] (mean, across all concurrent requests)
Transfer rate:          2317.21 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.4      0       1
Processing:     2    2   2.5      3      46
Waiting:        1    1   1.7      1      35
Total:          2    3   2.3      3      46

Percentage of the requests served within a certain time (ms)
  50%      3
  66%      3
  75%      3
  80%      3
  90%      3
  95%      4
  98%      4
  99%      4
 100%     46 (longest request)

はい、事実上、元(1.8.6-p111)と同じ速度に戻りました、と。

動的ページの場合

_ これじゃ意味がないかもしれないので、scaffoldで適当なModel/View/Controllerを生成して再確認。
今度はさすがに遅いので、100リクエストで実験。

_ まず1.8.6-p111から。

Server Software:        Mongrel
Server Hostname:        localhost
Server Port:            3000

Document Path:          /samples
Document Length:        582 bytes

Concurrency Level:      1
Time taken for tests:   8.591000 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      104600 bytes
HTML transferred:       58200 bytes
Requests per second:    11.64 [#/sec] (mean)
Time per request:       85.910 [ms] (mean)
Time per request:       85.910 [ms] (mean, across all concurrent requests)
Transfer rate:          11.87 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.6      0       1
Processing:    69   85  72.5     72     783
Waiting:       68   84  72.5     71     782
Total:         70   85  72.6     72     784

Percentage of the requests served within a certain time (ms)
  50%     72
  66%     73
  75%     74
  80%     75
  90%    121
  95%    125
  98%    129
  99%    784
 100%    784 (longest request)

うわー、動的ページは遅いなー。ほとんど中身ないページなのに(DBが空だから)、静的ページの1/25ですかい。

_ 続いて1.8.7-p174。

Concurrency Level:      1
Time taken for tests:   14.697000 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      104600 bytes
HTML transferred:       58200 bytes
Requests per second:    6.80 [#/sec] (mean)
Time per request:       146.970 [ms] (mean)
Time per request:       146.970 [ms] (mean, across all concurrent requests)
Transfer rate:          6.94 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.6      0       1
Processing:   126  146  75.8    132     877
Waiting:      126  145  75.9    132     877
Total:        126  146  75.9    133     878

Percentage of the requests served within a certain time (ms)
  50%    133
  66%    135
  75%    137
  80%    138
  90%    181
  95%    185
  98%    191
  99%    878
 100%    878 (longest request)

1.8.6-p111と比べてだいたい1/1.7の速度。静的ページの場合と比べてむしろ遅さが圧縮された。意味なかったなこのベンチ。

_ いちおう、最後に1.8.8dev r23613。

Concurrency Level:      1
Time taken for tests:   8.755000 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      104600 bytes
HTML transferred:       58200 bytes
Requests per second:    11.42 [#/sec] (mean)
Time per request:       87.550 [ms] (mean)
Time per request:       87.550 [ms] (mean, across all concurrent requests)
Transfer rate:          11.65 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.5      0       1
Processing:    53   87 252.3     55    2580
Waiting:       51   86 252.3     55    2579
Total:         53   87 252.4     56    2581

Percentage of the requests served within a certain time (ms)
  50%     56
  66%     56
  75%     58
  80%     61
  90%    104
  95%    105
  98%    118
  99%   2581
 100%   2581 (longest request)

はい、実質的に元通りの速度ですよ、と。

まとめ

_ というわけで、当方で観測できる限りでは、この問題は解決したってことで。

Sep.29,2009 (Tue)

Revision: 1.1 (Sep.30,2009 02:04)

被捕捉アンテナ類
[Ant] [Antenna-Julia] [Rabbit's Antenna] [Ruby hotlinks]