VS2010 + C# + .NET Framework 3.5 で組まれたシステムで、徐々に動作が重くなるとゆう問題が発生しました。

それも特に何もやってないメソッドから受け取った実行結果詳細をログに出力するってところで一行出力するたびに数msかかってしまうとゆうモノ

詳細を調べると処理を繰り返すうちあたかもCPUのクロックが激減したかのようにに全体のパフォーマンスが落ちていってます。

最初は10行出力しても1msさえかかってなかったログ出力が、一行出力するのに数msかかってしまうようになってます。

 

バグの症状としては定番なんですが、定番だけに症例が多いので特定も楽だとは思ったのですが・・・

メモリーリーク問題なし

ゾンビスレッドなし

バックグラウンドタスク問題なし

常駐プログラム問題なし

サービス動作状況問題なし

 

定番の原因が全て「問題なし」

 

ただ気になったのがC#のスレッド絡みでよく見る「スレッドの作成・破棄を繰り返すと効率が悪いので、スレッドプールを使うべき」とゆう一文

私は「スレッドを新規作成するコンストラクタはかなりヘビーなコストがかかる上にリソース消費も激しい」と理解していたのですが、なんとなくひっかかる気もしたのでサンプルコードを作って試験してみました。

                // スレッド作成
Thread threadQuery = new Thread(QueryThread);

// パラメーター作成
object[] prms = new object[] { (string)filename, (string)serialnum, (bool)continuous, (int)interval, (int)timeout };

//    スレッド始動
threadQuery.Start(prms);
handle = threadQuery;

//    スレッド終了
while (handle.IsAlive)
{
System.Threading.Thread.Sleep(10);
}
//    スレッド破棄

//    ログ出力1
WRITE_LOG(“LOG ” + i);
WRITE_LOG(“LOG ” + i);
WRITE_LOG(“LOG ” + i);
WRITE_LOG(“LOG ” + i);

このコードを1000回繰り返して、ログ出力をチェックします。

スレッドの中身は特に何もやらずに10msだけSleepした後にスレッド終了&消滅

で、実行結果(重複行はエディターで削除。つまり1ms以内に終わってる処理を消える)

2012/06/20 10:53:01.155    INFO,LOG 1
2012/06/20 10:53:01.192    INFO,LOG 2
2012/06/20 10:53:01.220    INFO,LOG 3
2012/06/20 10:53:01.221    INFO,LOG 3
2012/06/20 10:53:01.273    INFO,LOG 4
2012/06/20 10:53:01.496    INFO,LOG 5
2012/06/20 10:53:01.614    INFO,LOG 6
2012/06/20 10:53:01.647    INFO,LOG 7
2012/06/20 10:53:01.673    INFO,LOG 8
2012/06/20 10:53:01.697    INFO,LOG 9

.

.

.

2012/06/20 10:53:51.859    INFO,LOG 996
2012/06/20 10:53:51.860    INFO,LOG 996
2012/06/20 10:53:51.888    INFO,LOG 997
2012/06/20 10:53:51.912    INFO,LOG 998
2012/06/20 10:53:51.913    INFO,LOG 998
2012/06/20 10:53:51.935    INFO,LOG 999
2012/06/20 10:53:51.937    INFO,LOG 999
2012/06/20 10:53:51.937    INFO,END

明らかに終盤のログ出力処理間に時間がかかるようになってます。

ログ出力のタイミング次第では1ms差位は出てしまいますが、連続して出てしまうとゆうのは明らかに処理が重くなっている証拠です。

1ms未満の時間は取得出来ないのではっきりとはしないのですがカウントが100付近から遅延の影響が出てきていました。

ちなみに1プロセス内限定の症状のようで、一旦プログラムを終了させ頭から再実行させると遅延はリセットされます。

取り合えずスレッドプールで同じ事をやってみて比較してみようと思います。

 追記:

スレッドプールで同じ事をやってみたら、再現しない事を確認。

通常のスレッド生成と同じとはいかないので多少ロジックは変わっているので単に比較出来ないのですが、ログ上ではパスレッド自体の処理パフォーマンスが向上している事も確認。

ThreadからThreadPoolに書き換えるネックは個別スレッドのハンドルを取得できない事と、それに伴いIsAlive等のプロパティが使えないのが大きいです。

ボリュームの大きい処理をスレッドに投げて、メインはIsAliveで終了したかを確認しつつ他の事をやる・・・とゆう手順を少し弄る必要が出てきます。

自滅型スレッドの場合、スレッド開始に使ったハンドルのIsAliveプロパティをチェックする事で動作が終わったかを判断しますが、スレッドプールを使うとそれが出来ない!

仕方ないのでスレッド内部の始動&終了前にフラグをセットしてそれで判断させる事になります。

そうすると問題になるのは並行して幾つものスレッドを流す場合。

フラグに使う変数が一つだとバッティングしてしまいます。

なので、フラグを配列にしてスレッドIDなり通し番号なりをキーにして管理する事になります。

今回は検索処理を行うスレッドなので、フラグ配列を連想配列で宣言して検索に使うキーをの配列の添え字として使う事で動作完了フラグとして使ってみました。