6

データ接続をデバッグしていますが、発生する順序が重要です。ターミナルで ADB のタイムスタンプ付きの logcat を使用し、後で分析する数時間のログを収集します。私が抱えている問題は、タイムスタンプが連続していないことがあります。Logcat は循環バッファーであるため、なぜそのようになるのかわかりません。そのため、タイムスタンプにバグがあるかどうか、またはイベントが実際に連続してログに記録されていないため、タイムスタンプの代わりにログのシーケンスを参照する必要があるかどうかを迷っています (8 行目と 9 行目の遷移を見てください)。誰かそれについて知っていますか？ログを取得するために使用されるコマンドは次のとおりです。

adb logcat -b ラジオ -v 時間

およびログ:

...
09-06 18:32:29.426 D/GSM     (  200): getNitzTimeZone returning America/Detroit
09-06 18:32:29.434 I/AT      (   65): AT(14)< +CGDCONT: 1,"IP","pda.bell.ca","",0,0
09-06 18:32:29.434 I/AT      (   65): AT(14)< OK
09-06 18:32:29.434 E/RIL     (   65): processRequest: OPERATOR
09-06 18:32:29.434 E/AT      (   65): ---AT+COPS=3,0;+COPS?;+COPS=3,1;+COPS?;+COPS=3,2;+COPS?
09-06 18:32:29.434 I/AT      (   65): AT(14)> AT+COPS=3,0;+COPS?;+COPS=3,1;+COPS?;+COPS=3,2;+COPS?
09-06 18:32:29.434 D/RILJ    (  200): [UNSL]< UNSOL_DATA_CALL_LIST_CHANGED [DataCallState: { cid: 1, active: 0, type: IP, apn: pda.bell.ca, address:  }]
09-06 18:32:29.434 I/GSM     (  200): NITZ: Setting time of day to Thu Sep 06 18:32:29 EDT 2012 NITZ receive delay(ms): 14 gained(ms): -423 from 12/09/06,22:32:29-16,1
09-06 18:32:29.017 I/AT      (   65): AT(14)< +COPS: 0,0,"Bell",2
09-06 18:32:29.017 I/AT      (   65): AT(14)< +COPS: 0,1,"Bell",2
09-06 18:32:29.017 I/AT      (   65): AT(14)< +COPS: 0,2,"302610",2
09-06 18:32:29.017 I/AT      (   65): AT(14)< OK
09-06 18:32:29.017 I/RIL     (   65): swiril_cache_set: updating cache for OPERATOR
09-06 18:32:29.017 E/RIL     (   65): processRequest: GPRS_REGISTRATION_STATE
09-06 18:32:29.017 E/AT      (   65): --- AT+CGREG?
09-06 18:32:29.017 I/AT      (   65): AT(14)> AT+CGREG?
09-06 18:32:29.017 D/RILJ    (  200): [0612]< OPERATOR {Bell, Bell, 302610}
09-06 18:32:29.025 I/AT      (   65): AT(14)< +CGREG: 2,1,"2D8C","067C358F",2
09-06 18:32:29.025 I/AT      (   65): AT(14)< OK
09-06 18:32:29.025 I/RIL     (   65): swiril_cache_set: updating cache for GPRS_REGISTRATION_STATE
09-06 18:32:29.025 E/RIL     (   65): processRequest: REGISTRATION_STATE
09-06 18:32:29.025 E/AT      (   65): --- AT*CNTI=0
09-06 18:32:29.025 I/AT      (   65): AT(14)> AT*CNTI=0
09-06 18:32:29.025 D/RILJ    (  200): [0613]< GPRS_REGISTRATION_STATE {1, 2d8c, 067c358f, 3}
09-06 18:32:29.029 I/AT      (   65): AT(14)< *CNTI: 0,UMTS
...
4

2 に答える 2

12

Log.i操作はシステム内でアトミックではないため、タイムスタンプはシーケンシャルではありません。Log.iが基本的ないくつかのステップでどのように機能するかを見てみましょう：1。最初にシステム時刻を取得します2.次に取得したシステム時刻を使用して文字列をフォーマットします3.アプリケーションがメッセージを送信バッファに入れます4.最後にバックグラウンドスレッド時刻-時間にログデータをアプリケーションコンテキストから（中央ロギングシステムに）フラッシュします

2つのプロセスを並行して実行していると想像してください。不運な状況では、スケジューラーはステップ1を終了した瞬間にプロセスを一時停止します。次に、スケジューラーは次のプロセスにCPU時間を与えます。これにより、Log.iも作成されますが、Log.iジョブを完了するのに十分な時間があります。最後に、スケジューラーは、ロギング操作を終了するためにプロセスにCPU時間を与えます。

この例では、タイムスタンプの混合が非アトミックLog.i操作と送信ログエントリのバッファリングによって引き起こされていることがわかります。アプリケーションとロギングシステム間のコンテキストの切り替えは非常にCPUコストのかかる操作であるため、アプリケーションは各ログエントリの後にログエントリをフラッシュできません。代わりに、ログエントリをバッファリングし、バッファがいっぱいになるか、時間が経過すると、ログフラッシュを実行します。このアプローチにより、パフォーマンスが劇的に向上します。

注文したログエントリが必要な場合は、さらに処理する前に注文できます。

于 2012-11-02T11:51:02.470 に答える
2

logcat の時刻が乱れる直前の行に注意してください。

09-06 18:32:29.434 I/GSM     (  200): NITZ: Setting time of day to Thu Sep 06 18:32:29 EDT 2012 NITZ receive delay(ms): 14 gained(ms): -423 from 12/09/06,22:32:29-16,1

具体的には、行の と書かれている部分を見てくださいgained(ms): -423。次に、次の行が で発​​生し18:32:29.017ます。これは、システム クロックが 423 ミリ秒に戻された 16 ミリ秒後に発生したログ イベントと完全に一致しています。

vitの答えは、ログエントリが他のスレッドによって中断される可能性があるという点で正しいです.ログを作成する可能性があり、出力が混乱する可能性があります.しかし、これはこの場合に起こっていることではありません.

于 2013-08-23T04:08:56.033 に答える