> > On Wed, May 11, 2022 at 10:29:57AM -0400, Steven Rostedt wrote: > > > On Wed, 11 May 2022 15:39:56 +0200 > > > Uladzislau Rezki <urezki@xxxxxxxxx> wrote: > > > > > > > <snip> > > > > rcuop/6-54 [000] .N.. 183.753018: rcu_invoke_callback: rcu_preempt rhp=0xffffff88ffd440b0 func=__d_free.cfi_jt > > > > rcuop/6-54 [000] .N.. 183.753020: rcu_invoke_callback: rcu_preempt rhp=0xffffff892ffd8400 func=inode_free_by_rcu.cfi_jt > > > > rcuop/6-54 [000] .N.. 183.753021: rcu_invoke_callback: rcu_preempt rhp=0xffffff89327cd708 func=i_callback.cfi_jt > > > > ... > > > > rcuop/6-54 [000] .N.. 183.755941: rcu_invoke_callback: rcu_preempt rhp=0xffffff8993c5a968 func=i_callback.cfi_jt > > > > rcuop/6-54 [000] .N.. 183.755942: rcu_invoke_callback: rcu_preempt rhp=0xffffff8993c4bd20 func=__d_free.cfi_jt > > > > rcuop/6-54 [000] dN.. 183.755944: rcu_batch_end: rcu_preempt CBs-invoked=2112 idle=>c<>c<>c<>c< > > > > rcuop/6-54 [000] dN.. 183.755946: rcu_utilization: Start context switch > > > > rcuop/6-54 [000] dN.. 183.755946: rcu_utilization: End context switch > > > > <snip> > > > > > > > > i spent some time in order to understand why the context was not switched, > > > > even though the "rcuop" kthread was marked as TIF_NEED_RESCHED and an IPI > > > > was sent to the CPU_0 to reschedule. The last "." in latency field shows > > > > that a context has not disabled any preemption. So everything should be fine. > > > > > > > > An explanation is that a local_bh_disable() modifies the current_thread_info()->preempt.count > > > > so a task becomes non preemtable but the ftrace does not provide any signal about > > > > it. So i was fooled for some time by my tracer logs. > > > > > > > > Do you have any thoughts about it? Should it be solved or signaled > > > > somehow that a task in fact is not preemtable if a counter > 0? > > > > > > Hmm, it should show it in the first part (where the 'd' is). Is this a > > > snapshot from the kernel or from trace-cmd? > > > > > I do both and the behavior is the same. But the above one looks like a > > kernel trace output, the trace-cmd snapshot looks differently. So you > > mean "s" has to be there then? > > > > <snip> > > entry->preempt_count = pc & 0xff; > > entry->pid = (tsk) ? tsk->pid : 0; > > entry->type = type; > > entry->flags = > > #ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT > > (irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) | > > #else > > TRACE_FLAG_IRQS_NOSUPPORT | > > #endif > > ((pc & NMI_MASK ) ? TRACE_FLAG_NMI : 0) | > > ((pc & HARDIRQ_MASK) ? TRACE_FLAG_HARDIRQ : 0) | > > ((pc & SOFTIRQ_OFFSET) ? TRACE_FLAG_SOFTIRQ : 0) | > > (tif_need_resched() ? TRACE_FLAG_NEED_RESCHED : 0) | > > (test_preempt_need_resched() ? TRACE_FLAG_PREEMPT_RESCHED : 0); > > <snip> > > > > BTW, i am not the 5.10 kernel. I have not checked the latest kernel > > and what ftrace reports under holding local_bh_disable(). > > > Sorry, the was a typo. I am checking 5.10 kernel and the trace was taken > on that kernel. > OK. It was added on the latest kernel: root@pc638:/home/urezki# cat /sys/kernel/debug/tracing/trace_pipe vmalloc_test/0-1296 [062] b.... 18.157470: 0xffffffffc044e5dc: -> in the local_bh_disable() root@pc638:/home/urezki# cat /sys/kernel/debug/tracing/trace # tracer: nop # # entries-in-buffer/entries-written: 0/0 #P:64 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | root@pc638:/home/urezki# uname -a Linux pc638 5.17.0-rc2-next-20220201 #63 SMP PREEMPT Tue May 10 20:39:08 CEST 2022 x86_64 GNU/Linux root@pc638:/home/urezki# so it shows *bh* disabled sections. -- Uladzislau Rezki
