लॉगकैट अनुक्रम

Question

से टाइमस्टैम्प के साथ लॉग करता है मैं डेटा कनेक्शन डीबग कर रहा हूं और अनुक्रम जिसमें चीजें होती हैं महत्वपूर्ण है। मैं टर्मिनल में एडीबी के साथ टाइम स्टाम्प के साथ लॉगकैट का उपयोग करता हूं और बाद में विश्लेषण के लॉग के घंटों को इकट्ठा करता हूं। मेरी समस्या यह है कि, कभी-कभी, टाइमस्टैम्प अनुक्रमिक नहीं होते हैं। चूंकि लॉगकैट एक गोलाकार बफर है, इसलिए मैं नहीं देख सकता कि यह ऐसा क्यों होगा। इसलिए, अगर टाइमस्टैंप में कोई बग है या यदि घटना वास्तव में क्रमशः लॉग नहीं होती है तो मुझे घूम रहा है और मुझे टाइमस्टैम्प की बजाय लॉग के अनुक्रम का संदर्भ लेना चाहिए (लाइन 8 और 9 संक्रमण को देखें)। किसी को इसके बारे में पता है? लॉग प्राप्त करने के लिए इस्तेमाल आदेश है:

adb logcat बी रेडियो -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 
... 

Answer 1

मुहर नहीं अनुक्रमिक क्योंकि Log.i आपरेशन के भीतर परमाणु नहीं है प्रणाली। चलो एक नज़र कैसे Log.i बुनियादी कई चरणों में काम करता है दो: 1. सबसे पहले, यह सिस्टम का समय हो जाता है 2. फिर इसे प्राप्त प्रणाली समय 3. आवेदन बाहर जाने वाले बफर करने के लिए संदेश प्रस्तुत करती है 4. अंत का उपयोग कर स्ट्रिंग प्रारूप , बैकग्राउंड थ्रेड टाइम-टू-टाइम फ्लैश डेटा एप्लिकेशन संदर्भ (केंद्रीय लॉगिंग सिस्टम से)

कल्पना कीजिए कि समांतर में दो प्रक्रियाएं चल रही हैं। दुर्भाग्यपूर्ण स्थिति में शेड्यूलर आपकी प्रक्रिया को चरण 1 में समाप्त कर देता है। फिर शेड्यूलर CPU प्रक्रिया को अगली प्रक्रिया में देता है जो Log.i भी बनाता है लेकिन Log.i job को समाप्त करने के लिए पर्याप्त समय के साथ। अंत में, शेड्यूलर लॉगिंग ऑपरेशन को समाप्त करने के लिए हमारी प्रक्रिया में CPU समय देता है।

इस उदाहरण पर आप देख सकते हैं कि मिश्रित समय टिकटें गैर-परमाणु Log.i ऑपरेशन और आउटगोइंग लॉग प्रविष्टियों के बफरिंग के कारण होती हैं। एप्लिकेशन प्रत्येक लॉग एंट्री के बाद लॉग प्रविष्टियों को फ्लश नहीं कर सकता है, क्योंकि एप्लिकेशन और लॉगिंग सिस्टम के बीच स्विचिंग संदर्भ बहुत सीपीयू महंगा ऑपरेशन है। इसके बजाय, यह लॉग प्रविष्टियों को बफर करता है और जब बफर भरा होता है या कुछ समय समाप्त हो जाता है, तो यह लॉग फ्लश करता है। यह दृष्टिकोण नाटकीय रूप से प्रदर्शन में सुधार करता है।

यदि आपको ऑर्डर किए गए लॉग प्रविष्टियों की आवश्यकता है, तो आप आगे संसाधित करने से पहले उन्हें ऑर्डर कर सकते हैं।

Answer 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 पर होती है, जो सिस्टम घड़ी को 423ms वापस सेट करने के बाद 16ms हो रहा है, जो एक लॉग इवेंट के साथ पूरी तरह से संगत है।

विट का जवाब सही है कि लॉग प्रविष्टियों को अन्य धागे से बाधित किया जा सकता है, जो लॉगिंग भी कर सकता है, जिससे कुछ भ्रमित आउटपुट हो सकता है: लेकिन इस मामले में ऐसा नहीं हो रहा है।