Linux scheduler: sched_wakeup в активной задаче

Я пытаюсь отслеживать планировщик Linux с помощью Lttng, отслеживая события sched_wakeup и sched_switch в ядре 4.4 (Ubuntu 16.04 LTS). Иногда я получаю событие sched_wakeup еще до того, как поток отключился. Я не понимаю значение этого пробуждения, поскольку поток уже запущен. Ниже приведен фрагмент в результате журнала babeltrace, который показывает такое поведение (TID = 2326, события были отмечены стрелками):Linux scheduler: sched_wakeup в активной задаче

-->[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 запланирована с использованием SCHED_RR в приоритете 10. Временной срез для RR является ваулером по умолчанию (думаю, это 100 мс). Система сильно перегружена конструкцией, чтобы протестировать 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-03 Cupo

Я изменил название и отформатировал раздел результатов для правильной читаемости. Я также выделил ключевые слова в главном вопросе. – zx485

Не знаю, почему 2326 поток не был запланирован после ввода nanosleep (возможно, у вас есть некоторые конфигурации RT), но так как он спит, к пробуждению, вероятно, может достичь его.

Вы можете включить sched_waking (чтобы точно знать, что такое waker) и события hrtimer, чтобы получить дополнительную информацию.

источник

2016-05-05 13:24:11

Спасибо, я добавил новые события в след и снова запустил его. Все еще не знаю, почему он ведет себя так, как он. Он должен переключаться, поскольку система сильно перегружена. Я использую RT-планировщик с SCHED_RR, я забыл упомянуть об этом в оригинальном посте. Я редактировал сообщение, также добавляя в новый журнал, показывающий новые события. – Cupo

Linux scheduler: sched_wakeup в активной задаче

ответ

Смежные вопросы