Add some helpers to report potential problem on scheduler side

[imran-kn]

No description provided.

[brenns10]

I really like this module, it's going to be really useful. The code looks great as well, but I have a suggestion. The docstrings for check_runq_wakelist and check_idle_runq have really useful context, and it's a bit of a shame for that context to be hidden away in the code.

Do you think it would be possible to make each explanation a global variable, and then have the run_queue_check() function print each explanation at the end, only if necessary? Something like this:

EXPLAIN_WAKELIST = """
[TASKS ON WAKE LIST]
    A runq's wakelist temporarily holds tasks that are about to be woken
    up on that CPU. If this list has multiple tasks, it usually means that
    this CPU has missed multiple scheduler IPIs. This can imply issues
    like IRQs being disabled for too long, IRQ delivery issues between hypervisor
    and VM, or some other issue.
"""
EXPLAIN_IDLE_RUNQ = """
[IDLE RUN QUEUE]
    ...
"""

Then, each function that performs checks could take a parameter, explanations: Set[str], and you could do:

explanations.add(EXPLAIN_WAKELIST)
print(f"cpu: {cpu} has following tasks in its runq wake_list:")
...
print("See TASKS ON WAKE LIST below")

And then run_queue_check() could handle printing out explanations:

explanations = set()
for cpu in for_each_online_cpu(prog):
    check_runq_wakelist(prog, cpu, explanations) 
    ...
if not explanations:
    return
print("Note: found some possible run queue issues. Explanations below:")
for explanation in explanations:
    print(explanation)

I think this would be really helpful even for support & sustaining because we don't all have the context for why a detected issue may be a problem, and what next steps we should look into.

[imran-kn]

I really like this module, it's going to be really useful. The code looks great as well, but I have a suggestion. The docstrings for check_runq_wakelist and check_idle_runq have really useful context, and it's a bit of a shame for that context to be hidden away in the code.

Do you think it would be possible to make each explanation a global variable, and then have the run_queue_check() function print each explanation at the end, only if necessary? Something like this:

EXPLAIN_WAKELIST = """
[TASKS ON WAKE LIST]
    A runq's wakelist temporarily holds tasks that are about to be woken
    up on that CPU. If this list has multiple tasks, it usually means that
    this CPU has missed multiple scheduler IPIs. This can imply issues
    like IRQs being disabled for too long, IRQ delivery issues between hypervisor
    and VM, or some other issue.
"""
EXPLAIN_IDLE_RUNQ = """
[IDLE RUN QUEUE]
    ...
"""

Then, each function that performs checks could take a parameter, explanations: Set[str], and you could do:

explanations.add(EXPLAIN_WAKELIST)
print(f"cpu: {cpu} has following tasks in its runq wake_list:")
...
print("See TASKS ON WAKE LIST below")

And then run_queue_check() could handle printing out explanations:

explanations = set()
for cpu in for_each_online_cpu(prog):
    check_runq_wakelist(prog, cpu, explanations) 
    ...
if not explanations:
    return
print("Note: found some possible run queue issues. Explanations below:")
for explanation in explanations:
    print(explanation)

I think this would be really helpful even for support & sustaining because we don't all have the context for why a detected issue may be a problem, and what next steps we should look into.

Yes its definitely possible and I agree that this help string can help in getting a better context of this data. I have made the suggested change

[imran-kn]

@brenns10 thanks a lot for taking a look and sharing your feedback. I have addressed the review comments but at the moment I see some jobs failing. This looks like a setup issue.

[brenns10]

Thanks for adding the explanations! I think that'll be a great model as we start moving into more proactive checks & anomaly detection.

Since these helpers only execute on non-live systems, I triggered the vmcore tests on Gitlab (simply pushing a branch to the internal gitlab will do it, and you can view results under the "Pipelines" tab). There are some errors there -- one of which is from me which I'm fixing (#194), but the bigger issue is that the wake_list field is gone since UEK7, so we'll need to make sure this works on UEK7&8.

[brenns10]

I was thinking that the explanation should only appear if one of the checks failed. So something more like this:

Suggested change

	explanations.add(EXPLAIN_IDLE_RUNQ)
	if runq.nr_running.value_() != 0:
	print(f"Idle cpu: {cpu} has non-zero nr_running")
	nr_cfs_task = num_tasks_on_cfs_rq(prog, cpu)
	nr_rt_task = num_tasks_on_rt_rq(prog, cpu)
	nr_dl_task = num_tasks_on_dl_rq(prog, cpu)
	if nr_cfs_task != 0:
	print(f"Idle cpu: {cpu} has {nr_cfs_task} tasks on CFS runq")
	if nr_rt_task != 0:
	print(f"Idle cpu: {cpu} has {nr_rt_task} tasks on RT runq")
	if nr_dl_task != 0:
	print(f"Idle cpu: {cpu} has {nr_dl_task} tasks on DL runq")
	print("See IDLE RUN QUEUE below")
	if runq.nr_running.value_() != 0:
	print(f"Idle cpu: {cpu} has non-zero nr_running [IDLE RUN QUEUE]")
	explanations.add(EXPLAIN_IDLE_RUNQ)
	nr_cfs_task = num_tasks_on_cfs_rq(prog, cpu)
	nr_rt_task = num_tasks_on_rt_rq(prog, cpu)
	nr_dl_task = num_tasks_on_dl_rq(prog, cpu)
	if nr_cfs_task != 0:
	print(f"Idle cpu: {cpu} has {nr_cfs_task} tasks on CFS runq [IDLE RUN QUEUE]")
	explanations.add(EXPLAIN_IDLE_RUNQ)
	if nr_rt_task != 0:
	print(f"Idle cpu: {cpu} has {nr_rt_task} tasks on RT runq [IDLE RUN QUEUE]")
	explanations.add(EXPLAIN_IDLE_RUNQ)
	if nr_dl_task != 0:
	print(f"Idle cpu: {cpu} has {nr_dl_task} tasks on DL runq [IDLE RUN QUEUE]")
	explanations.add(EXPLAIN_IDLE_RUNQ)

[brenns10]

1. The print("\n") prints two blank lines, since the print() function always appends a newline to the string you give it. Is that intentional? If you only want one newline, print() with no argument would suffice.
2. I'm not sure whether I love the idea of printing all these newlines. Whenever helper functions start printing their own newlines, the output can have lots of extra spaces and it can be a bit difficult to read or track down which function printed which one. Instead, could we just indent each task for this CPU? That way, there is still visual grouping for each CPU, but we don't have the newlines contributing to odd spacing.

[brenns10]

Since torvalds/linux@a148866489fbe ("sched: Replace rq::wake_list"), wake_list doesn't exist, so this function doesn't work on UEK7 and later.

[brenns10]

These functions are the same, except for which kind of scheduler runqueue they operate on. Further, there's not an equivalent for the deadline scheduler. I think that makes sense for the deadline scheduler, because the deadline period may be greater than the threshold value -- though correct me if that was not the motivation for omitting it.

Regardless, it seems we should not have two copies of this function hanging around. Could we instead have a function that takes an iterable of tasks, plus a runqueue object (for consulting the runq clock), and prints out these warnings? Something like this:

Suggested change

	def dump_rt_runq_wait_summary(
	prog: Program, cpu: int, qduration_thresh_ms: int = 1000
	):
	"""
	Iterate through all tasks, on a CPU's runq and list tasks that have been queued
	for greater than specified threshold in ms (default 1000 ms).
	:param prog: drgn Program
	:param cpu: cpu number
	:param qduration_thresh_ms: threshold for wait duration on runq
	"""
	runq = per_cpu(prog["runqueues"], cpu)
	for task in for_each_task_on_rt_rq(prog, cpu):
	try:
	if (
	task.sched_info.last_queued.value_() > 0
	and task.sched_info.last_queued.value_()
	> task.sched_info.last_arrival.value_()
	):
	qduration = (
	runq.clock.value_() - task.sched_info.last_queued.value_()
	)
	print(
	f"cpu: {cpu} pid: {task.pid.value_()} prio: {task.prio.value_()} queued for {qduration} nsecs"
	)
	except AttributeError:
	pass
	def dump_cfs_runq_wait_summary(
	prog: Program, cpu: int, qduration_thresh_ms: int = 1000
	):
	"""
	Iterate through all tasks, on a CPU's runq and list tasks that have been queued
	for greater than specified threshold in ms (default 1000 ms).
	:param prog: drgn Program
	:param cpu: cpu number
	:param qduration_thresh_ms: threshold for wait duration on runq
	"""
	runq = per_cpu(prog["runqueues"], cpu)
	for task in for_each_task_on_cfs_rq(prog, cpu):
	try:
	if (
	task.sched_info.last_queued.value_() > 0
	and task.sched_info.last_queued.value_()
	> task.sched_info.last_arrival.value_()
	):
	qduration = (
	runq.clock.value_() - task.sched_info.last_queued.value_()
	)
	print(
	f"cpu: {cpu} pid: {task.pid.value_()} prio: {task.prio.value_()} queued for {qduration} nsecs"
	)
	except AttributeError:
	pass
	def dump_waiting_task_summary(
	cpu: int,
	runq: Object,
	tasks: Iterable[Object],
	qduration_thresh_ms: int = 1000,
	):
	"""
	Print tasks on a CPU's runq that have been queued
	for greater than specified threshold in ms (default 1000 ms).
	:param cpu: cpu number
	:param runq: CPU's ``struct rq *``
	:param tasks: iterable of ``struct task_struct *`` to check
	:param qduration_thresh_ms: threshold for wait duration on runq
	"""
	for task in tasks:
	try:
	if (
	task.sched_info.last_queued.value_() > 0
	and task.sched_info.last_queued.value_()
	> task.sched_info.last_arrival.value_()
	):
	qduration = (
	runq.clock.value_() - task.sched_info.last_queued.value_()
	)
	print(
	f"cpu: {cpu} pid: {task.pid.value_()} prio: {task.prio.value_()} queued for {qduration} nsecs"
	)
	except AttributeError:
	pass

And we could call this function by:

from itertools import chain

tasks = chain(
    for_each_task_on_rt_rq(prog, cpu),
    for_each_task_on_cfs_rq(prog, cpu),
    # if dl should be included:
    # for_each_task_on_dl_rq(prog, cpu),
)
dump_waiting_task_summary(cpu, per_pcu(prog["runqueues"], cpu), tasks)

Finally:

1. Is except AttributeError necessary? We need this to be compatible with UEK5+, so if we need a helper to correctly compute this (or if we already have one), let's do it and make sure we handle the cases, and then drop the exception handler here. Swallowing errors doesn't prevent them, it just hides them.
2. Can we have an explanation for this one too? I know it's a bit obvious, but it's good to follow the pattern.

[brenns10]

As noted elsewhere, wake_list is gone from UEK7 and later.