From: Uladzislau Rezki <urezki@gmail.com>
To: Joel Fernandes <joel@joelfernandes.org>, paulmck@kernel.org
Cc: Joel Fernandes <joel@joelfernandes.org>,
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 23:31:53 +0200 [thread overview]
Message-ID: <YzNryczGDQZpvIa8@pc636> (raw)
In-Reply-To: <YzMTHgLT0wk2zzg0@pc636>
On Tue, Sep 27, 2022 at 05:13:34PM +0200, Uladzislau Rezki wrote:
> On Tue, Sep 27, 2022 at 04:59:44PM +0200, Uladzislau Rezki wrote:
> > On Tue, Sep 27, 2022 at 02:30:03PM +0000, Joel Fernandes wrote:
> > > On Tue, Sep 27, 2022 at 04:08:18PM +0200, Uladzislau Rezki wrote:
> > > > 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.
> > >
> > > Can you log rcu_barrier() as well? It could be that the print is just a side
> > > effect of something else that is not being printed.
> > >
> > It has nothing to do with rcu_barrier() in my case. Also i have checked
> > the synchronize_rcu() it also works as expected, i.e. it is not a
> > blocking reason.
> >
> > Have you tried my config?
> >
> > --
> > Uladzislau Rezki
> OK. Seems one place i have spot:
>
> <snip>
> [ 7.074847] calling init_sr+0x0/0x1000 [sr_mod] @ 668
> [ 22.422808] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
> [ 22.422815] cdrom: Uniform CD-ROM driver Revision: 3.20
> [ 32.664590] sr 1:0:0:0: Attached scsi CD-ROM sr0
> [ 32.664642] initcall init_sr+0x0/0x1000 [sr_mod] returned 0 after 25589786 usecs
> <snip>
>
> --
> Uladzislau Rezki
OK. Found the boot up issue. In my case i had 120 seconds delay:
<snip>
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index 448748e3fba5..a56cfd612e3a 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -312,7 +312,7 @@ void scsi_eh_scmd_add(struct scsi_cmnd *scmd)
* Ensure that all tasks observe the host state change before the
* host_failed change.
*/
- call_rcu(&scmd->rcu, scsi_eh_inc_host_failed);
+ call_rcu_flush(&scmd->rcu, scsi_eh_inc_host_failed);
}
/**
<snip>
After this change the boot-up time settles back to normal 4 seconds.
--
Uladzislau Rezki
next prev parent reply other threads:[~2022-09-27 21:32 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
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 [this message]
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=YzNryczGDQZpvIa8@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.