[linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[kernel test robot]

Hello,

kernel test robot noticed "kernel-selftests.kvm.hardware_disable_test.fail" on:

commit: 66fbf677051818b9b5339fa8bfeac1b2e288efa5 ("x86: Use RCU in all users of __module_address().")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master

[test failed on linux-next/master df5d6180169ae06a2eac57e33b077ad6f6252440]

in testcase: kernel-selftests
version: kernel-selftests-x86_64-7503345ac5f5-1_20241208
with following parameters:

	group: kvm



config: x86_64-rhel-9.4-kselftests
compiler: gcc-12
test machine: 4 threads Intel(R) Xeon(R) CPU E3-1225 v5 @ 3.30GHz (Skylake) with 16G memory

(please refer to attached dmesg/kmsg for entire log/backtrace)



If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202502140800.ebac2328-lkp@intel.com


# timeout set to 120
# selftests: kvm: hardware_disable_test
# Random seed: 0x6b8b4567
#
not ok 73 selftests: kvm: hardware_disable_test # TIMEOUT 120 seconds


The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20250214/202502140800.ebac2328-lkp@intel.com



-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[Sebastian Andrzej Siewior]

On 2025-02-14 10:03:18 [+0800], kernel test robot wrote:
> kernel test robot noticed "kernel-selftests.kvm.hardware_disable_test.fail" on:
> 
> commit: 66fbf677051818b9b5339fa8bfeac1b2e288efa5 ("x86: Use RCU in all users of __module_address().")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> 
> [test failed on linux-next/master df5d6180169ae06a2eac57e33b077ad6f6252440]
> 
> # timeout set to 120
> # selftests: kvm: hardware_disable_test
> # Random seed: 0x6b8b4567
> #
> not ok 73 selftests: kvm: hardware_disable_test # TIMEOUT 120 seconds

I've been playing with that. It completed after ~45secs. The linked
dmesg had also mmu_stress_test timed out but it completed here, too.
I had a timeout in access_tracking_perf_test and memslot_perf_test.

The box is very sluggish. LOCKDEP, KASAN and maybe UBSAN cause that. I
would say the commit in question is innocent.

Sebastian

Re: [linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[Oliver Sang]

hi, Sebastian,

On Tue, Feb 18, 2025 at 03:49:18PM +0100, Sebastian Andrzej Siewior wrote:
> On 2025-02-14 10:03:18 [+0800], kernel test robot wrote:
> > kernel test robot noticed "kernel-selftests.kvm.hardware_disable_test.fail" on:
> > 
> > commit: 66fbf677051818b9b5339fa8bfeac1b2e288efa5 ("x86: Use RCU in all users of __module_address().")
> > https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
> > 
> > [test failed on linux-next/master df5d6180169ae06a2eac57e33b077ad6f6252440]
> > 
> > # timeout set to 120
> > # selftests: kvm: hardware_disable_test
> > # Random seed: 0x6b8b4567
> > #
> > not ok 73 selftests: kvm: hardware_disable_test # TIMEOUT 120 seconds
> 
> I've been playing with that. It completed after ~45secs. The linked
> dmesg had also mmu_stress_test timed out but it completed here, too.
> I had a timeout in access_tracking_perf_test and memslot_perf_test.
> 
> The box is very sluggish. LOCKDEP, KASAN and maybe UBSAN cause that. I
> would say the commit in question is innocent.

just FYI. we rebuild the kernel, and run the tests more times upon this commit
and its parent, still see the issue persistent:

=========================================================================================
tbox_group/testcase/rootfs/kconfig/compiler/group:
  lkp-skl-d06/kernel-selftests/debian-12-x86_64-20240206.cgz/x86_64-rhel-9.4-kselftests/gcc-12/kvm

f985e39203090cc6 66fbf677051818b9b5339fa8bfe
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
           :20         105%          20:20    kernel-selftests.kvm.hardware_disable_test.fail
         %stddev     %change         %stddev
             \          |                \
    580.92           +17.4%     682.06        kernel-selftests.time.elapsed_time
    580.92           +17.4%     682.06        kernel-selftests.time.elapsed_time.max
    550.23           +13.1%     622.20        kernel-selftests.time.system_time

as above, the time spent is also longer, though it's not only for
kvm.hardware_disable_test (the time is for whole kernel-selftests.kvm)

it seems to us that the commit really causes some slow down and it happens to
make kvm.hardware_disable_test timeout on the older machine for our original
report:

4 threads Intel(R) Xeon(R) CPU E3-1225 v5 @ 3.30GHz (Skylake) with 16G memory


then we make same tests on another newer platform:

224 threads Intel(R) Xeon(R) Platinum 8480+ with 256G memory


we see the test pass on both this commit and its parent. but the time spent is
still longer (again, for full kernel-selftests.kvm)

=========================================================================================
compiler/group/kconfig/rootfs/tbox_group/testcase:
  gcc-12/kvm/x86_64-rhel-9.4-kselftests/debian-12-x86_64-20240206.cgz/lkp-spr-2sp1/kernel-selftests

f985e39203090cc6 66fbf677051818b9b5339fa8bfe
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
         10:10           0%          10:10    kernel-selftests.kvm.hardware_disable_test.pass
         %stddev     %change         %stddev
             \          |                \
    238.99 ±  2%      +7.1%     255.89 ±  5%  kernel-selftests.time.elapsed_time
    238.99 ±  2%      +7.1%     255.89 ±  5%  kernel-selftests.time.elapsed_time.max
      1130 ±  2%     +31.4%       1486 ± 68%  kernel-selftests.time.system_time

> 
> Sebastian

Re: [linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[Sebastian Andrzej Siewior]

On 2025-02-20 15:04:43 [+0800], Oliver Sang wrote:
> hi, Sebastian,
Hi Oliver,

+ UBSAN & KASAN + STACK unwind people. The commit question is
    e9d25b42bde5a ("x86: Use RCU in all users of __module_address().")
  in -next.

> just FYI. we rebuild the kernel, and run the tests more times upon this commit
> and its parent, still see the issue persistent:
> 
…
> 
> f985e39203090cc6 66fbf677051818b9b5339fa8bfe
> ---------------- ---------------------------
>        fail:runs  %reproduction    fail:runs
>            |             |             |
>            :20         105%          20:20    kernel-selftests.kvm.hardware_disable_test.fail
>          %stddev     %change         %stddev
>              \          |                \
>     580.92           +17.4%     682.06        kernel-selftests.time.elapsed_time
>     580.92           +17.4%     682.06        kernel-selftests.time.elapsed_time.max
>     550.23           +13.1%     622.20        kernel-selftests.time.system_time

this is +~100 secs?

> as above, the time spent is also longer, though it's not only for
> kvm.hardware_disable_test (the time is for whole kernel-selftests.kvm)
…
> it seems to us that the commit really causes some slow down and it happens to
> make kvm.hardware_disable_test timeout on the older machine for our original

I made it slower, why is that so, let me look. On my HW
#1 patched (as of 66fbf677051818b9b5339fa8bfe)
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m43.242s
| user    0m0.635s
| sys     0m18.292s

#2 use preempt_disable instead of rcu_read_lock() in unwind_orc.c (=revert)
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m30.212s
| user    0m0.448s
| sys     0m12.939s

#3 replace preempt_disable with __rcu_read_lock() [slim without debug]
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
|
| real    0m29.953s
| user    0m0.436s
| sys     0m12.789s

#4 replace preempt_disable with __rcu_read_lock() + lockdep [RCU watching
  test is missing]
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m41.497s
| user    0m0.639s
| sys     0m17.112s

#5 Using rcu_read_lock() only if orc_module_find() is invoked.
Lost the output but it was more or less at #2 level meaning it does not
lookup modules to the point that it matters.

#6 CONFIG_UBSAN -CONFIG_KASAN +revert
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
|
| real    0m9.318s
| user    0m0.207s
| sys     0m3.395s

#7 -CONFIG_UBSAN -CONFIG_KASAN with RCU
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m9.249s
| user    0m0.196s
| sys     0m3.332s

#8 -CONFIG_UBSAN -CONFIG_KASAN -LOCKDEP
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| ^[[A
| 
| real    0m4.416s
| user    0m0.120s
| sys     0m1.426s

#9 -CONFIG_UBSAN -CONFIG_KASAN -LOCKDEP +revert
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m4.391s
| user    0m0.137s
| sys     0m1.415s


Now. Based on this:
The RCU read section increased the runtime (on my hardware) for the test
from 30 to 43 seconds which is roughly 43%.
This is due to the lockdep annotation within rcu_read_lock() and
unlock() which is not existing in preempt_disable(). After disabling
UBSAN + KASAN  the lockdep annotation has no effect. My guess that
UBSAN/ KASAN is in charge of countless backtraces while enabled. Those
backtraces seem to be limited to the core kernel.

How much do we care here? Is this something that makes UBSAN + KASAN
folks uncomfortable? Or is lockdep slowing things down anyway?

If so, we could either move the RCU section down (as in #5) so it is not
used that often or go the other direction and move it up. I got this:
| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m32.618s
| user    0m0.537s
| sys     0m13.942s

which is almost the pre-level with the hunk below after figuring out
that most callers are from arch_stack_walk(). 

diff --git a/arch/x86/include/asm/unwind.h b/arch/x86/include/asm/unwind.h
index 7cede4dc21f0..f20e3613942f 100644
--- a/arch/x86/include/asm/unwind.h
+++ b/arch/x86/include/asm/unwind.h
@@ -42,6 +42,7 @@ struct unwind_state {
 void __unwind_start(struct unwind_state *state, struct task_struct *task,
 		    struct pt_regs *regs, unsigned long *first_frame);
 bool unwind_next_frame(struct unwind_state *state);
+bool unwind_next_frame_unlocked(struct unwind_state *state);
 unsigned long unwind_get_return_address(struct unwind_state *state);
 unsigned long *unwind_get_return_address_ptr(struct unwind_state *state);
 
diff --git a/arch/x86/kernel/stacktrace.c b/arch/x86/kernel/stacktrace.c
index ee117fcf46ed..4df346b11f1e 100644
--- a/arch/x86/kernel/stacktrace.c
+++ b/arch/x86/kernel/stacktrace.c
@@ -21,8 +21,9 @@ void arch_stack_walk(stack_trace_consume_fn consume_entry, void *cookie,
 	if (regs && !consume_entry(cookie, regs->ip))
 		return;
 
+	guard(rcu)();
 	for (unwind_start(&state, task, regs, NULL); !unwind_done(&state);
-	     unwind_next_frame(&state)) {
+	     unwind_next_frame_unlocked(&state)) {
 		addr = unwind_get_return_address(&state);
 		if (!addr || !consume_entry(cookie, addr))
 			break;
diff --git a/arch/x86/kernel/unwind_orc.c b/arch/x86/kernel/unwind_orc.c
index 977ee75e047c..402779b3e90a 100644
--- a/arch/x86/kernel/unwind_orc.c
+++ b/arch/x86/kernel/unwind_orc.c
@@ -465,7 +465,7 @@ static bool get_reg(struct unwind_state *state, unsigned int reg_off,
 	return false;
 }
 
-bool unwind_next_frame(struct unwind_state *state)
+bool unwind_next_frame_unlocked(struct unwind_state *state)
 {
 	unsigned long ip_p, sp, tmp, orig_ip = state->ip, prev_sp = state->sp;
 	enum stack_type prev_type = state->stack_info.type;
@@ -475,9 +475,6 @@ bool unwind_next_frame(struct unwind_state *state)
 	if (unwind_done(state))
 		return false;
 
-	/* Don't let modules unload while we're reading their ORC data. */
-	guard(rcu)();
-
 	/* End-of-stack check for user tasks: */
 	if (state->regs && user_mode(state->regs))
 		goto the_end;
@@ -678,6 +675,13 @@ bool unwind_next_frame(struct unwind_state *state)
 	state->stack_info.type = STACK_TYPE_UNKNOWN;
 	return false;
 }
+
+bool unwind_next_frame(struct unwind_state *state)
+{
+	/* Don't let modules unload while we're reading their ORC data. */
+	guard(rcu)();
+	return unwind_next_frame_unlocked(state);
+}
 EXPORT_SYMBOL_GPL(unwind_next_frame);
 
 void __unwind_start(struct unwind_state *state, struct task_struct *task,

Sebastian

Re: [linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[Marco Elver]

On Thu, 20 Feb 2025 at 16:57, Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
[...]
> Now. Based on this:
> The RCU read section increased the runtime (on my hardware) for the test
> from 30 to 43 seconds which is roughly 43%.
> This is due to the lockdep annotation within rcu_read_lock() and
> unlock() which is not existing in preempt_disable(). After disabling
> UBSAN + KASAN  the lockdep annotation has no effect. My guess that
> UBSAN/ KASAN is in charge of countless backtraces while enabled. Those
> backtraces seem to be limited to the core kernel.
>
> How much do we care here? Is this something that makes UBSAN + KASAN
> folks uncomfortable? Or is lockdep slowing things down anyway?

Does this series from Waiman help?
https://lore.kernel.org/all/20250213200228.1993588-4-longman@redhat.com/

> If so, we could either move the RCU section down (as in #5) so it is not
> used that often or go the other direction and move it up. I got this:
> | ~# time ./hardware_disable_test
> | Random seed: 0x6b8b4567
> |
> | real    0m32.618s
> | user    0m0.537s
> | sys     0m13.942s
>
> which is almost the pre-level with the hunk below after figuring out
> that most callers are from arch_stack_walk().
>
> diff --git a/arch/x86/include/asm/unwind.h b/arch/x86/include/asm/unwind.h
> index 7cede4dc21f0..f20e3613942f 100644
> --- a/arch/x86/include/asm/unwind.h
> +++ b/arch/x86/include/asm/unwind.h
> @@ -42,6 +42,7 @@ struct unwind_state {
>  void __unwind_start(struct unwind_state *state, struct task_struct *task,
>                     struct pt_regs *regs, unsigned long *first_frame);
>  bool unwind_next_frame(struct unwind_state *state);
> +bool unwind_next_frame_unlocked(struct unwind_state *state);
>  unsigned long unwind_get_return_address(struct unwind_state *state);
>  unsigned long *unwind_get_return_address_ptr(struct unwind_state *state);
>
> diff --git a/arch/x86/kernel/stacktrace.c b/arch/x86/kernel/stacktrace.c
> index ee117fcf46ed..4df346b11f1e 100644
> --- a/arch/x86/kernel/stacktrace.c
> +++ b/arch/x86/kernel/stacktrace.c
> @@ -21,8 +21,9 @@ void arch_stack_walk(stack_trace_consume_fn consume_entry, void *cookie,
>         if (regs && !consume_entry(cookie, regs->ip))
>                 return;
>
> +       guard(rcu)();
>         for (unwind_start(&state, task, regs, NULL); !unwind_done(&state);
> -            unwind_next_frame(&state)) {
> +            unwind_next_frame_unlocked(&state)) {
>                 addr = unwind_get_return_address(&state);
>                 if (!addr || !consume_entry(cookie, addr))
>                         break;
> diff --git a/arch/x86/kernel/unwind_orc.c b/arch/x86/kernel/unwind_orc.c
> index 977ee75e047c..402779b3e90a 100644
> --- a/arch/x86/kernel/unwind_orc.c
> +++ b/arch/x86/kernel/unwind_orc.c
> @@ -465,7 +465,7 @@ static bool get_reg(struct unwind_state *state, unsigned int reg_off,
>         return false;
>  }
>
> -bool unwind_next_frame(struct unwind_state *state)
> +bool unwind_next_frame_unlocked(struct unwind_state *state)
>  {
>         unsigned long ip_p, sp, tmp, orig_ip = state->ip, prev_sp = state->sp;
>         enum stack_type prev_type = state->stack_info.type;
> @@ -475,9 +475,6 @@ bool unwind_next_frame(struct unwind_state *state)
>         if (unwind_done(state))
>                 return false;
>
> -       /* Don't let modules unload while we're reading their ORC data. */
> -       guard(rcu)();
> -
>         /* End-of-stack check for user tasks: */
>         if (state->regs && user_mode(state->regs))
>                 goto the_end;
> @@ -678,6 +675,13 @@ bool unwind_next_frame(struct unwind_state *state)
>         state->stack_info.type = STACK_TYPE_UNKNOWN;
>         return false;
>  }
> +
> +bool unwind_next_frame(struct unwind_state *state)
> +{
> +       /* Don't let modules unload while we're reading their ORC data. */
> +       guard(rcu)();
> +       return unwind_next_frame_unlocked(state);
> +}
>  EXPORT_SYMBOL_GPL(unwind_next_frame);
>
>  void __unwind_start(struct unwind_state *state, struct task_struct *task,
>
> Sebastian

Re: [linux-next:master] [x86] 66fbf67705: kernel-selftests.kvm.hardware_disable_test.fail

[Sebastian Andrzej Siewior]

On 2025-02-20 17:30:22 [+0100], Marco Elver wrote:
> > How much do we care here? Is this something that makes UBSAN + KASAN
> > folks uncomfortable? Or is lockdep slowing things down anyway?
> 
> Does this series from Waiman help?
> https://lore.kernel.org/all/20250213200228.1993588-4-longman@redhat.com/

I have applied

| locking/lock_events: Add locking events for rtmutex slow paths
| locking/lock_events: Add locking events for lockdep
| locking/lockdep: Disable KASAN instrumentation of lockdep.c
| locking/lockdep: Add kasan_check_byte() check in lock_acquire()

and with this I am down to:

| ~# time ./hardware_disable_test
| Random seed: 0x6b8b4567
| 
| real    0m29.517s
| user    0m0.493s
| sys     0m10.891s

Which is the pre-RCU case. Yes, the series from Waiman helps. This is my
favorite solution.

Sebastian