Find root of the stall: was: Re: [PATCH 2/3] livepatch: Avoid blocking tasklist_lock too long

[Petr Mladek <pmladek@suse.com>]

On Tue 2025-02-11 14:24:36, Yafang Shao wrote:
> I encountered a hard lockup when attempting to reproduce the panic issue
> occurred on our production servers [0]. The hard lockup is as follows,
> 
> [15852778.150191] livepatch: klp_try_switch_task: grpc_executor:421106 is sleeping on function do_exit
> [15852778.169471] livepatch: klp_try_switch_task: grpc_executor:421244 is sleeping on function do_exit
> [15852778.188746] livepatch: klp_try_switch_task: grpc_executor:421457 is sleeping on function do_exit
> [15852778.208021] livepatch: klp_try_switch_task: grpc_executor:422407 is sleeping on function do_exit
> [15852778.227292] livepatch: klp_try_switch_task: grpc_executor:423184 is sleeping on function do_exit
> [15852778.246576] livepatch: klp_try_switch_task: grpc_executor:423582 is sleeping on function do_exit
> [15852778.265863] livepatch: klp_try_switch_task: grpc_executor:423738 is sleeping on function do_exit
> [15852778.285149] livepatch: klp_try_switch_task: grpc_executor:423739 is sleeping on function do_exit
> [15852778.304446] livepatch: klp_try_switch_task: grpc_executor:423833 is sleeping on function do_exit
> [15852778.323738] livepatch: klp_try_switch_task: grpc_executor:423893 is sleeping on function do_exit
> [15852778.343017] livepatch: klp_try_switch_task: grpc_executor:423894 is sleeping on function do_exit
> [15852778.362292] livepatch: klp_try_switch_task: grpc_executor:423976 is sleeping on function do_exit
> [15852778.381565] livepatch: klp_try_switch_task: grpc_executor:423977 is sleeping on function do_exit
> [15852778.400847] livepatch: klp_try_switch_task: grpc_executor:424610 is sleeping on function do_exit

This message does not exist in vanilla kernel. It looks like an extra
debug message. And many extra messages might create stalls on its own.

AFAIK, your reproduced the problem even without these extra messages.
At least, I see the following at
https://lore.kernel.org/r/CALOAHbB8j6RrpJAyRkzPx2U6YhjWEipRspoQQ_7cvQ+M0zgdXg@mail.gmail.com

<paste>
[20329703.332453] livepatch: enabling patch 'livepatch_61_release6'
[20329703.340417] livepatch: 'livepatch_61_release6': starting
patching transition
[20329715.314215] rcu_tasks_wait_gp: rcu_tasks grace period 1109765 is
10166 jiffies old.
[20329737.126207] rcu_tasks_wait_gp: rcu_tasks grace period 1109769 is
10219 jiffies old.
[20329752.018236] rcu_tasks_wait_gp: rcu_tasks grace period 1109773 is
10199 jiffies old.
[20329754.848036] livepatch: 'livepatch_61_release6': patching complete
</paste>

Could you please confirm that this the original _non-filtered_ log?
I mean that the debug messages were _not_ printed and later filtered?

I would like to know more about the system where RCU reported the
stall. How many processes are running there in average?
A rough number is enough. I wonder if it is about 1000, 10000, or
50000?

Also what is the CONFIG_HZ value, please?

Also we should get some statistics how long klp_try_switch_task()
lasts in average. I have never did it but I guess that
it should be rather easy with perf. Or maybe just by looking
at function_graph trace.

I would like to be more sure that klp_try_complete_transition() really
could block RCU for that long. I would like to confirm that
the following is the reality:

  num_processes * average_klp_try_switch_task > 10second

If it is true than we really need to break the cycle after some
timeout. And rcu_read_lock() is _not_ a solution because it would
block RCU the same way.

Does it make sense, please?

Best Regards,
Petr