我试图使用Lttng跟踪4.4内核(Ubuntu16.04LTS)中的事件sched_wakeup
和sched_switch
来跟踪Linux调度程序。有时候,我甚至在线程关闭之前就得到了sched_wakeup
事件。我不明白这个唤醒的意义,因为线程已经在运行。下面是显示此行为(tid= 2326,事件被用箭头标记)的生成babeltrace日志的一部分:
-->[15:22:39.515333895] (+0.000001956) usr-VirtualBox sched_switch: { cpu_id = 1 }, { vtid = 2342, procname = "test" }, { prev_comm = "test", prev_tid = 2342, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2326, next_prio = -11 }
[15:22:39.515374982] (+0.000001397) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2323, procname = "test" }, { prev_comm = "test", prev_tid = 2323, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2328, next_prio = -11 }
[15:22:39.515376100] (+0.000001118) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 1 }, { vtid = 2326, procname = "test" }, { rqtp = 140003026402816 }
[15:22:39.515378336] (+0.000002236) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2328, procname = "test" }, { ret = 0, rmtp = 140003009617392 }
-->[15:22:39.515413833] (+0.000003074) usr-VirtualBox sched_wakeup: { cpu_id = 1 }, { vtid = 2326, procname = "test" }, { comm = "test", tid = 2326, prio = -11, target_cpu = 1 }
[15:22:39.515418026] (+0.000002516) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2328, procname = "test" }, { rqtp = 140003009617408 }
[15:22:39.515425293] (+0.000007267) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2328, procname = "test" }, { prev_comm = "test", prev_tid = 2328, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2334, next_prio = -11 }
[15:22:39.515428088] (+0.000002795) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2334, procname = "test" }, { ret = 0, rmtp = 140002959261168 }
[15:22:39.515428647] (+0.000000559) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 1 }, { vtid = 2326, procname = "test" }, { ret = 0, rmtp = 140003026402800 }
[15:22:39.515468616] (+0.000000838) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2334, procname = "test" }, { comm = "test", tid = 2336, prio = -11, target_cpu = 0 }
[15:22:39.515475045] (+0.000002516) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 1 }, { vtid = 2326, procname = "test" }, { rqtp = 140003026402816 }
[15:22:39.515482592] (+0.000007547) usr-VirtualBox syscall_entry_clock_gettime: { cpu_id = 0 }, { vtid = 2334, procname = "test" }, { which_clock = 1 }
-->[15:22:39.515483430] (+0.000000838) usr-VirtualBox sched_switch: { cpu_id = 1 }, { vtid = 2326, procname = "test" }, { prev_comm = "test", prev_tid = 2326, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2325, next_prio = -11 }
有人知道这个唤醒是干什么的吗?我需要提供更多的信息吗?
编辑:添加附加信息的以及包含更多事件的新日志。
线程2348是在优先级10上使用SCHED_RR
调度的。RR的时间片是默认的值(我认为是100 is )。为了测试RT-scheduler
,系统被设计的负载过重,总共运行了53个线程,这些线程都是使用SCHED_RR
调度的。
[09:11:06.284125458] (+0.000001957) usr-VirtualBox sched_waking: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { comm = "test", tid = 2348, prio = -11, target_cpu = 0 }
[09:11:06.284130489] (+0.000001957) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { comm = "test", tid = 2348, prio = -11, target_cpu = 0 }
[09:11:06.284133004] (+0.000002515) usr-VirtualBox timer_hrtimer_expire_exit: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88 }
[09:11:06.284203160] (+0.000003354) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { rqtp = 140046423100928 }
[09:11:06.284206234] (+0.000003074) usr-VirtualBox timer_hrtimer_init: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88, clockid = 1, mode = 1 }
[09:11:06.284210707] (+0.000004473) usr-VirtualBox timer_hrtimer_start: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88, function = 0xFFFFFFFF810EED30, expires = 91708656312, softexpires = 91708656312 }
[09:11:06.284225800] (+0.000011460) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { prev_comm = "test", prev_tid = 2347, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2348, next_prio = -11 }
[09:11:06.284270241] (+0.000002516) usr-VirtualBox timer_hrtimer_cancel: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88 }
[09:11:06.284273036] (+0.000000279) usr-VirtualBox timer_hrtimer_expire_entry: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88, now = 91708703021, function = 0xFFFFFFFF810EED30 }
[09:11:06.284276390] (+0.000000838) usr-VirtualBox sched_waking: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { comm = "test", tid = 2347, prio = -11, target_cpu = 0 }
[09:11:06.284281421] (+0.000005031) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { comm = "test", tid = 2347, prio = -11, target_cpu = 0 }
[09:11:06.284285334] (+0.000003913) usr-VirtualBox timer_hrtimer_expire_exit: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88 }
[09:11:06.284299310] (+0.000002796) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { ret = 0, rmtp = 140046414708208 }
[09:11:06.284365832] (+0.000002516) usr-VirtualBox timer_hrtimer_cancel: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF88001969BE88 }
[09:11:06.284369745] (+0.000003075) usr-VirtualBox timer_hrtimer_expire_entry: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF88001969BE88, now = 91708799171, function = 0xFFFFFFFF810EED30 }
[09:11:06.284372260] (+0.000000559) usr-VirtualBox sched_waking: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { comm = "test", tid = 2319, prio = -11, target_cpu = 0 }
[09:11:06.284375055] (+0.000000559) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { comm = "test", tid = 2319, prio = -11, target_cpu = 0 }
[09:11:06.284385956] (+0.000010901) usr-VirtualBox timer_hrtimer_expire_exit: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF88001969BE88 }
[09:11:06.284406360] (+0.000001118) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { rqtp = 140046414708224 }
[09:11:06.284408875] (+0.000000838) usr-VirtualBox timer_hrtimer_init: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, clockid = 1, mode = 1 }
[09:11:06.284413627] (+0.000004752) usr-VirtualBox timer_hrtimer_start: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, function = 0xFFFFFFFF810EED30, expires = 91708869016, softexpires = 91708869016 }
[09:11:06.284431795] (+0.000003634) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { prev_comm = "test", prev_tid = 2348, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2347, next_prio = -11 }
[09:11:06.284437105] (+0.000002795) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { ret = 0, rmtp = 140046423100912 }
[09:11:06.284456950] (+0.000019845) usr-VirtualBox timer_hrtimer_cancel: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88 }
[09:11:06.284459745] (+0.000001956) usr-VirtualBox timer_hrtimer_expire_entry: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, now = 91708890569, function = 0xFFFFFFFF810EED30 }
[09:11:06.284462540] (+0.000001956) usr-VirtualBox sched_waking: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { comm = "test", tid = 2348, prio = -11, target_cpu = 0 }
[09:11:06.284467292] (+0.000003913) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { comm = "test", tid = 2348, prio = -11, target_cpu = 0 }
[09:11:06.284470087] (+0.000001957) usr-VirtualBox timer_hrtimer_expire_exit: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88 }
[09:11:06.284535212] (+0.000001118) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { rqtp = 140046423100928 }
[09:11:06.284537727] (+0.000000838) usr-VirtualBox timer_hrtimer_init: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88, clockid = 1, mode = 1 }
[09:11:06.284542479] (+0.000004752) usr-VirtualBox timer_hrtimer_start: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88, function = 0xFFFFFFFF810EED30, expires = 91708993675, softexpires = 91708993675 }
[09:11:06.284559528] (+0.000002795) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2347, procname = "test" }, { prev_comm = "test", prev_tid = 2347, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2319, next_prio = -11 }
[09:11:06.284579094] (+0.000002236) usr-VirtualBox timer_hrtimer_cancel: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88 }
[09:11:06.284582727] (+0.000003354) usr-VirtualBox timer_hrtimer_expire_entry: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88, now = 91709012433, function = 0xFFFFFFFF810EED30 }
[09:11:06.284585243] (+0.000000559) usr-VirtualBox sched_waking: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { comm = "test", tid = 2347, prio = -11, target_cpu = 0 }
[09:11:06.284590833] (+0.000000559) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { comm = "test", tid = 2347, prio = -11, target_cpu = 0 }
[09:11:06.284593628] (+0.000002795) usr-VirtualBox timer_hrtimer_expire_exit: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { hrtimer = 0xFFFF8800256E7E88 }
[09:11:06.284607324] (+0.000003075) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { ret = 0, rmtp = 140046658096624 }
[09:11:06.284649529] (+0.000001956) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { rqtp = 140046658096640 }
[09:11:06.284652045] (+0.000002516) usr-VirtualBox timer_hrtimer_init: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { hrtimer = 0xFFFF88001969BE88, clockid = 1, mode = 1 }
[09:11:06.284656796] (+0.000001118) usr-VirtualBox timer_hrtimer_start: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { hrtimer = 0xFFFF88001969BE88, function = 0xFFFFFFFF810EED30, expires = 91709780826, softexpires = 91709780826 }
-->[09:11:06.284673007] (+0.000001118) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2319, procname = "test" }, { prev_comm = "test", prev_tid = 2319, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2348, next_prio = -11 }
[09:11:06.284678318] (+0.000003634) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { ret = 0, rmtp = 140046414708208 }
[09:11:06.284746238] (+0.000002516) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { rqtp = 140046414708224 }
[09:11:06.284749033] (+0.000001398) usr-VirtualBox timer_hrtimer_init: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, clockid = 1, mode = 1 }
[09:11:06.284753784] (+0.000001397) usr-VirtualBox timer_hrtimer_start: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, function = 0xFFFFFFFF810EED30, expires = 91709190725, softexpires = 91709190725 }
[09:11:06.284800182] (+0.000036615) usr-VirtualBox timer_hrtimer_cancel: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88 }
[09:11:06.284803257] (+0.000002795) usr-VirtualBox timer_hrtimer_expire_entry: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, now = 91709233521, function = 0xFFFFFFFF810EED30 }
[09:11:06.284806331] (+0.000002236) usr-VirtualBox sched_waking: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { comm = "test", tid = 2348, prio = -11, target_cpu = 0 }
-->[09:11:06.284811921] (+0.000005031) usr-VirtualBox sched_wakeup: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { comm = "test", tid = 2348, prio = -11, target_cpu = 0 }
[09:11:06.284814996] (+0.000002516) usr-VirtualBox timer_hrtimer_expire_exit: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88 }
[09:11:06.284834282] (+0.000019007) usr-VirtualBox syscall_exit_nanosleep: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { ret = 0, rmtp = 140046414708208 }
[09:11:06.284885990] (+0.000002515) usr-VirtualBox syscall_entry_nanosleep: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { rqtp = 140046414708224 }
[09:11:06.284888506] (+0.000002236) usr-VirtualBox timer_hrtimer_init: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, clockid = 1, mode = 1 }
[09:11:06.284893537] (+0.000004752) usr-VirtualBox timer_hrtimer_start: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { hrtimer = 0xFFFF8800256EFE88, function = 0xFFFFFFFF810EED30, expires = 91709347527, softexpires = 91709347527 }
-->[09:11:06.284915338] (+0.000021522) usr-VirtualBox sched_switch: { cpu_id = 0 }, { vtid = 2348, procname = "test" }, { prev_comm = "test", prev_tid = 2348, prev_prio = -11, prev_state = 1, next_comm = "test", next_tid = 2347, next_prio = -11 }
发布于 2016-05-05 13:24:11
不知道为什么2326线程在进入纳米睡眠后没有被调度出来(也许您有一些RT配置),但是由于它正在休眠,唤醒可能会到达它。
您可以让sched_waking (确切地知道waker是什么)和hrtimer事件有更多的信息。
https://stackoverflow.com/questions/37006728
复制相似问题