[PATCH v2 1/1] vhost scsi: alloc vhost_scsi with kvzalloc() to avoid delay

Subsystems: the rest, virtio host (vhost), virtio host (vhost-scsi)

STALE1997d LANDED

Landed in mainline as 489084dd3f7e on 2021-02-23.

10 messages, 6 authors, 2021-03-18 · open the first message on its own page

[PATCH v2 1/1] vhost scsi: alloc vhost_scsi with kvzalloc() to avoid delay

From: Dongli Zhang <hidden>
Date: 2021-01-23 08:08:12

The size of 'struct vhost_scsi' is order-10 (~2.3MB). It may take long time
delay by kzalloc() to compact memory pages by retrying multiple times when
there is a lack of high-order pages. As a result, there is latency to
create a VM (with vhost-scsi) or to hotadd vhost-scsi-based storage.

The prior commit 595cb754983d ("vhost/scsi: use vmalloc for order-10
allocation") prefers to fallback only when really needed, while this patch
allocates with kvzalloc() with __GFP_NORETRY implicitly set to avoid
retrying memory pages compact for multiple times.

The __GFP_NORETRY is implicitly set if the size to allocate is more than
PAGE_SZIE and when __GFP_RETRY_MAYFAIL is not explicitly set.

Cc: Aruna Ramakrishna <redacted>
Cc: Joe Jin <redacted>
Signed-off-by: Dongli Zhang <redacted>
---
Changed since v1:
  - To combine kzalloc() and vzalloc() as kvzalloc()
    (suggested by Jason Wang)

 drivers/vhost/scsi.c | 9 +++------
 1 file changed, 3 insertions(+), 6 deletions(-)
diff --git a/drivers/vhost/scsi.c b/drivers/vhost/scsi.c
index 4ce9f00ae10e..5de21ad4bd05 100644
--- a/drivers/vhost/scsi.c
+++ b/drivers/vhost/scsi.c
@@ -1814,12 +1814,9 @@ static int vhost_scsi_open(struct inode *inode, struct file *f)
 	struct vhost_virtqueue **vqs;
 	int r = -ENOMEM, i;
 
-	vs = kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
-	if (!vs) {
-		vs = vzalloc(sizeof(*vs));
-		if (!vs)
-			goto err_vs;
-	}
+	vs = kvzalloc(sizeof(*vs), GFP_KERNEL);
+	if (!vs)
+		goto err_vs;
 
 	vqs = kmalloc_array(VHOST_SCSI_MAX_VQ, sizeof(*vqs), GFP_KERNEL);
 	if (!vqs)
-- 
2.17.1

Re: [PATCH v2 1/1] vhost scsi: alloc vhost_scsi with kvzalloc() to avoid delay

From: Dongli Zhang <hidden>
Date: 2021-01-23 20:19:22

According to my "git send-email" history, I have CCed jasowang@redhat.com. Not
sure why Jason is not on the list.

CCed Jason. Thank you very much!

Dongli Zhang

On 1/23/21 12:08 AM, Dongli Zhang wrote:
quoted hunk
The size of 'struct vhost_scsi' is order-10 (~2.3MB). It may take long time
delay by kzalloc() to compact memory pages by retrying multiple times when
there is a lack of high-order pages. As a result, there is latency to
create a VM (with vhost-scsi) or to hotadd vhost-scsi-based storage.

The prior commit 595cb754983d ("vhost/scsi: use vmalloc for order-10
allocation") prefers to fallback only when really needed, while this patch
allocates with kvzalloc() with __GFP_NORETRY implicitly set to avoid
retrying memory pages compact for multiple times.

The __GFP_NORETRY is implicitly set if the size to allocate is more than
PAGE_SZIE and when __GFP_RETRY_MAYFAIL is not explicitly set.

Cc: Aruna Ramakrishna <redacted>
Cc: Joe Jin <redacted>
Signed-off-by: Dongli Zhang <redacted>
---
Changed since v1:
  - To combine kzalloc() and vzalloc() as kvzalloc()
    (suggested by Jason Wang)

 drivers/vhost/scsi.c | 9 +++------
 1 file changed, 3 insertions(+), 6 deletions(-)
diff --git a/drivers/vhost/scsi.c b/drivers/vhost/scsi.c
index 4ce9f00ae10e..5de21ad4bd05 100644
--- a/drivers/vhost/scsi.c
+++ b/drivers/vhost/scsi.c
@@ -1814,12 +1814,9 @@ static int vhost_scsi_open(struct inode *inode, struct file *f)
 	struct vhost_virtqueue **vqs;
 	int r = -ENOMEM, i;
 
-	vs = kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
-	if (!vs) {
-		vs = vzalloc(sizeof(*vs));
-		if (!vs)
-			goto err_vs;
-	}
+	vs = kvzalloc(sizeof(*vs), GFP_KERNEL);
+	if (!vs)
+		goto err_vs;
 
 	vqs = kmalloc_array(VHOST_SCSI_MAX_VQ, sizeof(*vqs), GFP_KERNEL);
 	if (!vqs)

Re: [PATCH v2 1/1] vhost scsi: alloc vhost_scsi with kvzalloc() to avoid delay

From: Jason Wang <hidden>
Date: 2021-01-25 03:14:52

On 2021/1/23 下午4:08, Dongli Zhang wrote:
quoted hunk
The size of 'struct vhost_scsi' is order-10 (~2.3MB). It may take long time
delay by kzalloc() to compact memory pages by retrying multiple times when
there is a lack of high-order pages. As a result, there is latency to
create a VM (with vhost-scsi) or to hotadd vhost-scsi-based storage.

The prior commit 595cb754983d ("vhost/scsi: use vmalloc for order-10
allocation") prefers to fallback only when really needed, while this patch
allocates with kvzalloc() with __GFP_NORETRY implicitly set to avoid
retrying memory pages compact for multiple times.

The __GFP_NORETRY is implicitly set if the size to allocate is more than
PAGE_SZIE and when __GFP_RETRY_MAYFAIL is not explicitly set.

Cc: Aruna Ramakrishna <redacted>
Cc: Joe Jin <redacted>
Signed-off-by: Dongli Zhang <redacted>
---
Changed since v1:
   - To combine kzalloc() and vzalloc() as kvzalloc()
     (suggested by Jason Wang)

  drivers/vhost/scsi.c | 9 +++------
  1 file changed, 3 insertions(+), 6 deletions(-)
diff --git a/drivers/vhost/scsi.c b/drivers/vhost/scsi.c
index 4ce9f00ae10e..5de21ad4bd05 100644
--- a/drivers/vhost/scsi.c
+++ b/drivers/vhost/scsi.c
@@ -1814,12 +1814,9 @@ static int vhost_scsi_open(struct inode *inode, struct file *f)
  	struct vhost_virtqueue **vqs;
  	int r = -ENOMEM, i;
  
-	vs = kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
-	if (!vs) {
-		vs = vzalloc(sizeof(*vs));
-		if (!vs)
-			goto err_vs;
-	}
+	vs = kvzalloc(sizeof(*vs), GFP_KERNEL);
+	if (!vs)
+		goto err_vs;
  
  	vqs = kmalloc_array(VHOST_SCSI_MAX_VQ, sizeof(*vqs), GFP_KERNEL);
  	if (!vqs)

Acked-by: Jason Wang <redacted>


Re: [PATCH v2 1/1] vhost scsi: alloc vhost_scsi with kvzalloc() to avoid delay

From: Joe Jin <hidden>
Date: 2021-02-01 16:04:27

Can anyone help to review this patch and give a review-by for it please?

Thanks,
Joe
On 1/24/21 7:12 PM, Jason Wang wrote:
On 2021/1/23 下午4:08, Dongli Zhang wrote:
quoted
The size of 'struct vhost_scsi' is order-10 (~2.3MB). It may take long time
delay by kzalloc() to compact memory pages by retrying multiple times when
there is a lack of high-order pages. As a result, there is latency to
create a VM (with vhost-scsi) or to hotadd vhost-scsi-based storage.

The prior commit 595cb754983d ("vhost/scsi: use vmalloc for order-10
allocation") prefers to fallback only when really needed, while this patch
allocates with kvzalloc() with __GFP_NORETRY implicitly set to avoid
retrying memory pages compact for multiple times.

The __GFP_NORETRY is implicitly set if the size to allocate is more than
PAGE_SZIE and when __GFP_RETRY_MAYFAIL is not explicitly set.

Cc: Aruna Ramakrishna <redacted>
Cc: Joe Jin <redacted>
Signed-off-by: Dongli Zhang <redacted>
---
Changed since v1:
   - To combine kzalloc() and vzalloc() as kvzalloc()
     (suggested by Jason Wang)

  drivers/vhost/scsi.c | 9 +++------
  1 file changed, 3 insertions(+), 6 deletions(-)
diff --git a/drivers/vhost/scsi.c b/drivers/vhost/scsi.c
index 4ce9f00ae10e..5de21ad4bd05 100644
--- a/drivers/vhost/scsi.c
+++ b/drivers/vhost/scsi.c
@@ -1814,12 +1814,9 @@ static int vhost_scsi_open(struct inode *inode, struct file *f)
      struct vhost_virtqueue **vqs;
      int r = -ENOMEM, i;
  -    vs = kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
-    if (!vs) {
-        vs = vzalloc(sizeof(*vs));
-        if (!vs)
-            goto err_vs;
-    }
+    vs = kvzalloc(sizeof(*vs), GFP_KERNEL);
+    if (!vs)
+        goto err_vs;
        vqs = kmalloc_array(VHOST_SCSI_MAX_VQ, sizeof(*vqs), GFP_KERNEL);
      if (!vqs)

Acked-by: Jason Wang <redacted>


Re: [PATCH v2 1/1] vhost scsi: alloc vhost_scsi with kvzalloc() to avoid delay

From: Pankaj Gupta <pankaj.gupta.linux@gmail.com>
Date: 2021-02-02 14:57:43

quoted hunk
The size of 'struct vhost_scsi' is order-10 (~2.3MB). It may take long time
delay by kzalloc() to compact memory pages by retrying multiple times when
there is a lack of high-order pages. As a result, there is latency to
create a VM (with vhost-scsi) or to hotadd vhost-scsi-based storage.

The prior commit 595cb754983d ("vhost/scsi: use vmalloc for order-10
allocation") prefers to fallback only when really needed, while this patch
allocates with kvzalloc() with __GFP_NORETRY implicitly set to avoid
retrying memory pages compact for multiple times.

The __GFP_NORETRY is implicitly set if the size to allocate is more than
PAGE_SZIE and when __GFP_RETRY_MAYFAIL is not explicitly set.

Cc: Aruna Ramakrishna <redacted>
Cc: Joe Jin <redacted>
Signed-off-by: Dongli Zhang <redacted>
---
Changed since v1:
  - To combine kzalloc() and vzalloc() as kvzalloc()
    (suggested by Jason Wang)

 drivers/vhost/scsi.c | 9 +++------
 1 file changed, 3 insertions(+), 6 deletions(-)
diff --git a/drivers/vhost/scsi.c b/drivers/vhost/scsi.c
index 4ce9f00ae10e..5de21ad4bd05 100644
--- a/drivers/vhost/scsi.c
+++ b/drivers/vhost/scsi.c
@@ -1814,12 +1814,9 @@ static int vhost_scsi_open(struct inode *inode, struct file *f)
        struct vhost_virtqueue **vqs;
        int r = -ENOMEM, i;

-       vs = kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
-       if (!vs) {
-               vs = vzalloc(sizeof(*vs));
-               if (!vs)
-                       goto err_vs;
-       }
+       vs = kvzalloc(sizeof(*vs), GFP_KERNEL);
+       if (!vs)
+               goto err_vs;

        vqs = kmalloc_array(VHOST_SCSI_MAX_VQ, sizeof(*vqs), GFP_KERNEL);
        if (!vqs)
 Acked-by: Pankaj Gupta [off-list ref]

[vdpa_sim_net] 79991caf52: net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section

From: kernel test robot <hidden>
Date: 2021-02-07 02:49:32

Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 79991caf5202c7989928be534727805f8f68bb8d ("vdpa_sim_net: Add support for user supported devices")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git Dongli-Zhang/vhost-scsi-alloc-vhost_scsi-with-kvzalloc-to-avoid-delay/20210129-191605


in testcase: trinity
version: trinity-static-x86_64-x86_64-f93256fb_2019-08-28
with following parameters:

	runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+-------------------------------------------------------------------------+------------+------------+
|                                                                         | 39502d042a | 79991caf52 |
+-------------------------------------------------------------------------+------------+------------+
| boot_successes                                                          | 0          | 0          |
| boot_failures                                                           | 62         | 57         |
| WARNING:suspicious_RCU_usage                                            | 62         | 57         |
| security/smack/smack_lsm.c:#RCU-list_traversed_in_non-reader_section    | 62         | 57         |
| security/smack/smack_access.c:#RCU-list_traversed_in_non-reader_section | 62         | 57         |
| BUG:workqueue_lockup-pool                                               | 33         | 40         |
| BUG:kernel_hang_in_boot_stage                                           | 6          | 2          |
| net/mac80211/util.c:#RCU-list_traversed_in_non-reader_section           | 23         | 15         |
| WARNING:SOFTIRQ-safe->SOFTIRQ-unsafe_lock_order_detected                | 18         |            |
| WARNING:inconsistent_lock_state                                         | 5          |            |
| inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                         | 5          |            |
| calltrace:asm_call_irq_on_stack                                         | 2          |            |
| RIP:lock_acquire                                                        | 2          |            |
| RIP:check_kcov_mode                                                     | 1          |            |
| RIP:native_safe_halt                                                    | 2          |            |
| INFO:rcu_sched_self-detected_stall_on_CPU                               | 2          |            |
| RIP:clear_page_rep                                                      | 1          |            |
| WARNING:at_drivers/gpu/drm/vkms/vkms_crtc.c:#vkms_vblank_simulate       | 9          | 7          |
| RIP:vkms_vblank_simulate                                                | 9          | 7          |
| RIP:__slab_alloc                                                        | 3          | 3          |
| RIP:__do_softirq                                                        | 2          |            |
| RIP:console_unlock                                                      | 6          | 3          |
| invoked_oom-killer:gfp_mask=0x                                          | 1          |            |
| Mem-Info                                                                | 1          |            |
| RIP:vprintk_emit                                                        | 1          |            |
| RIP:__asan_load4                                                        | 1          |            |
| kernel_BUG_at_kernel/sched/core.c                                       | 0          | 1          |
| invalid_opcode:#[##]                                                    | 0          | 1          |
| RIP:sched_cpu_dying                                                     | 0          | 1          |
| WARNING:possible_circular_locking_dependency_detected                   | 0          | 1          |
| Kernel_panic-not_syncing:Fatal_exception                                | 0          | 1          |
| net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section               | 0          | 8          |
| RIP:arch_local_irq_restore                                              | 0          | 1          |
| RIP:idr_get_free                                                        | 0          | 1          |
| net/ipv6/ip6mr.c:#RCU-list_traversed_in_non-reader_section              | 0          | 2          |
+-------------------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <redacted>


[  890.196279] =============================
[  890.212608] WARNING: suspicious RCU usage
[  890.228281] 5.11.0-rc4-00008-g79991caf5202 #1 Tainted: G        W
[  890.244087] -----------------------------
[  890.259417] net/ipv4/ipmr.c:138 RCU-list traversed in non-reader section!!
[  890.275043]
[  890.275043] other info that might help us debug this:
[  890.275043]
[  890.318497]
[  890.318497] rcu_scheduler_active = 2, debug_locks = 1
[  890.346089] 2 locks held by trinity-c1/2476:
[  890.360897]  #0: ffff888149d6f400 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xc0/0xe0
[  890.375165]  #1: ffff8881cabfd5c8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xa0/0x9c0
[  890.389706]
[  890.389706] stack backtrace:
[  890.416375] CPU: 1 PID: 2476 Comm: trinity-c1 Tainted: G        W         5.11.0-rc4-00008-g79991caf5202 #1
[  890.430706] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[  890.444971] Call Trace:
[  890.458554]  dump_stack+0x15f/0x1bf
[  890.471996]  ipmr_get_table+0x140/0x160
[  890.485328]  ipmr_vif_seq_start+0x4d/0xe0
[  890.498620]  seq_read_iter+0x1b2/0x9c0
[  890.511469]  ? kvm_sched_clock_read+0x14/0x40
[  890.524008]  ? sched_clock+0x1b/0x40
[  890.536095]  ? iov_iter_init+0x7c/0xa0
[  890.548028]  seq_read+0x2fd/0x3e0
[  890.559948]  ? seq_hlist_next_percpu+0x140/0x140
[  890.572204]  ? should_fail+0x78/0x2a0
[  890.584189]  ? write_comp_data+0x2a/0xa0
[  890.596235]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.608134]  ? seq_hlist_next_percpu+0x140/0x140
[  890.620042]  proc_reg_read+0x14e/0x180
[  890.631585]  do_iter_read+0x397/0x420
[  890.642843]  vfs_readv+0xf5/0x160
[  890.653833]  ? vfs_iter_read+0x80/0x80
[  890.664229]  ? __fdget_pos+0xc0/0xe0
[  890.674236]  ? pvclock_clocksource_read+0xd9/0x1a0
[  890.684259]  ? kvm_sched_clock_read+0x14/0x40
[  890.693852]  ? sched_clock+0x1b/0x40
[  890.702898]  ? sched_clock_cpu+0x18/0x120
[  890.711648]  ? write_comp_data+0x2a/0xa0
[  890.720243]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.729290]  do_readv+0x111/0x260
[  890.738205]  ? vfs_readv+0x160/0x160
[  890.747154]  ? lockdep_hardirqs_on+0x77/0x100
[  890.756100]  ? syscall_enter_from_user_mode+0x8a/0x100
[  890.765126]  do_syscall_64+0x34/0x80
[  890.773795]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  890.782630] RIP: 0033:0x453b29
[  890.791189] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 3b 84 00 00 c3 66 2e 0f 1f 84 00 00 00 00
[  890.810866] RSP: 002b:00007ffcda44fb18 EFLAGS: 00000246 ORIG_RAX: 0000000000000013
[  890.820764] RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 0000000000453b29
[  890.830792] RDX: 000000000000009a RSI: 0000000001de1c00 RDI: 00000000000000b9
[  890.840626] RBP: 00007ffcda44fbc0 R08: 722c279d69ffc468 R09: 0000000000000400
[  890.850366] R10: 0098d82a42c63c22 R11: 0000000000000246 R12: 0000000000000002
[  890.860001] R13: 00007f042ae6f058 R14: 00000000010a2830 R15: 00007f042ae6f000



To reproduce:

        # build kernel
	cd linux
	cp config-5.11.0-rc4-00008-g79991caf5202 .config
	make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Oliver Sang

Re: [vdpa_sim_net] 79991caf52: net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section

From: Dongli Zhang <hidden>
Date: 2021-02-07 20:17:11

Is it possible that the issue is not due to this change?

This change is just to call different API to allocate memory, which is
equivalent to kzalloc()+vzalloc().

Before the change:

try kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);

... and then below if the former is failed.

vzalloc(sizeof(*vs));


After the change:

try kmalloc_node(size, FP_KERNEL|GFP_ZERO|__GFP_NOWARN|__GFP_NORETRY, node);

... and then below if the former is failed

__vmalloc_node(size, 1, GFP_KERNEL|GFP_ZERO, node, __builtin_return_address(0));


The below is the first WARNING in uploaded dmesg. I assume it was called before
to open /dev/vhost-scsi.

Will this test try to open /dev/vhost-scsi?

[    5.095515] =============================
[    5.095515] WARNING: suspicious RCU usage
[    5.095515] 5.11.0-rc4-00008-g79991caf5202 #1 Not tainted
[    5.095534] -----------------------------
[    5.096041] security/smack/smack_lsm.c:351 RCU-list traversed in non-reader
section!!
[    5.096982]
[    5.096982] other info that might help us debug this:
[    5.096982]
[    5.097953]
[    5.097953] rcu_scheduler_active = 1, debug_locks = 1
[    5.098739] no locks held by kthreadd/2.
[    5.099237]
[    5.099237] stack backtrace:
[    5.099537] CPU: 0 PID: 2 Comm: kthreadd Not tainted
5.11.0-rc4-00008-g79991caf5202 #1
[    5.100470] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.12.0-1 04/01/2014
[    5.101442] Call Trace:
[    5.101807]  dump_stack+0x15f/0x1bf
[    5.102298]  smack_cred_prepare+0x400/0x420
[    5.102840]  ? security_prepare_creds+0xd4/0x120
[    5.103441]  security_prepare_creds+0x84/0x120
[    5.103515]  prepare_creds+0x3f1/0x580
[    5.103515]  copy_creds+0x65/0x480
[    5.103515]  copy_process+0x7b4/0x3600
[    5.103515]  ? check_prev_add+0xa40/0xa40
[    5.103515]  ? lockdep_enabled+0xd/0x60
[    5.103515]  ? lock_is_held_type+0x1a/0x100
[    5.103515]  ? __cleanup_sighand+0xc0/0xc0
[    5.103515]  ? lockdep_unlock+0x39/0x160
[    5.103515]  kernel_clone+0x165/0xd20
[    5.103515]  ? copy_init_mm+0x20/0x20
[    5.103515]  ? pvclock_clocksource_read+0xd9/0x1a0
[    5.103515]  ? sched_clock_local+0x99/0xc0
[    5.103515]  ? kthread_insert_work_sanity_check+0xc0/0xc0
[    5.103515]  kernel_thread+0xba/0x100
[    5.103515]  ? __ia32_sys_clone3+0x40/0x40
[    5.103515]  ? kthread_insert_work_sanity_check+0xc0/0xc0
[    5.103515]  ? do_raw_spin_unlock+0xa9/0x160
[    5.103515]  kthreadd+0x68f/0x7a0
[    5.103515]  ? kthread_create_on_cpu+0x160/0x160
[    5.103515]  ? lockdep_hardirqs_on+0x77/0x100
[    5.103515]  ? _raw_spin_unlock_irq+0x24/0x60
[    5.103515]  ? kthread_create_on_cpu+0x160/0x160
[    5.103515]  ret_from_fork+0x22/0x30

Thank you very much!

Dongli Zhang


On 2/6/21 7:03 PM, kernel test robot wrote:
Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 79991caf5202c7989928be534727805f8f68bb8d ("vdpa_sim_net: Add support for user supported devices")
https://urldefense.com/v3/__https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-p61PJtI$  Dongli-Zhang/vhost-scsi-alloc-vhost_scsi-with-kvzalloc-to-avoid-delay/20210129-191605


in testcase: trinity
version: trinity-static-x86_64-x86_64-f93256fb_2019-08-28
with following parameters:

	runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: https://urldefense.com/v3/__http://codemonkey.org.uk/projects/trinity/__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-6Y4x88c$ 


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+-------------------------------------------------------------------------+------------+------------+
|                                                                         | 39502d042a | 79991caf52 |
+-------------------------------------------------------------------------+------------+------------+
| boot_successes                                                          | 0          | 0          |
| boot_failures                                                           | 62         | 57         |
| WARNING:suspicious_RCU_usage                                            | 62         | 57         |
| security/smack/smack_lsm.c:#RCU-list_traversed_in_non-reader_section    | 62         | 57         |
| security/smack/smack_access.c:#RCU-list_traversed_in_non-reader_section | 62         | 57         |
| BUG:workqueue_lockup-pool                                               | 33         | 40         |
| BUG:kernel_hang_in_boot_stage                                           | 6          | 2          |
| net/mac80211/util.c:#RCU-list_traversed_in_non-reader_section           | 23         | 15         |
| WARNING:SOFTIRQ-safe->SOFTIRQ-unsafe_lock_order_detected                | 18         |            |
| WARNING:inconsistent_lock_state                                         | 5          |            |
| inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                         | 5          |            |
| calltrace:asm_call_irq_on_stack                                         | 2          |            |
| RIP:lock_acquire                                                        | 2          |            |
| RIP:check_kcov_mode                                                     | 1          |            |
| RIP:native_safe_halt                                                    | 2          |            |
| INFO:rcu_sched_self-detected_stall_on_CPU                               | 2          |            |
| RIP:clear_page_rep                                                      | 1          |            |
| WARNING:at_drivers/gpu/drm/vkms/vkms_crtc.c:#vkms_vblank_simulate       | 9          | 7          |
| RIP:vkms_vblank_simulate                                                | 9          | 7          |
| RIP:__slab_alloc                                                        | 3          | 3          |
| RIP:__do_softirq                                                        | 2          |            |
| RIP:console_unlock                                                      | 6          | 3          |
| invoked_oom-killer:gfp_mask=0x                                          | 1          |            |
| Mem-Info                                                                | 1          |            |
| RIP:vprintk_emit                                                        | 1          |            |
| RIP:__asan_load4                                                        | 1          |            |
| kernel_BUG_at_kernel/sched/core.c                                       | 0          | 1          |
| invalid_opcode:#[##]                                                    | 0          | 1          |
| RIP:sched_cpu_dying                                                     | 0          | 1          |
| WARNING:possible_circular_locking_dependency_detected                   | 0          | 1          |
| Kernel_panic-not_syncing:Fatal_exception                                | 0          | 1          |
| net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section               | 0          | 8          |
| RIP:arch_local_irq_restore                                              | 0          | 1          |
| RIP:idr_get_free                                                        | 0          | 1          |
| net/ipv6/ip6mr.c:#RCU-list_traversed_in_non-reader_section              | 0          | 2          |
+-------------------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <redacted>


[  890.196279] =============================
[  890.212608] WARNING: suspicious RCU usage
[  890.228281] 5.11.0-rc4-00008-g79991caf5202 #1 Tainted: G        W
[  890.244087] -----------------------------
[  890.259417] net/ipv4/ipmr.c:138 RCU-list traversed in non-reader section!!
[  890.275043]
[  890.275043] other info that might help us debug this:
[  890.275043]
[  890.318497]
[  890.318497] rcu_scheduler_active = 2, debug_locks = 1
[  890.346089] 2 locks held by trinity-c1/2476:
[  890.360897]  #0: ffff888149d6f400 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xc0/0xe0
[  890.375165]  #1: ffff8881cabfd5c8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xa0/0x9c0
[  890.389706]
[  890.389706] stack backtrace:
[  890.416375] CPU: 1 PID: 2476 Comm: trinity-c1 Tainted: G        W         5.11.0-rc4-00008-g79991caf5202 #1
[  890.430706] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[  890.444971] Call Trace:
[  890.458554]  dump_stack+0x15f/0x1bf
[  890.471996]  ipmr_get_table+0x140/0x160
[  890.485328]  ipmr_vif_seq_start+0x4d/0xe0
[  890.498620]  seq_read_iter+0x1b2/0x9c0
[  890.511469]  ? kvm_sched_clock_read+0x14/0x40
[  890.524008]  ? sched_clock+0x1b/0x40
[  890.536095]  ? iov_iter_init+0x7c/0xa0
[  890.548028]  seq_read+0x2fd/0x3e0
[  890.559948]  ? seq_hlist_next_percpu+0x140/0x140
[  890.572204]  ? should_fail+0x78/0x2a0
[  890.584189]  ? write_comp_data+0x2a/0xa0
[  890.596235]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.608134]  ? seq_hlist_next_percpu+0x140/0x140
[  890.620042]  proc_reg_read+0x14e/0x180
[  890.631585]  do_iter_read+0x397/0x420
[  890.642843]  vfs_readv+0xf5/0x160
[  890.653833]  ? vfs_iter_read+0x80/0x80
[  890.664229]  ? __fdget_pos+0xc0/0xe0
[  890.674236]  ? pvclock_clocksource_read+0xd9/0x1a0
[  890.684259]  ? kvm_sched_clock_read+0x14/0x40
[  890.693852]  ? sched_clock+0x1b/0x40
[  890.702898]  ? sched_clock_cpu+0x18/0x120
[  890.711648]  ? write_comp_data+0x2a/0xa0
[  890.720243]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.729290]  do_readv+0x111/0x260
[  890.738205]  ? vfs_readv+0x160/0x160
[  890.747154]  ? lockdep_hardirqs_on+0x77/0x100
[  890.756100]  ? syscall_enter_from_user_mode+0x8a/0x100
[  890.765126]  do_syscall_64+0x34/0x80
[  890.773795]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  890.782630] RIP: 0033:0x453b29
[  890.791189] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 3b 84 00 00 c3 66 2e 0f 1f 84 00 00 00 00
[  890.810866] RSP: 002b:00007ffcda44fb18 EFLAGS: 00000246 ORIG_RAX: 0000000000000013
[  890.820764] RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 0000000000453b29
[  890.830792] RDX: 000000000000009a RSI: 0000000001de1c00 RDI: 00000000000000b9
[  890.840626] RBP: 00007ffcda44fbc0 R08: 722c279d69ffc468 R09: 0000000000000400
[  890.850366] R10: 0098d82a42c63c22 R11: 0000000000000246 R12: 0000000000000002
[  890.860001] R13: 00007f042ae6f058 R14: 00000000010a2830 R15: 00007f042ae6f000



To reproduce:

        # build kernel
	cd linux
	cp config-5.11.0-rc4-00008-g79991caf5202 .config
	make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

        git clone https://urldefense.com/v3/__https://github.com/intel/lkp-tests.git__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-Qkr9TyI$ 
        cd lkp-tests
        bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Oliver Sang

Re: [vdpa_sim_net] 79991caf52: net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section

From: "Michael S. Tsirkin" <mst@redhat.com>
Date: 2021-02-08 10:09:44

On Sun, Feb 07, 2021 at 11:03:30AM +0800, kernel test robot wrote:
Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 79991caf5202c7989928be534727805f8f68bb8d ("vdpa_sim_net: Add support for user supported devices")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git Dongli-Zhang/vhost-scsi-alloc-vhost_scsi-with-kvzalloc-to-avoid-delay/20210129-191605


in testcase: trinity
version: trinity-static-x86_64-x86_64-f93256fb_2019-08-28
with following parameters:

	runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
Parav want to take a look?

-- 
MST

Re: [vdpa_sim_net] 79991caf52: net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section

From: Joe Jin <hidden>
Date: 2021-02-08 18:31:59

On 2/7/21 12:15 PM, Dongli Zhang wrote:
Is it possible that the issue is not due to this change?
Looks this issue does not related your change, from dmesg output, when issue occurred, virtio was not loaded:

[  502.508450] ------------[ cut here ]------------
[  502.511859] WARNING: CPU: 0 PID: 1 at drivers/gpu/drm/vkms/vkms_crtc.c:21 vkms_vblank_simulate+0x22a/0x240
[  502.524018] Modules linked in:
[  502.539642] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.11.0-rc4-00008-g79991caf5202 #1
This change is just to call different API to allocate memory, which is
equivalent to kzalloc()+vzalloc().

Before the change:

try kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);

... and then below if the former is failed.

vzalloc(sizeof(*vs));


After the change:

try kmalloc_node(size, FP_KERNEL|GFP_ZERO|__GFP_NOWARN|__GFP_NORETRY, node);

... and then below if the former is failed

__vmalloc_node(size, 1, GFP_KERNEL|GFP_ZERO, node, __builtin_return_address(0));


The below is the first WARNING in uploaded dmesg. I assume it was called before
to open /dev/vhost-scsi.

Will this test try to open /dev/vhost-scsi?

[    5.095515] =============================
[    5.095515] WARNING: suspicious RCU usage
[    5.095515] 5.11.0-rc4-00008-g79991caf5202 #1 Not tainted
[    5.095534] -----------------------------
[    5.096041] security/smack/smack_lsm.c:351 RCU-list traversed in non-reader
section!!
[    5.096982]
[    5.096982] other info that might help us debug this:
[    5.096982]
[    5.097953]
[    5.097953] rcu_scheduler_active = 1, debug_locks = 1
[    5.098739] no locks held by kthreadd/2.
[    5.099237]
[    5.099237] stack backtrace:
[    5.099537] CPU: 0 PID: 2 Comm: kthreadd Not tainted
5.11.0-rc4-00008-g79991caf5202 #1
[    5.100470] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.12.0-1 04/01/2014
[    5.101442] Call Trace:
[    5.101807]  dump_stack+0x15f/0x1bf
[    5.102298]  smack_cred_prepare+0x400/0x420
[    5.102840]  ? security_prepare_creds+0xd4/0x120
[    5.103441]  security_prepare_creds+0x84/0x120
[    5.103515]  prepare_creds+0x3f1/0x580
[    5.103515]  copy_creds+0x65/0x480
[    5.103515]  copy_process+0x7b4/0x3600
[    5.103515]  ? check_prev_add+0xa40/0xa40
[    5.103515]  ? lockdep_enabled+0xd/0x60
[    5.103515]  ? lock_is_held_type+0x1a/0x100
[    5.103515]  ? __cleanup_sighand+0xc0/0xc0
[    5.103515]  ? lockdep_unlock+0x39/0x160
[    5.103515]  kernel_clone+0x165/0xd20
[    5.103515]  ? copy_init_mm+0x20/0x20
[    5.103515]  ? pvclock_clocksource_read+0xd9/0x1a0
[    5.103515]  ? sched_clock_local+0x99/0xc0
[    5.103515]  ? kthread_insert_work_sanity_check+0xc0/0xc0
[    5.103515]  kernel_thread+0xba/0x100
[    5.103515]  ? __ia32_sys_clone3+0x40/0x40
[    5.103515]  ? kthread_insert_work_sanity_check+0xc0/0xc0
[    5.103515]  ? do_raw_spin_unlock+0xa9/0x160
[    5.103515]  kthreadd+0x68f/0x7a0
[    5.103515]  ? kthread_create_on_cpu+0x160/0x160
[    5.103515]  ? lockdep_hardirqs_on+0x77/0x100
[    5.103515]  ? _raw_spin_unlock_irq+0x24/0x60
[    5.103515]  ? kthread_create_on_cpu+0x160/0x160
[    5.103515]  ret_from_fork+0x22/0x30

Thank you very much!

Dongli Zhang


On 2/6/21 7:03 PM, kernel test robot wrote:
quoted
Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 79991caf5202c7989928be534727805f8f68bb8d ("vdpa_sim_net: Add support for user supported devices")
https://urldefense.com/v3/__https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-p61PJtI$  Dongli-Zhang/vhost-scsi-alloc-vhost_scsi-with-kvzalloc-to-avoid-delay/20210129-191605


in testcase: trinity
version: trinity-static-x86_64-x86_64-f93256fb_2019-08-28
with following parameters:

	runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: https://urldefense.com/v3/__http://codemonkey.org.uk/projects/trinity/__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-6Y4x88c$ 


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+-------------------------------------------------------------------------+------------+------------+
|                                                                         | 39502d042a | 79991caf52 |
+-------------------------------------------------------------------------+------------+------------+
| boot_successes                                                          | 0          | 0          |
| boot_failures                                                           | 62         | 57         |
| WARNING:suspicious_RCU_usage                                            | 62         | 57         |
| security/smack/smack_lsm.c:#RCU-list_traversed_in_non-reader_section    | 62         | 57         |
| security/smack/smack_access.c:#RCU-list_traversed_in_non-reader_section | 62         | 57         |
| BUG:workqueue_lockup-pool                                               | 33         | 40         |
| BUG:kernel_hang_in_boot_stage                                           | 6          | 2          |
| net/mac80211/util.c:#RCU-list_traversed_in_non-reader_section           | 23         | 15         |
| WARNING:SOFTIRQ-safe->SOFTIRQ-unsafe_lock_order_detected                | 18         |            |
| WARNING:inconsistent_lock_state                                         | 5          |            |
| inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                         | 5          |            |
| calltrace:asm_call_irq_on_stack                                         | 2          |            |
| RIP:lock_acquire                                                        | 2          |            |
| RIP:check_kcov_mode                                                     | 1          |            |
| RIP:native_safe_halt                                                    | 2          |            |
| INFO:rcu_sched_self-detected_stall_on_CPU                               | 2          |            |
| RIP:clear_page_rep                                                      | 1          |            |
| WARNING:at_drivers/gpu/drm/vkms/vkms_crtc.c:#vkms_vblank_simulate       | 9          | 7          |
| RIP:vkms_vblank_simulate                                                | 9          | 7          |
| RIP:__slab_alloc                                                        | 3          | 3          |
| RIP:__do_softirq                                                        | 2          |            |
| RIP:console_unlock                                                      | 6          | 3          |
| invoked_oom-killer:gfp_mask=0x                                          | 1          |            |
| Mem-Info                                                                | 1          |            |
| RIP:vprintk_emit                                                        | 1          |            |
| RIP:__asan_load4                                                        | 1          |            |
| kernel_BUG_at_kernel/sched/core.c                                       | 0          | 1          |
| invalid_opcode:#[##]                                                    | 0          | 1          |
| RIP:sched_cpu_dying                                                     | 0          | 1          |
| WARNING:possible_circular_locking_dependency_detected                   | 0          | 1          |
| Kernel_panic-not_syncing:Fatal_exception                                | 0          | 1          |
| net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section               | 0          | 8          |
| RIP:arch_local_irq_restore                                              | 0          | 1          |
| RIP:idr_get_free                                                        | 0          | 1          |
| net/ipv6/ip6mr.c:#RCU-list_traversed_in_non-reader_section              | 0          | 2          |
+-------------------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <redacted>


[  890.196279] =============================
[  890.212608] WARNING: suspicious RCU usage
[  890.228281] 5.11.0-rc4-00008-g79991caf5202 #1 Tainted: G        W
[  890.244087] -----------------------------
[  890.259417] net/ipv4/ipmr.c:138 RCU-list traversed in non-reader section!!
[  890.275043]
[  890.275043] other info that might help us debug this:
[  890.275043]
[  890.318497]
[  890.318497] rcu_scheduler_active = 2, debug_locks = 1
[  890.346089] 2 locks held by trinity-c1/2476:
[  890.360897]  #0: ffff888149d6f400 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xc0/0xe0
[  890.375165]  #1: ffff8881cabfd5c8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xa0/0x9c0
[  890.389706]
[  890.389706] stack backtrace:
[  890.416375] CPU: 1 PID: 2476 Comm: trinity-c1 Tainted: G        W         5.11.0-rc4-00008-g79991caf5202 #1
[  890.430706] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[  890.444971] Call Trace:
[  890.458554]  dump_stack+0x15f/0x1bf
[  890.471996]  ipmr_get_table+0x140/0x160
[  890.485328]  ipmr_vif_seq_start+0x4d/0xe0
[  890.498620]  seq_read_iter+0x1b2/0x9c0
[  890.511469]  ? kvm_sched_clock_read+0x14/0x40
[  890.524008]  ? sched_clock+0x1b/0x40
[  890.536095]  ? iov_iter_init+0x7c/0xa0
[  890.548028]  seq_read+0x2fd/0x3e0
[  890.559948]  ? seq_hlist_next_percpu+0x140/0x140
[  890.572204]  ? should_fail+0x78/0x2a0
[  890.584189]  ? write_comp_data+0x2a/0xa0
[  890.596235]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.608134]  ? seq_hlist_next_percpu+0x140/0x140
[  890.620042]  proc_reg_read+0x14e/0x180
[  890.631585]  do_iter_read+0x397/0x420
[  890.642843]  vfs_readv+0xf5/0x160
[  890.653833]  ? vfs_iter_read+0x80/0x80
[  890.664229]  ? __fdget_pos+0xc0/0xe0
[  890.674236]  ? pvclock_clocksource_read+0xd9/0x1a0
[  890.684259]  ? kvm_sched_clock_read+0x14/0x40
[  890.693852]  ? sched_clock+0x1b/0x40
[  890.702898]  ? sched_clock_cpu+0x18/0x120
[  890.711648]  ? write_comp_data+0x2a/0xa0
[  890.720243]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.729290]  do_readv+0x111/0x260
[  890.738205]  ? vfs_readv+0x160/0x160
[  890.747154]  ? lockdep_hardirqs_on+0x77/0x100
[  890.756100]  ? syscall_enter_from_user_mode+0x8a/0x100
[  890.765126]  do_syscall_64+0x34/0x80
[  890.773795]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  890.782630] RIP: 0033:0x453b29
[  890.791189] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 3b 84 00 00 c3 66 2e 0f 1f 84 00 00 00 00
[  890.810866] RSP: 002b:00007ffcda44fb18 EFLAGS: 00000246 ORIG_RAX: 0000000000000013
[  890.820764] RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 0000000000453b29
[  890.830792] RDX: 000000000000009a RSI: 0000000001de1c00 RDI: 00000000000000b9
[  890.840626] RBP: 00007ffcda44fbc0 R08: 722c279d69ffc468 R09: 0000000000000400
[  890.850366] R10: 0098d82a42c63c22 R11: 0000000000000246 R12: 0000000000000002
[  890.860001] R13: 00007f042ae6f058 R14: 00000000010a2830 R15: 00007f042ae6f000



To reproduce:

        # build kernel
	cd linux
	cp config-5.11.0-rc4-00008-g79991caf5202 .config
	make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

        git clone https://urldefense.com/v3/__https://github.com/intel/lkp-tests.git__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-Qkr9TyI$ 
        cd lkp-tests
        bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Oliver Sang

Re: [vdpa_sim_net] 79991caf52: net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section

From: Oliver Sang <hidden>
Date: 2021-03-18 06:33:56

Hi Joe and Dongli,

On Mon, Feb 08, 2021 at 08:10:21AM -0800, Joe Jin wrote:
On 2/7/21 12:15 PM, Dongli Zhang wrote:
quoted
Is it possible that the issue is not due to this change?
Looks this issue does not related your change, from dmesg output, when issue occurred, virtio was not loaded:

[  502.508450] ------------[ cut here ]------------
[  502.511859] WARNING: CPU: 0 PID: 1 at drivers/gpu/drm/vkms/vkms_crtc.c:21 vkms_vblank_simulate+0x22a/0x240
[  502.524018] Modules linked in:
[  502.539642] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.11.0-rc4-00008-g79991caf5202 #1
thanks for explanation and sorry for false positive.
we will investigate further to avoid such kind of false positive in the future.

quoted
This change is just to call different API to allocate memory, which is
equivalent to kzalloc()+vzalloc().

Before the change:

try kzalloc(sizeof(*vs), GFP_KERNEL | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);

... and then below if the former is failed.

vzalloc(sizeof(*vs));


After the change:

try kmalloc_node(size, FP_KERNEL|GFP_ZERO|__GFP_NOWARN|__GFP_NORETRY, node);

... and then below if the former is failed

__vmalloc_node(size, 1, GFP_KERNEL|GFP_ZERO, node, __builtin_return_address(0));


The below is the first WARNING in uploaded dmesg. I assume it was called before
to open /dev/vhost-scsi.

Will this test try to open /dev/vhost-scsi?

[    5.095515] =============================
[    5.095515] WARNING: suspicious RCU usage
[    5.095515] 5.11.0-rc4-00008-g79991caf5202 #1 Not tainted
[    5.095534] -----------------------------
[    5.096041] security/smack/smack_lsm.c:351 RCU-list traversed in non-reader
section!!
[    5.096982]
[    5.096982] other info that might help us debug this:
[    5.096982]
[    5.097953]
[    5.097953] rcu_scheduler_active = 1, debug_locks = 1
[    5.098739] no locks held by kthreadd/2.
[    5.099237]
[    5.099237] stack backtrace:
[    5.099537] CPU: 0 PID: 2 Comm: kthreadd Not tainted
5.11.0-rc4-00008-g79991caf5202 #1
[    5.100470] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.12.0-1 04/01/2014
[    5.101442] Call Trace:
[    5.101807]  dump_stack+0x15f/0x1bf
[    5.102298]  smack_cred_prepare+0x400/0x420
[    5.102840]  ? security_prepare_creds+0xd4/0x120
[    5.103441]  security_prepare_creds+0x84/0x120
[    5.103515]  prepare_creds+0x3f1/0x580
[    5.103515]  copy_creds+0x65/0x480
[    5.103515]  copy_process+0x7b4/0x3600
[    5.103515]  ? check_prev_add+0xa40/0xa40
[    5.103515]  ? lockdep_enabled+0xd/0x60
[    5.103515]  ? lock_is_held_type+0x1a/0x100
[    5.103515]  ? __cleanup_sighand+0xc0/0xc0
[    5.103515]  ? lockdep_unlock+0x39/0x160
[    5.103515]  kernel_clone+0x165/0xd20
[    5.103515]  ? copy_init_mm+0x20/0x20
[    5.103515]  ? pvclock_clocksource_read+0xd9/0x1a0
[    5.103515]  ? sched_clock_local+0x99/0xc0
[    5.103515]  ? kthread_insert_work_sanity_check+0xc0/0xc0
[    5.103515]  kernel_thread+0xba/0x100
[    5.103515]  ? __ia32_sys_clone3+0x40/0x40
[    5.103515]  ? kthread_insert_work_sanity_check+0xc0/0xc0
[    5.103515]  ? do_raw_spin_unlock+0xa9/0x160
[    5.103515]  kthreadd+0x68f/0x7a0
[    5.103515]  ? kthread_create_on_cpu+0x160/0x160
[    5.103515]  ? lockdep_hardirqs_on+0x77/0x100
[    5.103515]  ? _raw_spin_unlock_irq+0x24/0x60
[    5.103515]  ? kthread_create_on_cpu+0x160/0x160
[    5.103515]  ret_from_fork+0x22/0x30

Thank you very much!

Dongli Zhang


On 2/6/21 7:03 PM, kernel test robot wrote:
quoted
Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 79991caf5202c7989928be534727805f8f68bb8d ("vdpa_sim_net: Add support for user supported devices")
https://urldefense.com/v3/__https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-p61PJtI$  Dongli-Zhang/vhost-scsi-alloc-vhost_scsi-with-kvzalloc-to-avoid-delay/20210129-191605


in testcase: trinity
version: trinity-static-x86_64-x86_64-f93256fb_2019-08-28
with following parameters:

	runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: https://urldefense.com/v3/__http://codemonkey.org.uk/projects/trinity/__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-6Y4x88c$ 


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+-------------------------------------------------------------------------+------------+------------+
|                                                                         | 39502d042a | 79991caf52 |
+-------------------------------------------------------------------------+------------+------------+
| boot_successes                                                          | 0          | 0          |
| boot_failures                                                           | 62         | 57         |
| WARNING:suspicious_RCU_usage                                            | 62         | 57         |
| security/smack/smack_lsm.c:#RCU-list_traversed_in_non-reader_section    | 62         | 57         |
| security/smack/smack_access.c:#RCU-list_traversed_in_non-reader_section | 62         | 57         |
| BUG:workqueue_lockup-pool                                               | 33         | 40         |
| BUG:kernel_hang_in_boot_stage                                           | 6          | 2          |
| net/mac80211/util.c:#RCU-list_traversed_in_non-reader_section           | 23         | 15         |
| WARNING:SOFTIRQ-safe->SOFTIRQ-unsafe_lock_order_detected                | 18         |            |
| WARNING:inconsistent_lock_state                                         | 5          |            |
| inconsistent{SOFTIRQ-ON-W}->{IN-SOFTIRQ-W}usage                         | 5          |            |
| calltrace:asm_call_irq_on_stack                                         | 2          |            |
| RIP:lock_acquire                                                        | 2          |            |
| RIP:check_kcov_mode                                                     | 1          |            |
| RIP:native_safe_halt                                                    | 2          |            |
| INFO:rcu_sched_self-detected_stall_on_CPU                               | 2          |            |
| RIP:clear_page_rep                                                      | 1          |            |
| WARNING:at_drivers/gpu/drm/vkms/vkms_crtc.c:#vkms_vblank_simulate       | 9          | 7          |
| RIP:vkms_vblank_simulate                                                | 9          | 7          |
| RIP:__slab_alloc                                                        | 3          | 3          |
| RIP:__do_softirq                                                        | 2          |            |
| RIP:console_unlock                                                      | 6          | 3          |
| invoked_oom-killer:gfp_mask=0x                                          | 1          |            |
| Mem-Info                                                                | 1          |            |
| RIP:vprintk_emit                                                        | 1          |            |
| RIP:__asan_load4                                                        | 1          |            |
| kernel_BUG_at_kernel/sched/core.c                                       | 0          | 1          |
| invalid_opcode:#[##]                                                    | 0          | 1          |
| RIP:sched_cpu_dying                                                     | 0          | 1          |
| WARNING:possible_circular_locking_dependency_detected                   | 0          | 1          |
| Kernel_panic-not_syncing:Fatal_exception                                | 0          | 1          |
| net/ipv4/ipmr.c:#RCU-list_traversed_in_non-reader_section               | 0          | 8          |
| RIP:arch_local_irq_restore                                              | 0          | 1          |
| RIP:idr_get_free                                                        | 0          | 1          |
| net/ipv6/ip6mr.c:#RCU-list_traversed_in_non-reader_section              | 0          | 2          |
+-------------------------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <redacted>


[  890.196279] =============================
[  890.212608] WARNING: suspicious RCU usage
[  890.228281] 5.11.0-rc4-00008-g79991caf5202 #1 Tainted: G        W
[  890.244087] -----------------------------
[  890.259417] net/ipv4/ipmr.c:138 RCU-list traversed in non-reader section!!
[  890.275043]
[  890.275043] other info that might help us debug this:
[  890.275043]
[  890.318497]
[  890.318497] rcu_scheduler_active = 2, debug_locks = 1
[  890.346089] 2 locks held by trinity-c1/2476:
[  890.360897]  #0: ffff888149d6f400 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xc0/0xe0
[  890.375165]  #1: ffff8881cabfd5c8 (&p->lock){+.+.}-{3:3}, at: seq_read_iter+0xa0/0x9c0
[  890.389706]
[  890.389706] stack backtrace:
[  890.416375] CPU: 1 PID: 2476 Comm: trinity-c1 Tainted: G        W         5.11.0-rc4-00008-g79991caf5202 #1
[  890.430706] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[  890.444971] Call Trace:
[  890.458554]  dump_stack+0x15f/0x1bf
[  890.471996]  ipmr_get_table+0x140/0x160
[  890.485328]  ipmr_vif_seq_start+0x4d/0xe0
[  890.498620]  seq_read_iter+0x1b2/0x9c0
[  890.511469]  ? kvm_sched_clock_read+0x14/0x40
[  890.524008]  ? sched_clock+0x1b/0x40
[  890.536095]  ? iov_iter_init+0x7c/0xa0
[  890.548028]  seq_read+0x2fd/0x3e0
[  890.559948]  ? seq_hlist_next_percpu+0x140/0x140
[  890.572204]  ? should_fail+0x78/0x2a0
[  890.584189]  ? write_comp_data+0x2a/0xa0
[  890.596235]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.608134]  ? seq_hlist_next_percpu+0x140/0x140
[  890.620042]  proc_reg_read+0x14e/0x180
[  890.631585]  do_iter_read+0x397/0x420
[  890.642843]  vfs_readv+0xf5/0x160
[  890.653833]  ? vfs_iter_read+0x80/0x80
[  890.664229]  ? __fdget_pos+0xc0/0xe0
[  890.674236]  ? pvclock_clocksource_read+0xd9/0x1a0
[  890.684259]  ? kvm_sched_clock_read+0x14/0x40
[  890.693852]  ? sched_clock+0x1b/0x40
[  890.702898]  ? sched_clock_cpu+0x18/0x120
[  890.711648]  ? write_comp_data+0x2a/0xa0
[  890.720243]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  890.729290]  do_readv+0x111/0x260
[  890.738205]  ? vfs_readv+0x160/0x160
[  890.747154]  ? lockdep_hardirqs_on+0x77/0x100
[  890.756100]  ? syscall_enter_from_user_mode+0x8a/0x100
[  890.765126]  do_syscall_64+0x34/0x80
[  890.773795]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  890.782630] RIP: 0033:0x453b29
[  890.791189] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 3b 84 00 00 c3 66 2e 0f 1f 84 00 00 00 00
[  890.810866] RSP: 002b:00007ffcda44fb18 EFLAGS: 00000246 ORIG_RAX: 0000000000000013
[  890.820764] RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 0000000000453b29
[  890.830792] RDX: 000000000000009a RSI: 0000000001de1c00 RDI: 00000000000000b9
[  890.840626] RBP: 00007ffcda44fbc0 R08: 722c279d69ffc468 R09: 0000000000000400
[  890.850366] R10: 0098d82a42c63c22 R11: 0000000000000246 R12: 0000000000000002
[  890.860001] R13: 00007f042ae6f058 R14: 00000000010a2830 R15: 00007f042ae6f000



To reproduce:

        # build kernel
	cd linux
	cp config-5.11.0-rc4-00008-g79991caf5202 .config
	make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

        git clone https://urldefense.com/v3/__https://github.com/intel/lkp-tests.git__;!!GqivPVa7Brio!LfgrgVVtPAjwjqTZX8yANgsix4f3cJmAA_CcMeCVymh5XYcamWdR9dnbIQA-Qkr9TyI$ 
        cd lkp-tests
        bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Oliver Sang
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help