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:59:44 +0200 [thread overview]
Message-ID: <YzMP4LaIUY8Dh9Nw@pc636> (raw)
In-Reply-To: <YzMI68pbXXVWWKEN@google.com>
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
next prev parent reply other threads:[~2022-09-27 15:00 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 [this message]
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=YzMP4LaIUY8Dh9Nw@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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox