Re: rcu_preempt caused oom

From: Paul E. McKenney
Date: Thu Nov 29 2018 - 09:45:44 EST

On Thu, Nov 29, 2018 at 05:06:47AM -0800, Paul E. McKenney wrote:
> On Thu, Nov 29, 2018 at 08:49:35AM +0000, He, Bo wrote:
> > Hi,
> > we test on kernel 4.19.0 on android, after run more than 24 Hours monkey stress test, we see OOM on 1/10 2G memory board, the issue is not seen on the 4.14 kernel.
> > we have done some debugs:
> > 1. OOM is due to the filp consume too many memory: 300M vs 2G board.
> > 2. with the 120s hung task detect, most of the tasks will block at __wait_rcu_gp: wait_for_completion(&rs_array[i].completion);

Did you did see any RCU CPU stall warnings? Or have those been disabled?
If they have been disabled, could you please rerun with them enabled?

> > [47571.863839] Kernel panic - not syncing: hung_task: blocked tasks
> > [47571.875446] CPU: 1 PID: 13626 Comm: FinalizerDaemon Tainted: G U O 4.19.0-quilt-2e5dc0ac-gf3f313245eb6 #1
> > [47571.887603] Call Trace:
> > [47571.890547] dump_stack+0x70/0xa5
> > [47571.894456] panic+0xe3/0x241
> > [47571.897977] ? wait_for_completion_timeout+0x72/0x1b0
> > [47571.903830] __wait_rcu_gp+0x17b/0x180
> > [47571.908226] synchronize_rcu.part.76+0x38/0x50
> > [47571.913393] ? __call_rcu.constprop.79+0x3a0/0x3a0
> > [47571.918948] ? __bpf_trace_rcu_invoke_callback+0x10/0x10
> > [47571.925094] synchronize_rcu+0x43/0x50
> > [47571.929487] evdev_detach_client+0x59/0x60
> > [47571.934264] evdev_release+0x4e/0xd0
> > [47571.938464] __fput+0xfa/0x1f0
> > [47571.942072] ____fput+0xe/0x10
> > [47571.945683] task_work_run+0x90/0xc0
> > [47571.949884] exit_to_usermode_loop+0x9f/0xb0
> > [47571.954855] do_syscall_64+0xfa/0x110
> > [47571.959151] entry_SYSCALL_64_after_hwframe+0x49/0xbe

This is indeed a task waiting on synchronize_rcu().

> > 3. after enable the rcu trace, we don't see rcu_quiescent_state_report trace in a long time, we see rcu_callback: rcu_preempt will never response with the rcu_invoke_callback.
> > [47572.040668] ps-12388 1d..1 47566097572us : rcu_grace_period: rcu_preempt 23716088 AccWaitCB
> > [47572.040707] ps-12388 1d... 47566097621us : rcu_callback: rcu_preempt rhp=00000000783a728b func=file_free_rcu 4354/82824
> > [47572.040734] ps-12388 1d..1 47566097622us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Startleaf
> > [47572.040756] ps-12388 1d..1 47566097623us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Prestarted
> > [47572.040778] ps-12388 1d..1 47566097623us : rcu_grace_period: rcu_preempt 23716088 AccWaitCB
> > [47572.040802] ps-12388 1d... 47566097674us : rcu_callback: rcu_preempt rhp=0000000042c76521 func=file_free_rcu 4354/82825
> > [47572.040824] ps-12388 1d..1 47566097676us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Startleaf
> > [47572.040847] ps-12388 1d..1 47566097676us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Prestarted
> > [47572.040868] ps-12388 1d..1 47566097676us : rcu_grace_period: rcu_preempt 23716088 AccWaitCB
> > [47572.040895] ps-12388 1d..1 47566097716us : rcu_callback: rcu_preempt rhp=000000005e40fde2 func=avc_node_free 4354/82826
> > [47572.040919] ps-12388 1d..1 47566097735us : rcu_callback: rcu_preempt rhp=00000000f80fe353 func=avc_node_free 4354/82827
> > [47572.040943] ps-12388 1d..1 47566097758us : rcu_callback: rcu_preempt rhp=000000007486f400 func=avc_node_free 4354/82828
> > [47572.040967] ps-12388 1d..1 47566097760us : rcu_callback: rcu_preempt rhp=00000000b87872a8 func=avc_node_free 4354/82829
> > [47572.040990] ps-12388 1d... 47566097789us : rcu_callback: rcu_preempt rhp=000000008c656343 func=file_free_rcu 4354/82830
> > [47572.041013] ps-12388 1d..1 47566097790us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Startleaf
> > [47572.041036] ps-12388 1d..1 47566097790us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Prestarted
> > [47572.041057] ps-12388 1d..1 47566097791us : rcu_grace_period: rcu_preempt 23716088 AccWaitCB
> > [47572.041081] ps-12388 1d... 47566097871us : rcu_callback: rcu_preempt rhp=000000007e6c898c func=file_free_rcu 4354/82831
> > [47572.041103] ps-12388 1d..1 47566097872us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Startleaf
> > [47572.041126] ps-12388 1d..1 47566097872us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Prestarted
> > [47572.041147] ps-12388 1d..1 47566097873us : rcu_grace_period: rcu_preempt 23716088 AccWaitCB
> > [47572.041170] ps-12388 1d... 47566097945us : rcu_callback: rcu_preempt rhp=0000000032f4f174 func=file_free_rcu 4354/82832
> > [47572.041193] ps-12388 1d..1 47566097946us : rcu_future_grace_period: rcu_preempt 23716088 23716092 0 0 3 Startleaf

Callbacks are being queued and future grace periods to handle them are being
requested, but as you say, no progress on the current grace period.

Is it possible to start the trace earlier?

> > Do you have any suggestions to debug the issue?
>
> If you do not already have CONFIG_RCU_BOOST=y set, could you please
> rebuild with that?
>
> Could you also please send your .config file?

So, to summarize:

1. If you don't have RCU CPU stall warnings enabled,
please enable them. For example, please remove
rcupdate.rcu_cpu_stall_suppress from the kernel boot
parameters if it is there.

Getting an RCU CPU stall warning would be extremely
helpful. It contains many useful diagnostics.

2. If possible, please start the trace before the last
grace period starts.

3. If CONFIG_RCU_BOOST=y is not set, please try setting it.

4. Please send me your .config file.

Thanx, Paul