Chinaunix首页 | 论坛 | 博客

mournjustmournjust.blog.chinaunix.net

首页　| 　博文目录　| 　关于我

mournjust

  • 博客访问： 733346
  • 博文数量： 79
  • 博客积分： 2671
  • 博客等级： 少校
  • 技术积分： 1247
  • 用 户 组： 普通用户
  • 注册时间： 2010-04-02 15:26
个人简介

宅男

文章分类

全部博文（79）

文章存档

2017年（11）

2016年（12）

2015年（6）

2012年（10）

2011年（33）

2010年（7）

我的朋友
最近访客
推荐博文
相关博文
android logcat system与kernel时间戳不一致

分类： Android平台

2016-05-05 15:33:29

最近发现一个logcat时间戳不一致的问题，具体是kernel的时间戳没有被更新。
一般adb logcat -b system的输出如下：
  1. 05-05 01:16:00.896 1236 1236 W PackageManager: Library not found: /system/framework/com.android.nfc.helper.jar
  2. 05-05 01:16:00.932 1236 1236 W PackageManager: Library not found: /system/framework/org.apache.http.legacy.jar
  3. 05-05 01:16:00.969 1236 1236 W PackageManager: Library not found: /system/framework/smartsearch.jar
  4. 05-05 01:16:01.059 1236 1236 W PackageManager: Library not found: /system/framework/com.android.nfc.helper.jar
  5. 05-05 01:16:01.084 1236 1236 W PackageManager: Library not found: /system/framework/org.apache.http.legacy.jar
  6. 05-05 01:16:01.336 1236 1236 W PackageManager: Failed to parse /system/framework/arm: Missing base APK in /system/framework/arm
  7. 05-05 01:16:01.336 1236 1236 W PackageManager: Failed to parse /system/framework/arm64: Missing base APK in /system/framework/arm64
  8. 05-05 01:16:01.668 1236 1236 W PackageManager: Failed to parse /system/framework/oat: Missing base APK in /system/framework/oat
但是同样的情况下，adb logcat -b kernel的输出确实下面这样
  1. 01-01 01:16:16.358 0 0 I init : Service 'bootanim' (pid 556) exited with status 0
  2. 01-01 01:16:16.366 0 0 W : NPDecoder (4119) used greatest stack depth: 10040 bytes left
  3. 01-01 01:16:16.546 0 0 I : Boot completed init: Starting service 'qcom-post-boot'...
  4. 01-01 01:16:16.549 0 0 I init : Starting service 'qti-testscripts'...
  5. 01-01 01:16:16.555 0 0 I init : Starting service 'config-zram'...
  6. 01-01 01:16:16.560 0 0 I init : Starting service 'atfwd'...
  7. 01-01 01:16:16.564 0 0 I init : Starting service 'cs-post-boot'...
  8. 01-01 01:16:16.569 0 0 E init : cannot find '/system/bin/qrngp', disabling 'qrngp'
  9. 01-01 01:16:16.604 0 0 I init : Service 'qti-testscripts' (pid 5307) exited with status 0
  10. 01-01 01:16:16.610 0 0 I init : Service 'cs-post-boot' (pid 5310) exited with status 0
  11. 01-01 01:16:16.642 0 0 I : Adding 524284k swap on /dev/block/zram0. Priority:-1 extents:1 across:524284k SS
  12. 01-01 01:16:16.653 0 0 I init : Service 'config-zram' (pid 5308) exited with status 0
  13. 01-01 01:16:16.705 0 0 I msm_thermal: store_cc_enabled Core control disabled
可以看出system的时间是正确的（2016年5月5号），但是kernel的时间戳一直是 （1970年1月1号）。
其实关于system的时间戳，很好理解，无非就是在调用函数的时候，实时插入了一些时间信息等等。
但是kernel的时间就不太一样，内核的时间是logd从/proc/kmsg里面读出来的。内核默认显示的时从开机以来的相对时间。
  1. [ 8.566478] （开机时间哦） zram: Created 1 device(s) ...
  2. [ 8.567260] ashmem: initialized
  3. [ 8.567988] platform 78c4000.qcom,usbbam: Driver usb_bam requests probe deferral
  4. [ 8.568785] qcom,qpnp-power-on qpnp-power-on-ffffffc0af3f4d00: PMIC@SID0 Power-on reason: Triggered from Hard Reset and 'cold' boot
  5. [ 8.568802] qcom,qpnp-power-on qpnp-power-on-ffffffc0af3f4d00: PMIC@SID0: Power-off reason: Triggered from PS_HOLD (PS_HOLD/MSM controlled shutdown)
  6. [ 8.569177] input: qpnp_pon as /devices/virtual/input/input3
  7. [ 8.570557] pon_spare_reg: no parameters
  8. [ 8.570860] qcom,qpnp-power-on qpnp-power-on-ffffffc0aec28b00: No PON config. specified
  9. [ 8.570899] qcom,qpnp-power-on qpnp-power-on-ffffffc0aec28b00: PMIC@SID2 Power-on reason: Triggered from PON1 (secondary PMIC) and 'cold' boot
  10. [ 8.570915] qcom,qpnp-power-on qpnp-power-on-ffffffc0aec28b00: PMIC@SID2: Power-off reason: Triggered from PS_HOLD (PS_HOLD/MSM controlled shutdown)
  11. [ 8.571326] qpnp_coincell_charger_show_state: enabled=Y, voltage=3200 mV, resistance=2100 ohm
  12. [ 8.673320] mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12 p13 p14 p15 p16 p17 p18 p19 p20 p21 p22 p23 p24 p25 p26 p27 p28 p29 p30 p31 p32 p33 p34 p35 p36 p37 p38 p39 p40 p41 p42 p43 p44 p45 p46
  13. [ 8.673885] bimc-bwmon 408000.qcom,cpu-bwmon: BW HWmon governor registered.
  14. [ 8.675208] msmcci-hwmon b1dc000.qcom,msmcci-ccimon: Cache HWmon governor registered.
  15. [ 8.675213] msmcci-hwmon b1dc000.qcom,msmcci-ccimon: MSMCCI cache hwmon registered
  16. [ 8.715807] devfreq qcom,cpubw.49: Couldn't update frequency transition information.
  17. [ 8.723407] devfreq qcom,mincpubw.50: Couldn't update frequency transition information.
  18. [ 8.734005] devfreq qcom,cci.48: Couldn
开撸代码。在system/core目录下有两个目录，一个是logcat，另外一个是logd。关于logcat的整体框架就不再描述了，网上能搜到很多。
关于kernel部分的代码在logd/LogKlog.cpp文件中。这边有个极其关键的函数。
  1. void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
  2.     const char *cp;
  3.     if ((cp = now.strptime(*buf, "[ %s.%q]"))) {
  4.         static const char suspend[] = "PM: suspend entry ";
  5.         static const char resume[] = "PM: suspend exit ";
  6.         static const char healthd[] = "healthd: battery ";
  7.         static const char suspended[] = "Suspended for "
这个函数在一些特定的event发生时，用来修正时间戳。（即开机启动时间与实际时间之间的delta值）。换句话说，如果没有发生这些事件，时间就不对。
那么这些事件是什么呢？
  1. 6,2277,359478935 （开机时间）,-;PM: suspend entry 2016-05-05 01:34:55.386101848 UTC （UTC时间）
    6,2278,359478958,-;PM: Syncing filesystems ... done.
    3,2279,359577087,-;Error: returning -512 value
    6,2280,359574192,-;Freezing user space processes ...
    6,2281,359604671,-;last active wakeup source: eventpoll
    6,2282,359604792,-;
    3,2283,359604807,-;Freezing of tasks aborted after 0.030 seconds
    6,2284,359609616,-;Restarting tasks ... done.
    6,2285,359636056,-;PM: suspend exit 2016-05-05 01:34:55.543212368 UTC （由于无法从/proc/kmsg中抓取log，只能从/dev/kmsg中抓取了，格式稍微有点差异）
上面是我抓取的kernel中关于是suspend entry的log。这条log中除了正常的开机时间（CLOCK_MONOTONIC）以外，还有一条关键信息即UTC时间 （CLOCK_REALTIME）。
那么logcat对于这条kernel log进行处理的时候，会修正时间，即修改correction参数。这时候kernel 的时间戳就可以被修正过来了。adb logcat -b kernel可以显示正确的logs了

  1. 01-01 01:31:58.104 0 0 I : read strings
  2. 01-01 01:31:58.105 0 0 I msm_hsusb: CI13XXX_CONTROLLER_DISCONNECT_EVENT received
  3. 01-01 01:31:58.119 0 0 I msm_bam_device_lpm_ok: Going to LPM now
  4. 01-01 01:31:58.124 0 0 I android_work: android_work: sent uevent USB_STATE=DISCONNECTED
  5. 01-01 01:31:58.152 0 0 I msm_otg 78db000.usb: USB in low power mode
  6. 01-01 01:31:59.123 0 0 I init : Untracked pid 6249 exited with status 129 （注意这两条logs的时间戳）
  7. 05-05 01:32:08.788 0 0 I PM : suspend entry 2016-05-05 01:32:08.788320073 UTC  （时间对啦！！！）
  8. 05-05 01:32:08.788 0 0 I PM : Syncing filesystems ... done.
  9. 05-05 01:32:08.871 0 0 I : Freezing user space processes ...
  10. 05-05 01:32:08.873 0 0 E Error : returning -512 value
  11. 05-05 01:32:08.901 0 0 I : last active wakeup source: eventpoll
  12. 05-05 01:32:08.902 0 0 E : Freezing of tasks aborted after 0.030 seconds
  13. 05-05 01:32:08.907 0 0 I : Restarting tasks ... done.
  14. 05-05 01:32:08.932 0 0 I PM : suspend exit 2016-05-05 01:32:08.932476531 UTC
我们来看一下这个参数correction的默认值是多少。
  1. log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC)
从这个correction的初始值来看，这个值应该是正确的。只能说明在logd启动的时候，RTC时间没有被正确的设置。
也就是Qualcomm time daemon没有启动。这时候就涉及到了time daemon跟logd之间的先后顺序问题了。因为涉及到一些非open source的代码，
不在本博文范围之内。

另外一个方法是使用SELINUX的audit log。因为每一条audit log中都包含了时间戳。
  1. 36,2127,107424263（CLOCK_MONOTONIC 时间）,-;type=1400 audit(1462411803.160:14)（CLOCK_REALTIME时间）: avc: denied { kill } for pid=5438 comm="perfd" capability=5 scontext=u:r:perfd:s0 tcontext=u:r:perfd:s0 tclass=capability permissive=0
  2. 36,2128,167425781,-;type=1400 audit(1462411863.160:15): avc: denied { kill } for pid=5438 comm="perfd" capability=5 scontext=u:r:perfd:s0 tcontext=u:r:perfd:s0 tclass=capability permissive=0
这条log中跟suspend entry一样，同时包含了两种时间戳（只不过不是UTC格式的）。
可以利用这条log来修正correction变量。








阅读(12027) | 评论(0) | 转发(0) |
0

上一篇：如何写一个简易的文件系统（5）

下一篇：打开ftrace function graph，设备crash

给主人留下些什么吧！~~
关于我们 | 关于IT168 | 联系方式 | 广告合作 | 法律声明 | 免费注册

Copyright 2001-2010 ChinaUnix.net All Rights Reserved 北京皓辰网域网络信息技术有限公司. 版权所有

感谢所有关心和支持过ChinaUnix的朋友们

16024965号-6