- PR -

lg4j のローテーション時にアプリが固まる

1|2 次のページへ»
投稿者投稿内容
ねま
会議室デビュー日: 2004/11/10
投稿数: 18
投稿日時: 2005-02-18 16:25
log4j について質問です。

アプリケーション(※1)がときどき数秒間かたまるという症状が発生しており、
調査したところ、ログのローテーションのタイミングで起きている事がわかりました。

ログ出力には、log4j を使用しており、ファイルサイズ 10MB, 履歴 300個。
ログ出力先は、外付け USB HDD という設定で運用しています。
(文末に lo4j.properties を載せました。)

ログのローテーション時には、ファイルのリネームしかしないと思うのですが、
300ファイルのリネームってそんなに時間がかかるものなのでしょうか？

log4j を使用していて、皆さんはそういう経験がありますでしょうか？
また、そのときどういう運用方法で対応したのでしょうか？

やりたいことは、↓の2つです。
[1] ログは 最大容量 5GB 程度までは保存したい。
[2] ログローテーションのタイミングでアプリが固まることのないようにしたい。


例えば、ファイルサイズをもっと大きくとり、履歴数を減らすという
チューニング方法もありそうですが、ファイルサイズが大きくなりすぎると
今度は人間が見るとき困る気がします。適度な設定を見つけるという
アナログなチューニング方法しかないのでしょうか？


※1.windowアプリです。webアプリではありません

--[log4j.properties]-----------------------------------------------------------
# log4j configuration file
log4j.rootCategory=DEBUG, APPLOG

log4j.appender.APPLOG=org.apache.log4j.RollingFileAppender
log4j.appender.APPLOG.File=e:/log/app/app.log

log4j.appender.APPLOG.MaxFileSize=10000KB
log4j.appender.APPLOG.MaxBackupIndex=300
log4j.appender.APPLOG.layout=org.apache.log4j.PatternLayout
log4j.appender.APPLOG.layout.ConversionPattern=%d{yyyy/MM/dd HH:mm:ss:SSS} %-5p [%t] %m (%c{3}%x)%n
-------------------------------------------------------------------------------
takamaro
大ベテラン
会議室デビュー日: 2004/10/12
投稿数: 100
投稿日時: 2005-02-19 01:40
引用:

ねまさんの書き込み (2005-02-18 16:25) より:

例えば、ファイルサイズをもっと大きくとり、履歴数を減らすという
チューニング方法もありそうですが、ファイルサイズが大きくなりすぎると
今度は人間が見るとき困る気もします。

ログの書き込み時ではなくログを見る段階で適宜分割することで、結果同じだ
という気がします。
本質的に問題なのは、サイズの最大値を大きく取る事でインデックス超過時の
ローテーションで一度に削除されるログ数も大きくなるという事でしょうか。

現実問題として一度に300のファイルのリネームが行なわれるとフリーズ気味
になりそれが問題だということですが、これはLog4JやJavaの問題というより
実行環境（OS,HDD）によるものでしょうから、この現象を回避する方法は無い
と思われます。
じゃ、どうするかですが、、、
１つの方法としては、総インデックス数は減らさずに極力リネーム回数を減らす
という事が考えられると思います。
要するに最過去ログファイルを削除後に全てのログファイル名をスライドさせる
事がリネーム回数の増加に繋がっているのですから、それを止めローテーション
時のログファイル名のネーミングに工夫をすれば何とかなりそうです。
例えば、、、「A」「B」というグループ単位で考えて、、、
A001〜A300までファイル名を使いきったら次のファイル名はB001とし、A001を
廃棄する。次のローテーションは新規でB002、そしてA002を廃棄。以上繰返し。
こうする事で、ローテーション時のリネーム処理は実質１回になります。

で、、実現方法ですが、、これはRollingFileAppenderを書きかえるか継承する
かしかない気がします、、、残念ながら。
恐らく１メソッドのオーバーライド位で済むのでは？と想像しますが。。。
unibon
ぬし
会議室デビュー日: 2002/08/22
投稿数: 1532
お住まい・勤務地: 美人谷　　　　　　　　良回答(20pt)
投稿日時: 2005-02-19 21:05
unibon です。こんにちわ。

引用:

ねまさんの書き込み (2005-02-18 16:25) より:
ログのローテーション時には、ファイルのリネームしかしないと思うのですが、
300ファイルのリネームってそんなに時間がかかるものなのでしょうか？

log4j は使ったことはないのですが、一般に、ファイルのリネームは時間はかからないものだと思います。なお、古い FAT(12 や 16) などでは、ひとつのディレクトリの中にたくさんのファイルを作ると、ファイルの検索に時間がかかるようになりますが、300個位なら大丈夫なはずです。
固まっている最中にタスクマネージャーで CPU 使用率や、どのプロセスがたくさんつかっているか、などを調べられてはどうでしょうか。
log4j の仕様は分かりませんが、もしかしたらリネームせずコピーしていたりするかもしれません。もしそうならディスクI/Oが多いはずです。
あるいはひょっとしたら、リネーム時にウイルス検出のソフトウェアなどが動いているのかもしれません。
ねま
会議室デビュー日: 2004/11/10
投稿数: 18
投稿日時: 2005-02-21 10:50
takamaroさん、unibonさんありがとうございます。
引用:

本質的に問題なのは、サイズの最大値を大きく取る事でインデックス超過時の
ローテーションで一度に削除されるログ数も大きくなるという事でしょうか。

なるほど、そこまで深く考えていませんでした。
引用:

１つの方法としては、総インデックス数は減らさずに極力リネーム回数を減らす
という事が考えられると思います。

自分もそう思います。自分はファイル名に日付時刻を付加できれば解決するかなと考えていたのですが、takamaroさんの案も参考にさせていただきます。

引用:

固まっている最中にタスクマネージャーで CPU 使用率や、どのプロセスがたくさんつかっているか、などを調べられてはどうでしょうか。
log4j の仕様は分かりませんが、もしかしたらリネームせずコピーしていたりするかもしれません。もしそうならディスクI/Oが多いはずです。
あるいはひょっとしたら、リネーム時にウイルス検出のソフトウェアなどが動いているのかもしれません。

貴重なご意見ありがとうございます。確かに環境面や log4j の実装を調査したいところではあるのですが、今回はそれだけの人的余裕も時間的余裕もないのでリネーム回数を減らすという方法で進める予定です。
takamaro
大ベテラン
会議室デビュー日: 2004/10/12
投稿数: 100
投稿日時: 2005-02-21 13:55
引用:

さんの書き込み (2005-02-21 10:50) より:

自分はファイル名に日付時刻を付加できれば解決するかなと考えていたのですが
　　　　ー略ー
確かに環境面や log4j の実装を調査したいところではあるのですが、今回はそれだけの人的余裕も時間的余裕もないのでリネーム回数を減らすという方法で進める予定です。

日付を付加するAppenderクラスも存在しますが、これはログファイルのネーミング
以外にも動作も異なるものなので私の考えとしてはRollingFileAppenderの修正の
方向で事を進めるのが良いのではと思います。
で、修正のポイントはRollingFileAppenderクラスのrollOver()メソッドが中心と
なると思うのですが、ここを見れば解かりますがjava.io.File#renameTo()により
全ログファイルをリネームを行っています（unibonさんは「それ程時間が掛かる処理
ではない」とアドバイスされていますが、USB接続の外付けHDDである事が影響してい
るのかもしれません）もし日付を付加する事と仮定してみると、リネーム処理の替わり
にファイル名に付加された日付の比較を行わなければならないわけですが、その為に
は何らかの形（キューとか）でログファイル情報を世代順で持たないとけませんよね。
という事は必ず（最低でも起動毎に一度）全ログファイルをソートするなどの処理が
必要になってくるわけです。。。
と、ここまで書いていて最初に提案した私の方法を肯定しうる根拠も怪しい
ものだと思えてきましたｗ
うーん、悪くないかもしれませんね「日付の付加」というのも。
最初の段で３００位のソート処理がネックになるとは思えませんし、先入れ後出し
で後はスムースに処理を進める事が出来ますものね。
なによりもログを見る人間にとっても日付というのは理解しやすいので説明も簡潔に
行える事でしょうし。。。
ねまさんの方向で進めてみては如何でしょう？具体的なRollingFileAppenderの実装
で解からない部分が出てきたら再投稿して見てください。協力しますんで。
ken
常連さん
会議室デビュー日: 2002/04/29
投稿数: 38
投稿日時: 2005-02-21 15:13
まずは何が問題で遅いのかを何かしらのツールを使ってプロファイリングしてみて
何が問題を突き止めて、それからそれに対処するというのが、一般的な手順だと思
います。
やはり推測だけで物事を進めるのはあまり良くないと思います。
takamaro
大ベテラン
会議室デビュー日: 2004/10/12
投稿数: 100
投稿日時: 2005-02-21 16:32
引用:

kenさんの書き込み (2005-02-21 15:13) より:
まずは何が問題で遅いのかを何かしらのツールを使ってプロファイリングしてみて
何が問題を突き止めて、それからそれに対処するというのが、一般的な手順だと思
います。
やはり推測だけで物事を進めるのはあまり良くないと思います。

確かにそうなのですが、今回の場合はLog4Jのローテーションに関してですから
該当する部分（環境は替えられないとした場合）はリネーム処理部だけなんですよね。
そうなるとリネームの回数を減らす以外に対処が存在しないわけでして。。。
要するにツールを使うまでも無く「問題点」は明確な事例なわけです。
過去にLog4Jのソースを見た経験の上で提案をしていますので「推測だけ」という
わけじゃないです。
ねま
会議室デビュー日: 2004/11/10
投稿数: 18
投稿日時: 2005-02-23 13:04
お返事遅くなりました。

続報です。調査する余裕がないと自分で言っておきながらやはり調査してみました。

再現した環境
　・OS = windowsXP
　・CPU = Pen3 1.2GHz
　・HDD = USB1.0 外付けHDD
　・アンチウィルスソフト = ウィルスバスター 2005

再現しない環境
　・OS = windows2000
　・CPU = Pen4 2.5GHz
　・HDD = USB2.0 外付けHDD
　・アンチウィルスソフト = なし

再現しない環境もあることから、log4j の問題というよりは、環境の問題といえそうです。
再現しない環境では 300 ファイルのリネームなんて一瞬でした。
再現する環境で実際どのタスクが CPUを占有しているのかタスクマネージャで見てみて
これから調査する予定です。

ただ、お客様の環境で使っていただくためどんな環境でも再現しないように
するために、解決方法としてはリネーム処理の回数を減らすという方向は変わらない
かなと考えています。

また、状況が進展したら報告させていただきます。
1|2 次のページへ»

スキルアップ／キャリアアップ（JOB@IT）