-
Notifications
You must be signed in to change notification settings - Fork 113
「ログ出力時に毎回ファイルを開いている」の修正 #67
base: feature/log_improvement
Are you sure you want to change the base?
Conversation
実際に試していないですが、#38 (comment) にある あと、コードフォーマットや命名規則が他のファイルと全く違っているので、できればある程度 見落としていましたが書式は勝手に変えたらダメですね。運用側ではこのログを見ている人がいるはずなので。。 |
Rotateやログ送信時はIDEの不具合(#53)でまだ試せていません。ファイルの共有はされるので理論上は動くと思っています。 コードフォーマットについては、マージ直前に修正する予定です。その時には .editorconfig ファイルを貸して頂ければ助かります。 |
排他制御を |
この変更について、ぼくはCOCOAの改善として良いと考えているのでレビューしていきます。 大きい変更なので、ぼくがApproveしてから開発チーム側でレビューする流れになります。ぼくのApprove != 取り込み決定ではないことをお伝えしておきます。 処理効率を上げた結果、デグレが起こってログが失われるのが一番よろしくないので、そのあたりの懸念をなくすためにどうするのが良いかが課題ですね。 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
所見でレビューコメント付けました。
ひとまず、フォーマッターの変更をお願いします!
@@ -75,6 +75,7 @@ | |||
- Tassana Thaveeteeratham (Thai Translation) | |||
- Kotaro Sakamoto | |||
- Koichi Yokota (Documentation) | |||
- Takym (LogWriter) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
CONTRIBUTORに関しては新しく項目を設けますね。
@@ -1,18 +1,13 @@ | |||
/* This Source Code Form is subject to the terms of the Mozilla Public | |||
/* This Source Code Form is subject to the terms of the Mozilla Public |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
この変更でBOMが取れたりしていますか?
もし取れていれば付け直してもらえると(付けてあれば全く問題ないです
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Visual Studio で保存した場合、BOM が付いたり消えたりしました(そろそろ BOM 無しを既定の設定にして欲しいですよね)。VSCode から BOM を取り除きました。
); | ||
} | ||
|
||
private static string CreateLogRow(params string[] cols) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
元実装と比べると複雑度が増しているように思います。
特定文字があったら置き換える処理と理解していますが、元実装のReplace
を使った方法で不都合は想定されますか?
置き換え文字列が多い場合は変換テーブルのようなものを作ってそれに基づいて処理をする(処理そのものはすっきりさせる)のがうれしいです。ご意見をうかがえればと思います。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LINQ から for に替えて速度向上を図ろうとしました。後で性能比較します。(Replace と同時に Select も展開しています。)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
簡略化して試してみた所、LINQ より FOR の方が微妙に早くまたコードサイズも小さくなりました。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
https://gist.github.com/Takym/e0a382ff63179c5a7b07bfc301e2914b
元の実装と本PRの実装の性能を比較しました。全体的に向上しています。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
ここは可読性優先でいきましょう! ミリ秒単位の差なら気になるところですが、ナノ秒なら無視しても良いレベルだと思います。
こういう提案があったことは記録として残すので、性能が問題になったら採用と言うことで。
cocoa/Covid19Radar/Covid19Radar/Services/Logs/LogWriter.cs
Lines 145 to 182 in 36b68b0
private static string CreateLogRow(params string[] cols) | |
{ | |
var sb = new StringBuilder(); | |
for (int i = 0; i < cols.Length; ++i) { | |
if (i != 0) { | |
sb.Append(", "); | |
} | |
string s = cols[i]; | |
sb.Append('\"'); | |
for (int j = 0; j < s.Length; ++j) { | |
char ch = s[j]; | |
switch (ch) { | |
case '\t': | |
sb.Append("\\t"); | |
break; | |
case '\v': | |
sb.Append("\\v"); | |
break; | |
case '\r': | |
sb.Append("\\r"); | |
break; | |
case '\n': | |
sb.Append("\\n"); | |
break; | |
case '\\': | |
case '\"': | |
sb.Append(ch); | |
sb.Append(ch); | |
break; | |
default: | |
sb.Append(ch); | |
break; | |
} | |
} | |
sb.Append('\"'); | |
} | |
return sb.ToString(); | |
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
単位はナノ秒で書かれていますが、差は約0.5マイクロ秒程あります。
ログ出力処理は様々な場所で沢山呼ばれており、この小さい差は全体的には大きな影響を与えると思います。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
今は可読性と処理速度を両立したコードを試行錯誤しています。少し時間が掛かりそうです。すみません。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
締め切りとかがあるわけではないので大丈夫ですよ。
ぼくの考えとして、このログ出力は必ずFile IOを伴うものです。ファイル入出力にかかる時間を考えると、提示いただいているナノ秒・マイクロ秒未満の差は誤差の域だとぼくは思っていて、現時点であまり頑張って縮める必要はないとも考えています。
ぼく自身、Androidではカスタムビューで60fpsを維持したまま複雑な描画処理をするのにどうするかとか、カメラプレビューの大きな画像データを可能な限り早く前処理して機械学習モデルに入力するとかしているので、場合によってはナノ秒単位の差が積み重なってアプリの体験として命取りになることは承知しています。
その上で、この部分はそこまでのことではないなと考えています。最初の方にいただいていた「ファイルハンドラーを開いて保持しておく。日付が変わっていたら新しいファイルで開き直す」があれば、Issueそのものは解決できると考えています。
処理速度については、現在、ファイルハンドラーを開いたり閉じたりするやり方でも、性能面で問題になっていないると言う認識はありません。また、ハンドラーを開いたり閉じたりしなくなる分、少なくとも性能は上がるものと期待しているので、性能については今後、問題になるようなことがあれば、そのときに対応すればいいと考えています。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
工夫して可読性と効率のバランスを取る事ができました。
for
文をforeach
文に置き換えました。- 配列に対する
foreach
はfor
と同程度の性能を持つそうです。
- 配列に対する
switch
を文から式に変更して、何を何に変換しているか分かり易くしました。- この書き方は
switch
式やReplace
よりも見やすいと思います。 '変換前の文字' => '変換後の文字列'
- この書き方は
- 三項演算子と破棄を利用して、左側に条件、右側に値を配置しました。
- 三項演算子は式ですので破棄は必ず書かなくてはなりません。
- カンマを入れるかどうかの判定を無くし行数を減らしました。
- 動作効率も僅かながら向上しています。
- 動作効率については以下の点を気を付けました。
StringBuilder
を使いました。- 元のコードと比べると、文字列を追加する順番も明確になり、可読性も高いと感じています。
- ループの深さを最小限にしました。
- 元のコードでは
Select
、Replace
、Join
を使っており、ループ回数が多いです。
- 元のコードでは
- 文字列連結演算子は使わない様にしました。
- 文字列連結演算子を使うと、メモリの確保が発生し、全体的に効率が落ちてしまいます。
cocoa/Covid19Radar/Covid19Radar/Services/Logs/LogWriter.cs
Lines 139 to 160 in 72a4f73
private static string CreateLogRow(params string[] cols) | |
{ | |
_ = _sb is null ? _sb = new StringBuilder() | |
: _sb.Clear(); | |
foreach (string col in cols) { | |
_sb.Append(",\""); | |
foreach (char ch in col) { | |
string? escaped = ch switch { | |
'\t' => "\\t", '\v' => "\\v", | |
'\r' => "\\r", '\n' => "\\n", | |
'\\' => "\\\\", '\"' => "\"\"", | |
_ => null | |
}; | |
_ = escaped is null ? _sb.Append(ch) | |
: _sb.Append(escaped); | |
} | |
_sb.Append('\"'); | |
} | |
_sb.Remove(0, 1); | |
return _sb.ToString(); | |
} |
LINQ を使わずに書いてみましたが、どうでしょうか?
Co-authored-by: ARIYAMA Keiji <keiji.ariyama@gmail.com>
); | ||
} | ||
|
||
private static string CreateLogRow(params string[] cols) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LINQ から for に替えて速度向上を図ろうとしました。後で性能比較します。(Replace と同時に Select も展開しています。)
private void WriteLine(DateTime jstNow, string line) | ||
{ | ||
var file = this.file; | ||
string fname = logPath.LogFilePath(jstNow); | ||
if (file is null || file.FileName != fname) { | ||
var newFile = new File(fname, enc); | ||
RewriteField(ref this.file, newFile, ref file); | ||
file?.Dispose(); | ||
file = newFile; | ||
file.Writer.WriteLine(HEADER); | ||
} | ||
file.Writer.WriteLine(line); | ||
} | ||
|
||
/// <inheritdoc/> | ||
public void Dispose() | ||
{ | ||
var file = this.file; | ||
RewriteField(ref this.file, null, ref file); | ||
file?.Dispose(); | ||
} | ||
|
||
[MethodImpl(MethodImplOptions.AggressiveInlining)] | ||
private static void RewriteField<T>(ref T field, T newValue, ref T oldValue) where T: class? | ||
{ | ||
while (Interlocked.CompareExchange(ref field, newValue, oldValue) != oldValue) { | ||
Thread.Yield(); | ||
oldValue = field; | ||
} | ||
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
while (true)
を無くし、処理を共通化しました。
file
への書き換えが発生するタイミングは下記の四つです。
- 始めて
WriteLine(DateTime, string)
が呼ばれた時 - 日付が変わった時
Dispose
が呼ばれた時Dispose
後にWriteLine(DateTime, string)
が呼ばれた時
複数のスレッドが同時に80行目に到達しますと、同じログファイルに HEADER
が複数出力される可能性はあります。また、HEADER
が出力される前に line
が出力される可能性もあります。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
複数のスレッドが同時に80行目に到達しますと、同じログファイルに HEADER が複数出力される可能性はあります。また、HEADER が出力される前に line が出力される可能性もあります。
ここだけ見るとけっこう厳しい挙動だなと思います。
WriteLine自体を同期化というか、SemaphoreSlimとかを使って2つのスレッドの処理が同時に通らないようにすれば解決しないでしょうか。
ログ出力は、そこまで性能を追い求めるものではないので、もう少しシンプルな作りの方が安心かと思います。現状、ファイルを開いたり閉じたりして効率が悪いことは確かですが、ちゃんと動いているという実績は大きいです。開発チームに推していくに当たって、現状のログ機構と同等の安定性があるとうれしいです。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
フィールドの書き換えに成功した時にのみ HEADER
を出力する様にしました。
そして、書き換えに失敗した場合は、現在開いている _file
の名前が最新かどうか確認する様に変更しました。
cocoa/Covid19Radar/Covid19Radar/Services/Logs/LogWriter.cs
Lines 81 to 90 in b4f15d8
do { | |
file = _file; | |
if (Interlocked.CompareExchange(ref _file, newFile, file) == file) { | |
file?.Dispose(); | |
file = newFile; | |
file.Writer.WriteLine(HEADER); | |
break; | |
} | |
Thread.Yield(); | |
} while (file is null || file.FileName != fname); |
どうでしょうか?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
WriteLine(DateTime, string)
の処理を改善し、HEADER
の複数回出力が発生する確率を下げました。
cocoa/Covid19Radar/Covid19Radar/Services/Logs/LogWriter.cs
Lines 75 to 93 in 68b7d9f
private void WriteLine(DateTime jstNow, string line) | |
{ | |
var file = _file; | |
string fname = _log_path.LogFilePath(jstNow); | |
if (file is null || file.FileName != fname) { | |
var newFile = new File(fname, _enc); | |
do { | |
if (Interlocked.CompareExchange(ref _file, newFile, file) == file) { | |
newFile.Writer.WriteLine(HEADER); | |
file?.Dispose(); | |
file = newFile; | |
break; | |
} | |
Thread.Yield(); | |
file = _file; | |
} while (file is null || file.FileName != fname); | |
} | |
file.Writer.WriteLine(line); | |
} |
処理を詳しく説明します。
- 77行目でローカル変数
file
にフィールド変数_file
の値を退避させます。 - 79行目で
file
が最新かどうか判定します。- 最新ではない場合は下記の処理を行います。
- 80行目で最新のファイルオブジェクトを生成し
newFile
に格納します。 - 82行目で
_file
とfile
が等しかった時にのみnewFile
に置き換えます。- 等しかった場合は、
HEADER
を出力し、元のfile
を破棄します。 - ループから抜けます。
- 等しかった場合は、
- 等しくなかった場合は、下記の処理を行います。
- 89行目でもう一度、ローカル変数
file
にフィールド変数_file
の値を退避させます。 - 90行目で
file
が最新かどうか判定し、最新でなければ再試行します。 - 最新であればループから抜けます。
- 89行目でもう一度、ローカル変数
- 92行目でログをファイルに書き込みます。
どうでしょうか?
追記
HEADER
を _file
フィールドの書き換え直後に行う様にしました。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
_file
フィールドの書き換えに失敗した時に、現在の _file
が最新かどうか確認していますので、HEADER
が複数回出力される事は無い筈です。
CocoaLogViewer で目視で確認した所、正しくログ出力できていました。 |
@keiji 返信が遅れて申し訳ありません。 非公開変数の命名規則について現在、非公開になっているフィールド変数の命名規則は統一されていない様に見えます。 内部クラス
|
using (var sr = new StreamReader("~/.cocoa/logs/cocoa_log_20201101.csv")) |
cocoa/Covid19Radar/Tests/Covid19Radar.UnitTests/Services/Logs/LoggerServiceTests.cs
Line 88 in bc848ce
Mock.Get(mockILogPathService).Verify(s => s.LogsDirPath, Times.Exactly(2)); |
cocoa/Covid19Radar/Tests/Covid19Radar.UnitTests/Services/Logs/LoggerServiceTests.cs
Line 107 in bc848ce
Mock.Get(mockILogPathService).Verify(s => s.LogsDirPath, Times.Once()); |
cocoa/Covid19Radar/Tests/Covid19Radar.UnitTests/Services/Logs/LoggerServiceTests.cs
Line 126 in bc848ce
Mock.Get(mockILogPathService).Verify(s => s.LogsDirPath, Times.Once()); |
LogWriter
を毎回生成していますので、それが原因でIO処理が上手く行っていないと予想しています。var jstNow = Utils.JstNow(); | ||
string row = CreateLogContentRow(message ?? string.Empty, method, filePath, lineNumber, logLevel, jstNow, _essentials); | ||
Debug.WriteLine(row); | ||
this.WriteLine(jstNow, row); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
この部分では日付を取得してから、WriteLine
を呼び出しています。
しかし、WriteLine
を実行するタイミングで日付が変更され、且つ _log_file
が最新のファイルに更新された場合に、ファイルの開き直しが複数回行われる気がします。
日付の取得は WriteLine
内に移動した方が良さそうです。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
下記の可能性が考えられます。
- 日付が変更される前に、スレッドAが
WriteLine
を呼び出します。 - 日付が変更された後に、スレッドBが
WriteLine
を呼び出します。 - スレッドB が
_log_file
を最新のファイルに更新します。 - スレッドA が
_log_file
を前日のファイルに更新します。 - 別のスレッドCがログを書き込むタイミングで、もう一度
_log_file
を最新のファイルに更新します。
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
WriteLine
の91行目の直後に日付を再取得すればこの問題は発生しませんが、この場合、前日のログを保持したログファイルが生成される可能性が生まれます。
This comment has been minimized.
This comment has been minimized.
単体テストについては こちら に情報をまとめていきます。 |
向き先変更しました。 |
ありがとうございます。 |
feature/log_improvementを最新のdevelopにrebaseした方がいいかもしれませんね。 |
af44703
to
9ada1f7
Compare
CIを動かすためにCloseとreopenします。 |
@Takym 今回、developの直近のcommitを一気にloggingに取り込んでいるように見えました。Pull Request一つ一つを構成する変更は、そのタイトルが指し示す内容を実現するのに必要と思われるcommitに限定してもらえるとありがたいです。 もしdevelopの更新を取り入れる必要がある場合、今回のようにrebaseをかけるので声をかけてください。 |
テスト処理を自動的に実行させる為に最新の CI を GitHub 上から取り込みました所、 |
* DeleteLogsDirIfExists 無効化 * テスト時のストリームの開き方を変更 * `DeleteLogsDirIfExists` を再度有効化&ログファイルの削除を許可 * `CocoaLogViewer` からコードを拝借 * テストケース修正 * Revert "テストケース修正" This reverts commit 7b43750. * テストケース修正 * `ILogWriter.Write` の仕様を変更し、null 値の入力を許可。 * Update CI.yml for logging_test * Revert "Update CI.yml for logging_test" * Suppress diff * Update CI.yml for logging test * Update CIserver.yml for logging test * `LogWriter` を大幅に改善 * テスト処理修正:`StartMethod_Success_LogsDir_Not_Exists`、`StartMethod_Success_LogsDir_Exists_LogFile_Not_Exists`、`StartMethod_Success_LogsDir_Exists_LogFile_Exists` * ログファイルのヘッダーの出力タイミングを変更 * Update CI.yml * Update CIserver.yml * Update CI.yml
このPRでは #38 と #208 の二つの解決が図られています。 #38 については #67 (comment) でもお伝えしましたが、速度面の心配は現時点であまりしていないので、可読性を優先してLINQを使った方法にしてもらえればと思います。 また、#208 については、タブ文字や改行コードをエスケープついて少なくとも「動作ログを確認する」という現在の用途では必須ではなく、開発チームとの調整ができていないので、こちらも一旦外してもらえると話が進めやすくなりますが、いかがでしょうか。 |
(久し振りにソースコードを確認しましたので、誤っている可能性があります。)
|
Issue 番号 / Issue ID
目的 / Purpose
破壊的変更をもたらしますか / Does this introduce a breaking change?
Pull Request の種類 / Pull Request type
検証方法 / How to test
コードの入手 / Get the code
コードの検証 / Test the code
以前と同じ様にログ出力が行われるか検証してください。宜しくお願い致します。
確認事項 / What to check
LoggerService
に記述されていたログ出力処理をLogWriter
に移動しました。LoggerService
のコンストラクタの引数を変更しました。FileStream
にはFileShare.ReadWrite
を指定しています。LogWriter
はファイル名の変更(日付の変更)を検出すると自動的にファイルを切り替えます。LogWriter.Dispose
を呼び出すと強制的にストリームを開き直す事ができます。yyyy/MM/dd HH:mm:ss.fffffff
に変更しました。CreateLogRow
を LINQ から for に変換しました。その他 / Other information