Linux scheduler: sched_wakeup on an active task

Question

I am trying to trace the Linux scheduler using Lttng by tracing the events sched_wakeup and sched_switch in the 4.4 kernel (Ubuntu 16.04 LTS). Sometimes I get the sched_wakeup event even before the thread has switched out. I don't understand the significance of this wakeup, since the thread is already running. The following is a piece of resulting babeltrace log that shows this behaviour(tid = 2326, the events were marked with arrows):

-->[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 }

Does anyone know what this wakeup does? Do I need to supply any more information?

Edit: Adding additional information as well as a new log containing more events.

Thread 2348 is scheduled using SCHED_RR on priority 10. The time slice for RR is the default vaulue (100ms I think). The system is heavily overloaded by design in order to test the RT-scheduler, running a total of 53 threads all scheduled using 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 }

I changed the title and formatted the result section for proper readability. I also highlighted the keywords in the main question. — zx485, May 06 '16 at 15:20

score 0 · Answer 1 · answered May 05 '16 at 13:24

0

Not sure why the 2326 thread was not scheduled out after entering the nanosleep (maybe you have some RT configuration), but since it is sleeping, a wakeup can probably reach it.

You could enable sched_waking (to know exactly what is the waker) and the hrtimer events to have more information.

answered May 05 '16 at 13:24

Julien Desfossez

11
1

Thanks, I added the new events to the trace and ran it again. Still don't really know why it behaves as it does. It should switch out as the system is heavily overloaded. I am using the RT-scheduler with SCHED_RR, I forgot to mention that in the original post. I edited the post, also adding in a new log showing the new events. – Cupo May 09 '16 at 10:42

Linux scheduler: sched_wakeup on an active task

1 Answers1