From: Uladzislau Rezki <urezki@gmail.com>
To: Joel Fernandes <joel@joelfernandes.org>
Cc: Uladzislau Rezki <urezki@gmail.com>,
rcu@vger.kernel.org, linux-kernel@vger.kernel.org,
rushikesh.s.kadam@intel.com, neeraj.iitr10@gmail.com,
frederic@kernel.org, paulmck@kernel.org, rostedt@goodmis.org
Subject: Re: [PATCH v6 1/4] rcu: Make call_rcu() lazy to save power
Date: Tue, 27 Sep 2022 16:08:18 +0200 [thread overview]
Message-ID: <YzMD0pdR6rvGSZ/o@pc636> (raw)
In-Reply-To: <YzIRg2u2JYXN9bnK@google.com>
On Mon, Sep 26, 2022 at 08:54:27PM +0000, Joel Fernandes wrote:
> Hi Vlad,
>
> On Mon, Sep 26, 2022 at 09:39:23PM +0200, Uladzislau Rezki wrote:
> [...]
> > > > On my KVM machine the boot time is affected:
> > > >
> > > > <snip>
> > > > [ 2.273406] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
> > > > [ 11.945283] e1000 0000:00:03.0 ens3: renamed from eth0
> > > > [ 22.165198] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
> > > > [ 22.165206] cdrom: Uniform CD-ROM driver Revision: 3.20
> > > > [ 32.406981] sr 1:0:0:0: Attached scsi CD-ROM sr0
> > > > [ 104.115418] process '/usr/bin/fstype' started with executable stack
> > > > [ 104.170142] EXT4-fs (sda1): mounted filesystem with ordered data mode. Quota mode: none.
> > > > [ 104.340125] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
> > > > [ 104.340193] systemd[1]: Detected virtualization kvm.
> > > > [ 104.340196] systemd[1]: Detected architecture x86-64.
> > > > [ 104.359032] systemd[1]: Set hostname to <pc638>.
> > > > [ 105.740109] random: crng init done
> > > > [ 105.741267] systemd[1]: Reached target Remote File Systems.
> > > > <snip>
> > > >
> > > > 2 - 11 and second delay is between 32 - 104. So there are still users which must
> > > > be waiting for "RCU" in a sync way.
> > >
> > > I was wondering if you can compare boot logs and see which timestamp does the
> > > slow down start from. That way, we can narrow down the callback. Also another
> > > idea is, add "trace_event=rcu:rcu_callback,rcu:rcu_invoke_callback
> > > ftrace_dump_on_oops" to the boot params, and then manually call
> > > "tracing_off(); panic();" from the code at the first printk that seems off in
> > > your comparison of good vs bad. For example, if "crng init done" timestamp is
> > > off, put the "tracing_off(); panic();" there. Then grab the serial console
> > > output to see what were the last callbacks that was queued/invoked.
>
> Would you be willing to try these steps? Meanwhile I will try on my side as
> well with the .config you sent me in another email.
>
Not exactly those steps. But see below:
<snip>
[ 2.291319] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 17.302946] e1000 0000:00:03.0 ens3: renamed from eth0
<snip>
15 seconds delay between two prints. I have logged all call_rcu() users
between those two prints:
<snip>
# tracer: nop
#
# entries-in-buffer/entries-written: 166/166 #P:64
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
systemd-udevd-669 [002] ..... 2.338739: e1000_probe: Intel(R) PRO/1000 Network Connection
systemd-udevd-665 [061] ..... 2.338952: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 2.338962: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-665 [061] ..... 2.338965: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 2.338968: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-665 [061] ..... 2.338987: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-645 [053] ..... 2.338989: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 2.338999: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-645 [053] ..... 2.339002: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 2.339024: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
kworker/0:3-546 [000] d..1. 6.329516: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70effe40a0
rcuop/0-17 [000] b.... 6.337320: __call_rcu_common: -> 0x0: exit_creds+0x63/0x70 <- 0x0
kworker/38:1-744 [038] d..1. 6.841479: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f97e40a0
<...>-739 [035] d..1. 6.841479: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f8be40a0
<...>-732 [021] d..1. 6.841486: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f53e40a0
kworker/36:1-740 [036] d..1. 6.841487: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f8fe40a0
rcuop/21-170 [023] b.... 6.849276: __call_rcu_common: -> 0x0: exit_creds+0x63/0x70 <- 0x0
rcuop/38-291 [052] b.... 6.849950: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/38-291 [052] b.... 6.849957: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
kworker/5:1-712 [005] d..1. 7.097392: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f13e40a0
kworker/19:1-727 [019] d..1. 7.097392: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f4be40a0
<...>-719 [007] d..1. 7.097392: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f1be40a0
kworker/13:1-721 [013] d..1. 7.097392: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f33e40a0
kworker/52:1-756 [052] d..1. 7.097395: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fcfe40a0
kworker/29:1-611 [029] d..1. 7.097395: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f73e40a0
<...>-754 [049] d..1. 7.097405: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fc3e40a0
kworker/12:1-726 [012] d..1. 7.097405: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f2fe40a0
kworker/53:1-710 [053] d..1. 7.097405: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fd3e40a0
<...>-762 [061] d..1. 7.097405: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70ff3e40a0
<...>-757 [054] d..1. 7.097408: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fd7e40a0
kworker/25:1-537 [025] d..1. 7.097408: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f63e40a0
<...>-714 [004] d..1. 7.097408: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f0fe40a0
<...>-749 [044] d..1. 7.097413: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fafe40a0
kworker/51:1-755 [051] d..1. 7.097413: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fcbe40a0
<...>-764 [063] d..1. 7.097415: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70ffbe40a0
<...>-753 [045] d..1. 7.097416: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fb3e40a0
kworker/43:1-748 [043] d..1. 7.097416: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fabe40a0
kworker/41:1-747 [041] d..1. 7.097416: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fa3e40a0
kworker/57:1-760 [057] d..1. 7.097416: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fe3e40a0
<...>-720 [008] d..1. 7.097418: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f1fe40a0
kworker/58:1-759 [058] d..1. 7.097421: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fe7e40a0
kworker/16:1-728 [016] d..1. 7.097424: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f3fe40a0
<...>-722 [010] d..1. 7.097427: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f27e40a0
kworker/22:1-733 [022] d..1. 7.097432: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f57e40a0
<...>-731 [026] d..1. 7.097432: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f67e40a0
<...>-752 [048] d..1. 7.097437: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fbfe40a0
kworker/18:0-147 [018] d..1. 7.097437: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f47e40a0
kworker/39:1-745 [039] d..1. 7.097437: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f9be40a0
<...>-716 [003] d..1. 7.097437: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70f0be40a0
<...>-703 [050] d..1. 7.097437: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fc7e40a0
kworker/42:1-746 [042] d..1. 7.097444: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70fa7e40a0
rcuop/13-113 [013] b.... 7.105592: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/13-113 [013] b.... 7.105595: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/10-92 [040] b.... 7.105608: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/10-92 [040] b.... 7.105610: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/16-135 [023] b.... 7.105613: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/8-78 [039] b.... 7.105636: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/8-78 [039] b.... 7.105640: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/12-106 [040] b.... 7.105651: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/12-106 [040] b.... 7.105652: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/19-156 [000] b.... 7.105727: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/19-156 [000] b.... 7.105730: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/5-56 [058] b.... 7.105808: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/5-56 [058] b.... 7.105814: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/20-163 [023] b.... 17.345648: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/20-163 [023] b.... 17.345655: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/14-120 [013] b.... 17.345675: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/14-120 [013] b.... 17.345681: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/6-63 [013] b.... 17.345714: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/6-63 [013] b.... 17.345715: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/9-85 [000] b.... 17.345753: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/9-85 [000] b.... 17.345758: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/17-142 [000] b.... 17.345775: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/17-142 [000] b.... 17.345776: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/17-142 [000] b.... 17.345777: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/11-99 [000] b.... 17.345810: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/11-99 [000] b.... 17.345811: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/15-127 [013] b.... 17.345832: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/15-127 [013] b.... 17.345834: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/1-28 [000] b.... 17.345834: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/1-28 [000] b.... 17.345835: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/15-127 [013] b.... 17.345835: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/15-127 [013] b.... 17.345837: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
systemd-udevd-633 [035] ..... 17.346591: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-633 [035] ..... 17.346609: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-633 [035] ..... 17.346659: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-633 [035] ..... 17.346666: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-669 [002] ..... 17.347573: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
kworker/2:2-769 [002] ..... 17.347659: __call_rcu_common: -> 0x0: __wait_rcu_gp+0xff/0x120 <- 0x0
systemd-udevd-675 [012] ..... 17.347981: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-675 [012] ..... 17.348002: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-675 [012] ..... 17.348037: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348098: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348117: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-665 [061] ..... 17.348120: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348156: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348166: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348176: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-642 [050] ..... 17.348179: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348186: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348197: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348200: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348231: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348240: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348250: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348259: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348262: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348305: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348317: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348332: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348336: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348394: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348403: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348406: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 17.348503: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 17.348531: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-645 [053] ..... 17.348535: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348536: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 17.348563: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-665 [061] ..... 17.348575: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348628: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348704: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348828: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348884: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348904: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348954: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348983: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.348993: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349002: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349014: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349024: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349026: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349119: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349182: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349243: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349430: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349462: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349472: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349483: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349486: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349583: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349632: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349666: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349699: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 17.349727: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349733: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 17.349739: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-645 [053] ..... 17.349742: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349765: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-645 [053] ..... 17.349766: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-642 [050] ..... 17.349780: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-665 [061] ..... 17.349800: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-642 [050] ..... 17.349815: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-642 [050] ..... 17.349829: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-642 [050] ..... 17.349832: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349834: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-675 [012] ..... 17.349835: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-675 [012] ..... 17.349853: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-642 [050] ..... 17.349861: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
systemd-udevd-675 [012] ..... 17.349873: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.349879: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.350007: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.350011: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.350080: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.350175: __call_rcu_common: -> ____fput+0x0/0x10: task_work_run+0x5c/0x90 <- 0x0
systemd-udevd-665 [061] ..... 17.350362: dev_change_name: --> renamed from eth0
<snip>
First delay:
<snip>
systemd-udevd-645 [053] ..... 2.339024: __call_rcu_common: -> 0x0: __dentry_kill+0x140/0x180 <- 0x2
kworker/0:3-546 [000] d..1. 6.329516: __call_rcu_common: -> 0x0: queue_rcu_work+0x2b/0x40 <- 0xffff8c70effe40a0
<snip>
__dentry_kill() function and after 4 seconds there is another one queue_rcu_work().
I have checked the __dentry_kill() if it can do any sync talk with RCU but from the
first glance i do not see anything critical. But more attention is required.
Second delay:
<snip>
rcuop/5-56 [058] b.... 7.105814: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
rcuop/20-163 [023] b.... 17.345648: __call_rcu_common: -> 0x0: file_free_rcu+0x32/0x50 <- 0x0
<snip>
10 seconds. But please note that it could be that there were not any callbacks queued
during 10 seconds.
--
Uladzislau Rezki
next prev parent reply other threads:[~2022-09-27 14:08 UTC|newest]
Thread overview: 62+ messages / expand[flat|nested] mbox.gz Atom feed top
2022-09-22 22:01 [PATCH v6 0/4] rcu: call_rcu() power improvements Joel Fernandes (Google)
2022-09-22 22:01 ` [PATCH v6 1/4] rcu: Make call_rcu() lazy to save power Joel Fernandes (Google)
2022-09-23 21:44 ` Paul E. McKenney
2022-09-24 16:20 ` Joel Fernandes
2022-09-24 21:11 ` Paul E. McKenney
2022-09-24 22:56 ` Joel Fernandes
2022-09-25 17:31 ` Joel Fernandes
2022-09-26 17:42 ` Paul E. McKenney
2022-09-26 21:07 ` Joel Fernandes
2022-09-26 22:37 ` Paul E. McKenney
2022-09-26 23:33 ` Joel Fernandes
2022-09-26 23:53 ` Paul E. McKenney
2022-10-03 19:33 ` Joel Fernandes
2022-10-03 19:49 ` Paul E. McKenney
2022-09-24 22:46 ` Frederic Weisbecker
2022-09-24 23:28 ` Joel Fernandes
2022-09-25 1:00 ` Joel Fernandes
2022-09-25 22:00 ` Frederic Weisbecker
2022-09-26 15:04 ` Joel Fernandes
2022-09-26 17:33 ` Paul E. McKenney
2022-09-26 23:37 ` Joel Fernandes
2022-09-25 22:09 ` Frederic Weisbecker
2022-09-26 17:45 ` Paul E. McKenney
2022-09-25 8:57 ` Uladzislau Rezki
2022-09-25 17:46 ` Joel Fernandes
2022-09-26 17:48 ` Paul E. McKenney
2022-09-26 19:32 ` Uladzislau Rezki
2022-09-26 21:02 ` Joel Fernandes
2022-09-26 22:32 ` Paul E. McKenney
2022-09-26 23:47 ` Joel Fernandes
2022-09-26 23:59 ` Paul E. McKenney
2022-09-27 1:49 ` Joel Fernandes
2022-09-27 3:22 ` Paul E. McKenney
2022-09-27 13:05 ` Joel Fernandes
2022-09-27 14:14 ` Paul E. McKenney
2022-09-27 14:22 ` Joel Fernandes
2022-09-27 14:30 ` Paul E. McKenney
2022-09-27 15:25 ` Joel Fernandes
2022-09-27 15:59 ` Paul E. McKenney
[not found] ` <CAEXW_YRpAjvmBPzRA-hRQpuaDuZUzfndLb3q+e3BUyWprg5wkQ@mail.gmail.com>
2022-09-27 3:21 ` Paul E. McKenney
2022-09-26 22:27 ` Paul E. McKenney
2022-09-26 19:39 ` Uladzislau Rezki
2022-09-26 20:54 ` Joel Fernandes
2022-09-26 22:35 ` Paul E. McKenney
2022-09-26 23:44 ` Joel Fernandes
2022-09-26 23:57 ` Paul E. McKenney
2022-09-27 1:16 ` Joel Fernandes
2022-09-27 3:20 ` Paul E. McKenney
2022-09-27 14:08 ` Uladzislau Rezki [this message]
2022-09-27 14:30 ` Joel Fernandes
2022-09-27 14:59 ` Uladzislau Rezki
2022-09-27 15:13 ` Uladzislau Rezki
2022-09-27 21:31 ` Uladzislau Rezki
2022-09-27 22:05 ` Joel Fernandes
2022-09-27 22:29 ` Joel Fernandes
2022-09-30 16:11 ` Uladzislau Rezki
2022-10-04 11:35 ` Uladzislau Rezki
2022-10-04 18:06 ` Joel Fernandes
2022-09-27 15:14 ` Joel Fernandes
2022-09-22 22:01 ` [PATCH v6 2/4] rcu: shrinker for lazy rcu Joel Fernandes (Google)
2022-09-22 22:01 ` [PATCH v6 3/4] rcuscale: Add laziness and kfree tests Joel Fernandes (Google)
2022-09-22 22:01 ` [PATCH v6 4/4] percpu-refcount: Use call_rcu_flush() for atomic switch Joel Fernandes (Google)
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=YzMD0pdR6rvGSZ/o@pc636 \
--to=urezki@gmail.com \
--cc=frederic@kernel.org \
--cc=joel@joelfernandes.org \
--cc=linux-kernel@vger.kernel.org \
--cc=neeraj.iitr10@gmail.com \
--cc=paulmck@kernel.org \
--cc=rcu@vger.kernel.org \
--cc=rostedt@goodmis.org \
--cc=rushikesh.s.kadam@intel.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.