負荷テスト(Grails 0.5)
以前、やろうとしていたスループットのテストをやってみる。groovy-all-1.1-BEATA-1.jarをgroovy-all-1.1-BETA-2-SNAPSHOT.jarに入れ替えて実行した。実行したアプリケーションはこんな感じ。
まず、コントローラ
class Test01Controller { def index = { render """ <html> <head> <title>Hello</title> </head> <body> Hello World </body> </html> """ } def view = { render(view:'hello') } def layout = { render(view:'hellolayout') } }
views/test01/hello.gspはこんな感じ
<html> <head> <title>Hello</title> </head> <body> Hello World </body> </html>
views/test01/hellolayout.gspはこんな感じ
<html> <head> <meta name="layout" content="simple" /> </head> <body>Hello World</body> </html>
views/layouts/simple.gspはこんな感じだ。
<html> <head> <title>Hello</title> <g:layoutHead /> </head> <body> <g:layoutBody /> </body> </html>
何がやりたいかと言うと、
- コントローラのrenderでHTML出力した場合
- GSPでHTML出力した場合(レイアウトなし)
- GSPでHTML出力した場合(レイアウトあり)
でどの程度の違いがあるのか、ということだ。
テストは、grails war でWARファイルを作成して、Tomcat 6.0.13にデプロイし、最初に対象URLをブラウザで表示して、その後ApacheBenchで負荷をかけることとした。
最初に、コントローラのrenderで出力した場合のテスト結果はこんな感じだった。
第1回目
$ ab -c 100 -n 10000 http://localhost:8080/pagetest-0.1/test01
This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright 2006 The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Server Software: Apache-Coyote/1.1
Server Hostname: localhost
Server Port: 8080
Document Path: /pagetest-0.1/test01
Document Length: 90 bytes
Concurrency Level: 100
Time taken for tests: 26.640011 seconds
Complete requests: 10000
Failed requests: 1
(Connect: 0, Length: 1, Exceptions: 0)
Write errors: 0
Non-2xx responses: 1
Total transferred: 2891115 bytes
HTML transferred: 901010 bytes
Requests per second: 375.38 [#/sec] (mean)
Time per request: 266.400 [ms] (mean)
Time per request: 2.664 [ms] (mean, across all concurrent requests)
Transfer rate: 105.97 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 6 17.4 1 301
Processing: 12 256 155.7 210 1394
Waiting: 7 248 154.9 204 1392
Total: 36 263 154.6 215 1419
Percentage of the requests served within a certain time (ms)
50% 215
66% 264
75% 304
80% 335
90% 459
95% 559
98% 752
99% 918
100% 1419 (longest request)続けて2度目
$ ab -c 100 -n 10000 http://localhost:8080/pagetest-0.1/test01 This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0 Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Copyright 2006 The Apache Software Foundation, http://www.apache.org/ Benchmarking localhost (be patient) Total of 6052 requests completed
むむむ、タイムアウトしてしまった。Tomcatの方はというと、OutOfMemoryErrorが出ている。ま、原因は予想がつくのだが。
Tomcatを再起動して、GSP(レイアウトなし)のテスト。
1回目
$ ab -c 100 -n 10000 http://localhost:8080/pagetest-0.1/test01/view
This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright 2006 The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Server Software: Apache-Coyote/1.1
Server Hostname: localhost
Server Port: 8080
Document Path: /pagetest-0.1/test01/view
Document Length: 97 bytes
Concurrency Level: 100
Time taken for tests: 59.736206 seconds
Complete requests: 10000
Failed requests: 0
Write errors: 0
Total transferred: 3600000 bytes
HTML transferred: 970000 bytes
Requests per second: 167.40 [#/sec] (mean)
Time per request: 597.362 [ms] (mean)
Time per request: 5.974 [ms] (mean, across all concurrent requests)
Transfer rate: 58.84 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 5.4 0 128
Processing: 95 593 340.9 480 3809
Waiting: 77 590 339.4 477 3808
Total: 130 594 341.0 480 3812
Percentage of the requests served within a certain time (ms)
50% 480
66% 584
75% 677
80% 748
90% 967
95% 1227
98% 1588
99% 1920
100% 3812 (longest request)2回目はハングして返ってこなかった(ように見えた)ので強制終了した。
再度Tomcatを再起動(停止中にOutOfMemoryError発生)してGSP(レイアウトあり)のテスト。
1回目
$ ab -c 100 -n 10000 http://localhost:8080/pagetest-0.1/test01/layout
This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright 2006 The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Server Software: Apache-Coyote/1.1
Server Hostname: localhost
Server Port: 8080
Document Path: /pagetest-0.1/test01/layout
Document Length: 140 bytes
Concurrency Level: 100
Time taken for tests: 169.166464 seconds
Complete requests: 10000
Failed requests: 0
Write errors: 0
Total transferred: 4040000 bytes
HTML transferred: 1400000 bytes
Requests per second: 59.11 [#/sec] (mean)
Time per request: 1691.665 [ms] (mean)
Time per request: 16.917 [ms] (mean, across all concurrent requests)
Transfer rate: 23.32 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 3.4 0 55
Processing: 28 1681 7113.9 632 72432
Waiting: 27 1678 7112.7 630 72432
Total: 71 1682 7113.8 633 72432
Percentage of the requests served within a certain time (ms)
50% 633
66% 970
75% 1277
80% 1546
90% 2174
95% 3014
98% 5148
99% 71387
100% 72432 (longest request)2回目はやはりハングしたように見えるほど遅かったので強制終了した。同様にOutOfMemoryErrorが発生した。
回数を重ねると遅く、メモリを消費していくのは多分HttpSessionのせいだろう。
しかし、Cookieが使えないクライアントから毎秒1000以上のリクエストが来るようなサイトでGrailsが果たして使えるのか？ということが実は最大の関心事なのだけれども。
一応、最初のテスト(コントローラのrenderでHTMLを出力)をプロファイラで調べてみた。やはりメモリを圧迫しているのはHttpSessionのインスタンスのようだ。1セッションで1800バイトくらい使っているようだ。確かにデフォルトのメモリ設定だと、20000セッションは厳しいかもしれない。
次に、CPU時間の結果を見てみた。全体の63.8%がSimpleGrailsControllerHelper#handleURI()で消費されている。そのうち、SimpleGrailsControllerHelper#getControllerInstance()で実に39.1%を消費している。SimpleGrailsControllerHelper#handleAction()が9.1%の消費となっているので、コントローラの実行の実に4倍のCPU時間を消費していることになる。まあ、今回のコントローラは殆ど何もしていないので、こんな結果になったのではないかと思われる。なお、SimpleGrailsControllerHelper#getControllerInstance()の消費時間はクロージャの数に比例するようだ。
次にGSPでHTML出力した場合(レイアウトなし)の場合のプロファイルを取る。
ここで新たに登場してくるのが、全体の40.2%のCPU時間を消費しているGrailsLayoutDecoratorMapper#getNamedDecorator()だ。これが増えたおかげで先ほどのSimpleGrailsControllerHelper#handleURI()の消費時間が26.6%まで落ちた。このメソッドは結果をキャッシュできるような気がするなぁ(少なくともProductionでは)。
ソースを見てみると、
public Decorator getNamedDecorator(HttpServletRequest request, String name) { if(StringUtils.isBlank(name))return null; if(decoratorMap.containsKey(name)) { return (Decorator)decoratorMap.get(name); } else { String decoratorName = name; if(!name.matches("(.+)(\\.)(\\w{2}|\\w{3})")) { name += DEFAULT_VIEW_TYPE; } String decoratorPage = DEFAULT_DECORATOR_PATH + '/' + name; ResourceLoader resourceLoader = establishResourceLoader(); Resource res = resourceLoader.getResource(decoratorPage); if(!res.exists()) { PathMatchingResourcePatternResolver matcher = new PathMatchingResourcePatternResolver(resourceLoader); String pattern = GrailsResourceUtils.WEB_INF + "/plugins/*/grails-app/views/layouts/" + name; if(LOG.isDebugEnabled()) LOG.debug("No decorator found at " + decoratorPage+". Trying plug-ins with pattern: " + pattern); try { Resource[] layouts = matcher.getResources(pattern); if(layouts.length>0) { if(layouts.length>1) { LOG.warn("Multiple matching layouts found in plug-ins for name ["+name+"] using first from ["+ ArrayUtils.toString(layouts) +"]"); } String url = layouts[0].getURL().toString(); url = GrailsResourceUtils.WEB_INF + url.substring(url.indexOf("/plugins"),url.length()); Decorator d = new DefaultDecorator(name, request.getRequestURI(), url, Collections.EMPTY_MAP); decoratorMap.put(decoratorName, d); return d; } } catch (IOException e) { // ignore, if there was a problem here its going to be a FNFE which is ok } return null; } else { if(LOG.isDebugEnabled()) LOG.debug("Using decorator " + decoratorPage); Decorator d = new DefaultDecorator(decoratorName,request.getRequestURI(),decoratorPage, Collections.EMPTY_MAP); decoratorMap.put(decoratorName,d); return d; } } }
をを、キャッシュしているぞ。ただし、見つかったものだけだな。return nullのものに関してはキャッシュしていないということか。確かに妥当な気もする。nameとして与えられるパラメタの内容が有限ならばネガティブキャッシュしてもよさそうだが。
最後にGSPでHTML出力した場合(レイアウトあり)の場合。
新たに登場するのは、GrailsPageFilter#applyDecorator()だ(31.7%)。これはレイアウトGSPページを実行するのだから当然といえば当然か。逆にGrailsLayoutDecoratorMapper#getNamedDecorator()は姿を消した。おそらく、レイアウトが指定されているので何も検索しないのだろう。ちなみに、SimpleGrailsControllerHelper#handleURI()は、32.2%のCPU消費時間となっている。
むぅ、劇的なパフォーマンスアップは望めないかも。。。
