Logcat có nhật ký có dấu thời gian ngoài chuỗi

Question

Tôi đang gỡ lỗi kết nối dữ liệu và chuỗi trong đó mọi thứ xảy ra là quan trọng. Tôi sử dụng logcat với dấu thời gian với ADB trong một thiết bị đầu cuối và thu thập số lượng nhật ký mà tôi phân tích sau này. Vấn đề tôi có là, đôi khi, các dấu thời gian không tuần tự. Vì Logcat là một bộ đệm tròn, tôi không thể thấy tại sao nó lại như vậy. Vì vậy, tôi đang lang thang nếu có một lỗi trong dấu thời gian hoặc nếu sự kiện thực sự không được ghi tuần tự và tôi nên tham khảo chuỗi nhật ký thay vì dấu thời gian (xem chuyển tiếp dòng 8 và 9). Có ai biết về điều đó không? các lệnh được sử dụng để có được các bản ghi là:

thời gian adb logcat -b đài phát thanh -v

và nhật ký:

... 
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 
... 

Answer 1

Timestamps không tuần tự bởi vì các hoạt động Log.i không phải là nguyên tử trong vòng hệ thống. Hãy xem Log.i hoạt động như thế nào trong một vài bước cơ bản: 1. Đầu tiên, nó sẽ có thời gian hệ thống 2. Sau đó, định dạng chuỗi bằng cách sử dụng thời gian hệ thống thu được 3. Ứng dụng đặt thông báo vào bộ đệm gửi 4. Cuối cùng , thời gian nền của luồng thời gian xóa dữ liệu nhật ký khỏi ngữ cảnh ứng dụng (đối với hệ thống ghi nhật ký trung tâm)

Hãy tưởng tượng rằng đang chạy hai quy trình song song. Trong tình huống không may, bộ lập lịch tạm dừng quá trình của bạn trong thời điểm nó kết thúc bước 1. Sau đó, thời gian chạy CPU của trình lên lịch cho quá trình tiếp theo cũng giúp Log.i nhưng có đủ thời gian để hoàn thành công việc Log.i. Cuối cùng, trình lên lịch cho CPU thời gian xử lý của chúng tôi để hoàn tất quá trình ghi nhật ký.

Trong ví dụ này, bạn có thể thấy rằng dấu thời gian trộn là do hoạt động Log.i không nguyên tử và đệm các mục nhật ký gửi đi. Ứng dụng không thể xóa các mục nhập nhật ký sau mỗi lần nhập nhật ký, vì việc chuyển ngữ cảnh giữa ứng dụng và hệ thống ghi nhật ký là rất, rất tốn kém CPU hoạt động. Thay vào đó, nó đệm các mục nhập nhật ký và khi bộ đệm đầy hoặc một khoảng thời gian trôi qua, sau đó nó thực hiện đăng nhập tuôn ra. Cách tiếp cận này cải thiện đáng kể hiệu suất.

Nếu bạn cần mục nhập nhật ký được sắp xếp theo thứ tự, bạn có thể đặt hàng trước khi xử lý tiếp.

Answer 2

Lưu ý dòng ngay trước thời điểm logcat được ra khỏi trật tự:

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 

Cụ thể, nhìn vào một phần của dòng nơi nó nói gained(ms): -423. Dòng sau đây xảy ra tại 18:32:29.017, hoàn toàn phù hợp với sự kiện nhật ký xảy ra 16ms sau khi đồng hồ hệ thống được đặt trở lại 423 mili giây.

Câu trả lời của vit là chính xác trong các mục nhật ký có thể bị gián đoạn bởi các luồng khác, cũng có thể ghi nhật ký, dẫn đến một số kết quả khó hiểu: nhưng đây không phải là điều đang xảy ra trong trường hợp này.