Ich versuche, den Linux-Scheduler mit Lttng durch die Verfolgung der Ereignisse sched_wakeup
und sched_switch
im Kernel 4.4 (Ubuntu 16.04 LTS) zu verfolgen. Manchmal bekomme ich das Ereignis sched_wakeup
, noch bevor der Thread aus ist. Ich verstehe die Bedeutung dieses Aufweckens nicht, da der Thread bereits läuft. Das folgende ist ein Stück resultierenden babeltrace Protokoll, das dieses Verhalten zeigt (tid = 2326 wurden die Ereignisse mit Pfeilen markiert):Linux-Scheduler: sched_wakeup auf einer aktiven Aufgabe
-->[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 }
Weiß jemand, was das Wake-up tut? Muss ich weitere Informationen liefern?
Bearbeiten: Hinzufügen von zusätzlichen Informationen sowie ein neues Protokoll mit mehr Ereignissen.
Thread 2348 ist geplant mit SCHED_RR
auf Priorität 10. Die Zeitscheibe für RR ist der Standard-Vaulue (100ms denke ich). Das System wird stark vom Design überlastet, um die RT-scheduler
zu testen, die insgesamt 53 Threads ausführt, die alle unter Verwendung von SCHED_RR
geplant werden.
[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 }
Ich änderte den Titel und formatierte den Ergebnisabschnitt für die richtige Lesbarkeit. Ich habe auch die Keywords in der Hauptfrage hervorgehoben. – zx485