TracLightningのチューニング方法について
jun66j5 そんなに遅いのは何かおかしい気がしますね…。ざっと確認したいのが…、
こんなところでしょうか。
jun66j5が既にコメントしてますが、思い当たるところを書いておきます(まずはjun66j5さんのコメントを試してもらうのがいいと思います)。
あと、秒間のアクセス頻度はどのくらいでしょうか?CPU使用率が40～70%だと、かなりアクセスがあるのではないかと思います。
早速の情報ありがとうございました。確認できたところからご返答させていただきます。
なお、TracLightningはVM環境ではありません。物理HWにインストールしています。
CPU Xeon 2.4GHz
RAM 3GiB
Windows Server 2008 STD SP2(32bit)
すいません。いろいろ調べているうちに思い出したのですが、以下のようなエラーが1時間あたり多いと10件くらい記録されていました。
しかし、影響がなさそうに見えたため、すっかり問題なしと思い込んでいました。
Fork日時 : 2011/09/20 8:56:10
イベントの種類 : エラー
コンピュータ :
ユーザー : N/A
ソース : d:\traclight\projects\trac\●●●●
カテゴリー : 0 (0)
イベントID : 1
Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
File "build\bdist.win32\egg\trac\web\main.py", line 511, in _dispatch_request
dispatcher.dispatch(req)
File "build\bdist.win32\egg\trac\web\main.py", line 202, in dispatch
chosen_handler)
File "build\bdist.win32\egg\trac\web\main.py", line 344, in _pre_process_request
chosen_handler = filter_.pre_process_request(req, chosen_handler)
File "build\bdist.win32\egg\acct_mgr\web_ui.py", line 827, in pre_process_request
if not req.session.authenticated:
File "build\bdist.win32\egg\trac\web\api.py", line 216, in __getattr__
value = self.callbacks[name](self)
File "build\bdist.win32\egg\trac\web\main.py", line 300, in _get_session
return Session(self.env, req)
File "build\bdist.win32\egg\trac\web\session.py", line 192, in __init__
if req.authname == 'anonymous':
File "build\bdist.win32\egg\trac\web\api.py", line 216, in __getattr__
value = self.callbacks[name](self)
File "build\bdist.win32\egg\trac\web\main.py", line 159, in authenticate
authname = authenticator.authenticate(req)
File "build\bdist.win32\egg\trac\web\auth.py", line 83, in authenticate
authname = self._get_name_for_cookie(req, req.incookie['trac_auth'])
File "build\bdist.win32\egg\trac\web\auth.py", line 209, in _get_name_for_cookie
db = self.env.get_db_cnx()
File "build\bdist.win32\egg\trac\env.py", line 328, in get_db_cnx
return get_read_db(self)
File "build\bdist.win32\egg\trac\db\api.py", line 90, in get_read_db
return _transaction_local.db or DatabaseManager(env).get_connection()
File "build\bdist.win32\egg\trac\db\api.py", line 152, in get_connection
return self._cnx_pool.get_cnx(self.timeout or None)
File "build\bdist.win32\egg\trac\db\pool.py", line 226, in get_cnx
return _backend.get_cnx(self._connector, self._kwargs, timeout)
File "build\bdist.win32\egg\trac\db\pool.py", line 146, in get_cnx
raise TimeoutError(errmsg)
TimeoutError: 0秒内にデータベースに接続できませんでした。
日時 : 2011/09/20 8:53:46
イベントの種類 : エラー
コンピュータ :
ユーザー : N/A
ソース : d:\traclight\projects\trac\●●●●
カテゴリー : 0 (0)
イベントID : 1
Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
File "build\bdist.win32\egg\trac\web\main.py", line 511, in _dispatch_request
dispatcher.dispatch(req)
File "build\bdist.win32\egg\trac\web\main.py", line 261, in dispatch
req.send(output, content_type or 'text/html')
File "build\bdist.win32\egg\trac\web\api.py", line 416, in send
self.write(content)
File "build\bdist.win32\egg\trac\web\api.py", line 536, in write
self._write(data)
IOError: failed to write data
日時 : 2011/09/17 17:00:02
イベントの種類 : エラー
コンピュータ :
ユーザー : N/A
ソース : d:\traclight\projects\trac\●●●●
カテゴリー : 0 (0)
イベントID : 1
Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
File "build\bdist.win32\egg\trac\web\main.py", line 511, in _dispatch_request
dispatcher.dispatch(req)
File "build\bdist.win32\egg\trac\web\main.py", line 237, in dispatch
resp = chosen_handler.process_request(req)
File "build\bdist.win32\egg\trac\versioncontrol\web_ui\browser.py", line 393, in process_request
file_data = self._render_file(req, context, repos, node, rev)
File "build\bdist.win32\egg\trac\versioncontrol\web_ui\browser.py", line 652, in _render_file
req.write(chunk)
File "build\bdist.win32\egg\trac\web\api.py", line 536, in write
self._write(data)
IOError: failed to write data
最初のエラーメッセージを見て思い出したのですが、アクセスが多すぎてDBのアクセスが 追いつかなく処理が重くなることはありますね。
pool.pyの
_pool_size = int(os.environ.get('TRAC_DB_POOL_SIZE', 10))
の部分で、コネクションのプールサイズを設定しているので、ここを大きく(100とかに) すると改善されるかも知れません。
上記の記録されているエラーに問題ありでしたら、そもそもチューニングの話ではなかったかもしれませんね……。
>2.有効になっているプラグインや設定を確認したいので trac.ini と httpd.conf を添付してもらえないでしょうか?
上記、添付いたしました。
>3.レスポンスが遅い時がある…ではなくて常に遅いでしょうか?
今日はあまり問題なかったとのことで、常に遅いわけではないようです。
よろしくお願いします。
jun66j5 trac.ini や httpd.conf は特に問題ないと思います。
それで Windows 環境の Apache + mod_wsgi は1プロセス・マルチスレッドで実行されます。同時に実行されるスレッドは GIL により1つなので CPU が1コア分以下しか使えていないのはそういうものです。ちなみに Apache Bench で concurrent 4 にして /wiki/WikiStart にアクセスさせたら concurrent 1 のときの4倍近い時間がかかってました。
この環境下で残されたチューニングは、個々のプラグインが持っている静的ファイルを Trac に処理させないで Apache で返すようにすれば、その分 Python に処理が流れないので少し早くなると思います (F5 でリロードしたがる人には有効)。
これを施してもデータベースに接続できないエラーが出るようでしたら、環境変数 TRAC_DB_POOL_SIZE を使ってサイズを大きくしてみてください。
手順:
python\Scripts\easy_install.exe -Z egg\Babel-0.9.5-py2.6.egg ....
python\python.exe chrome-paths.py > CollabNetSVN\httpd\conf\chrome-paths.conf
Include conf/chrome-paths.conf
別案としては IIS7, fastcgi で複数プロセスでサービスさせるとか、VirtualBox などで Linux を入れて Kanon でサービスするとかのほうがマシな気がしなくもないです。
>jun66j5さん
>okamototkさん
情報ありがとうございました！
TRAC_DB_POOL_SIZEですが、SQLiteのデットロックがでてサービスを再起動しないとTracにアクセスできない現象が2.4系の頃に多発していたため、100に変更済みでした。3.1.2にバージョンアップしたときも念のために100に設定していましたが、まだ足りないとの可能性があるようなので500まであげてみました。
IIS7への変更など、あまり変更してしまうとTracLightningのバージョンアップに追随できなくなりそうなので、悩ましいところですね。いただいた情報を検討してみます。できれば、別の環境でテストしてみます。
次回はkanonを検討するか、少なくともCPUはクロック数の高いものを選定するようにします。マルチコアはいきないんですね、勉強になりました。
>jun66j5さん
テストのためWin2003 + Trac Lightning 3.1.2で適用してみたのですが、うまくいきませんでした。
プロジェクトの一覧画面までは表示されるのですが、プロジェクト名をクリックすると、下記のようなエラーが表示されてしまいました。
Traceback (most recent call last):
File "build\bdist.win32\egg\trac\web\api.py", line 440, in send_error
data, 'text/html')
File "build\bdist.win32\egg\trac\web\chrome.py", line 833, in render_template
data = self.populate_data(req, data)
File "build\bdist.win32\egg\trac\web\chrome.py", line 756, in populate_data
'locale': req and req.locale,
File "build\bdist.win32\egg\trac\web\api.py", line 216, in __getattr__
value = self.callbacks[name](self)
File "build\bdist.win32\egg\trac\web\main.py", line 311, in _get_locale
req.languages)
File "build\bdist.win32\egg\trac\util\translation.py", line 347, in get_negotiated_locale
normalize(get_available_locales()), sep='-')
File "build\bdist.win32\egg\babel\core.py", line 185, in negotiate
return Locale.parse(identifier, sep=sep)
File "build\bdist.win32\egg\babel\core.py", line 212, in parse
return cls(*parse_locale(identifier, sep=sep))
File "build\bdist.win32\egg\babel\core.py", line 137, in __init__
raise UnknownLocaleError(identifier)
UnknownLocaleError: unknown locale 'ja'
もう一度やりなおしたのですがダメで、ダメもとで次の変更を行いました。easy_installの展開先がDocument and Settings\Administrator\Application Data\Pyhon-Eggs\以下に書き出されていました。
フォルダをTracLightning用フォルダ以下にフォルダを作って移動。chrome-paths.confのファイルパスを上記にあわせ修正したくらいです。
お忙しいところすみませんが、アドバイスいただけると幸いです。
jun66j5 生成した chrome-paths.conf の中に %USERPROFILE%\Application Data\Python-Eggs があるということは python\lib\site-packages にある egg ファイルを展開した状態になっていないのではないでしょうか (setuptools-0.6c11-py2.6.egg は除く)。なんとなく -Z オプションを最初の1行にだけ付けた、もしくは traclightning サービスが起動していて書き換えに失敗したのかどちらかのような気がします。実行前に traclightning サービスは停止させてみてください。
あと、念のため 3.1.2 から抜き出した egg\install-eggs.cmd に -Z を書きたしたファイルを添付しておきました。
これを実行したあとに python\lib\site-packages\ 配下に setuptools-0.6c11-py2.6.egg 以外の *.egg ファイルがすべてディレクトリになっていない場合は何かに失敗しています。
どうしてもうまく行かないようでしたら egg\install-eggs.cmd >install-eggs.log 2>&1 で実行結果をいただけますか?
>jun66j5さん
アドバイスありがとうございました。うまく動作するようになりました。本当にありがとうございました！
install-eggs.cmdですが、オプションをzとしていました。Zに修正したところ、正しく動作するようになりました。
ちなみに、今後TracLightningをバージョンアップした場合、基本的にはバージョンアップ作業後に上記の egg ファイルを展開、chrome-paths.confの更新、サービスの再起動をすれば動作するはずですよね?
万一、ダメならhttpd.confを元に戻す、と。
参考までにApache Benchの結果です。別セグメントのWin 2003 R2（他に稼働しているサービスあり）+TracLightning3.1.2に対して、リクエスト 100 同時接続 10でSample ProjectのTOP（wiki）にアクセスしました。それぞれ3回テストし、効果を確認できました。
・標準の状態
Requests per second: 2.57～2.72 [#/sec]
・TRAC_DB_POOL_SIZE=500
Requests per second: 2.83～2.86 [#/sec]
・POOL_SIZE=500 + eggファイルを展開
Requests per second: 3.11～3.14 [#/sec]
jun66j5 ちなみに、今後TracLightningをバージョンアップした場合、基本的にはバージョンアップ作業後に上記の egg ファイルを展開、chrome-paths.confの更新、サービスの再起動をすれば動作するはずですよね?
万一、ダメならhttpd.confを元に戻す、と。
はい。それで問題ないです。
ちなみに 3.1.3 以降は egg ファイルは展開した状態でインストールするようにしています (最近変更しました)。 なので 3.1.3 以降の場合は chrome-paths.conf 生成以降の手順を行なってもらえればよいです。
それと、別のプラグインを導入するときは -Z オプション付きで easy_install を実行し、chrome-paths.conf を再生成するとよいです。
参考までにApache Benchの結果です。別セグメントのWin 2003 R2（他に稼働しているサービスあり）+TracLightning3.1.2に対して、リクエスト 100 同時接続 10でSample ProjectのTOP（wiki）にアクセスしました。それぞれ3回テストし、効果を確認できました。
...
少し早くなっていますね。これは egg ファイルを展開した効果だと思います。
chrome-paths.conf の効果は、ブラウザを使ってアクセスしたときに *.{css,js} などの静的ファイルを早く返却することで、その分早くなったように感じることを期待しています。
>jun66j5さん
>okamototkさん
ご返答ありがとうございました。非常に助かりました。プラグインなどOFFにできそうなものがあれば、OFFにしてみます。
今後ともよろしくお願いします。
今更ですが、もう少し改善しましたのでご報告だけさせて下さい。
Windows 2003 R2でPOOL_SIZE=1000にし、eggファイルを展開してベンチをとりました。
・POOL_SIZE=1000 + eggファイルを展開
Requests per second: 約5 #/sec （/newticket に対して実施）
というところまで改善しました。ただ、OSがWindows 2008では変わらず3でした。 また、POOL_SIZEを3000まであげてみましたが、5以上にはなりませんでした。 ※POOL_SIZEをこんなに大きくしていいのかという疑問もありますが。
ご指摘の通り、KanonをPCにインストールしてベンチとったら15以上でました。
TracLightning3.1.2を使用させていただいています。2～3ヶ月ほど前にTracの使用頻度が高いこともあり、Trac専用のサーバーを購入・移行するのと同時にTracLightning2.4系からバージョンアップしました。
このところ、チケットやwikiを表示するのに時間がかかる（4秒以上）との相談が続いているため、何とか改善を行いたいのですがの良いチューニング方法はありますでしょうか？よろしくお願いいたします。
ひとまず、OS（Windows Server 2008）での対応として、httpdのプロセスの優先度を通常から高に変更してみました。若干、レスポンスがよくなったように思いますが、状況はあまり変わっていません。また、CPU利用率も1つのコアだけに偏ってしまっており、5分平均で40～70%の使用率のコア以外は数%しか使用していませんでした。