linux – lttng中的时间戳错误

发布时间：2020-12-13 23:21:05 所属栏目：Linux 来源：网络整理

导读：我正在尝试使用lttng来分析远程系统上的调度. 但是,使用babeltrace将跟踪显示为文本格式表示所有记录的事件都具有相同的时间戳.因此,TraceCompass中的可视化失败. thomas@horrorshow: babeltrace ~/temp/lttng/my-trace/MySystem/my-session-20170608-133943

我正在尝试使用lttng来分析远程系统上的调度.
但是,使用babeltrace将跟踪显示为文本格式表示所有记录的事件都具有相同的时间戳.因此,TraceCompass中的可视化失败.

thomas@horrorshow: babeltrace ~/temp/lttng/my-trace/MySystem/my-session-20170608-133943/ | head
[13:41:59.444999936] (+?.?????????) MySystem sched_stat_runtime: { cpu_id = 0 },{ comm = "lttng-sessiond",tid = 1533,runtime = 5016120,vruntime = 451268995605 }
[13:41:59.444999936] (+0.000000000) MySystem sched_waking: { cpu_id = 0 },{ comm = "lttng-consumerd",tid = 1547,prio = 20,target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 },runtime = 276632,vruntime = 451269272237 }
[13:41:59.444999936] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 },target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_switch: { cpu_id = 0 },{ prev_comm = "lttng-sessiond",prev_tid = 1533,prev_prio = 20,prev_state = 4096,next_comm = "lttng-consumerd",next_tid = 1547,next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_epoll_wait: { cpu_id = 0 },{ ret = 1,fds_length = 1,overflow = 0,fds = [ [0] = { data_union = { u64 = 0x1C,fd = 28 },raw_events = 0x1,events = { EPOLLIN = 1,EPOLLPRI = 0,EPOLLOUT = 0,EPOLLERR = 0,padding = 0 } } ] }
[13:41:59.444999936] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 },{ fd = 28,cmd = 62981,arg = 1547 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_ioctl: { cpu_id = 0 },{ ret = 0,arg = 1547 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 },cmd = 2147808776,arg = 3047156396 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_ioctl: { cpu_id = 0 },arg = 3047156396 }

thomas@horrorshow: babeltrace ~/temp/lttng/my-trace/MySystem/my-session-20170608-133943/ | tail
[13:41:59.444999936] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 },{ comm = "rcu_preempt",tid = 7,{ prev_comm = "lttng",prev_tid = 1698,next_comm = "rcu_preempt",next_tid = 7,next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 },runtime = 128301,vruntime = 456917982563 }
[13:41:59.444999936] (+0.000000000) MySystem sched_switch: { cpu_id = 0 },{ prev_comm = "rcu_preempt",prev_tid = 7,prev_state = 1,next_comm = "lttng",next_tid = 1698,next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem sched_waking: { cpu_id = 0 },{ comm = "lttng",tid = 1698,runtime = 209068,vruntime = 456921063330 }
[13:41:59.444999936] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 },next_comm = "lttng-sessiond",next_tid = 1533,next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_recvmsg: { cpu_id = 0 },{ ret = 13156,msg = 3046107868 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 },{ fd = 31,cmd = 63063,arg = 17 }

跟踪运行几秒钟,大小为912K.
我使用以下命令在嵌入式Linux设备上启动跟踪,使用lttng-relayd将数据传输到我的主机系统进行分析：

lttng create my-session --set-url=net://10.0.28.1
lttng enable-channel --kernel --subbuf-size=2621440 channel0
lttng enable-event --kernel --syscall --all --channel channel0
lttng enable-event --kernel --channel channel0 sched* 
lttng start
# Wait a bit
lttng stop

我该如何修复时间戳？

解决方法

The folks at the lttng-dev mailing list solved the problem for me：我意外地将内核模块加载到假的测试时钟,而不是真正的时钟的内核模块.

我的错误是我在lttng手动提供的所有.ko文件上运行了insmod.但是,正确的方法是让lttng-sessiond自动加载模块,这将忽略假的测试时钟模块.自动模块加载失败对我来说因为我在安装内核模块后没有运行depmod -a.

在depmod -a之后,一切正常,时间戳是正确的.

（编辑：李大同）

【声明】本站内容均来自网络，其相关言论仅代表作者个人观点，不代表本站立场。若无意侵犯到您的权利，请及时与联系站长删除相关内容!