* [nvme] Invalid SGL for payload:91648 nents:3
@ 2019-06-25 7:51 Wolfgang Rohdewald
2019-06-25 9:17 ` Ming Lei
0 siblings, 1 reply; 11+ messages in thread
From: Wolfgang Rohdewald @ 2019-06-25 7:51 UTC (permalink / raw)
For some time now, I am getting this on an Intel SSD M.2, output of smartctl see below.
This also happens with sgl_threshold=0.
Untainted kernel 5.1.14 (happens also with 5.1.8 and 5.1.15) on Ubuntu 19.04
I cannot say exactly when this started. I cannot trigger it with
cp -a but after starting Virtualbox 6.0.6_Ubuntu r129722 with a Windows 10 client,
it happens quickly. The first logged case is with Linux 5.1.11 but I did
not use Virtualbox for some time before, so if that is what it triggers,
the bug might be older.
I have a Samsung SSD 950 PRO 512GB for the root partition, the Intel SSD
holds a separate ext4 file system. According to smartctl, the Samsung
has no problems. Using Virtualbox there also gives me unexplainable
print_req_error messages but nothing else.
After this happens, smartctl -a often says
Read Error Information Log failed: NVMe Status 0x02
Otherwise, smartctl finds no problems with the SSD, fsck -f is clean,
fsck -c finds no bad blocks.
The sector numbers in the print_req_error message vary, see below.
smartctl 6.6 2017-11-05 r4594 [x86_64-linux-5.1.15-364] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org
=== START OF INFORMATION SECTION ===
Model Number: INTEL SSDPEKNW020T8
Serial Number: BTNH903409YJ2P0C
Firmware Version: 002C
PCI Vendor/Subsystem ID: 0x8086
IEEE OUI Identifier: 0x5cd2e4
Controller ID: 1
Number of Namespaces: 1
Namespace 1 Size/Capacity: 2.048.408.248.320 [2,04 TB]
Namespace 1 Formatted LBA Size: 512
Local Time is: Tue Jun 25 08:57:41 2019 CEST
Firmware Updates (0x14): 2 Slots, no Reset required
Optional Admin Commands (0x0017): Security Format Frmw_DL Self_Test
Optional NVM Commands (0x005f): Comp Wr_Unc DS_Mngmt Wr_Zero Sav/Sel_Feat Timestmp
Maximum Data Transfer Size: 32 Pages
Warning Comp. Temp. Threshold: 77 Celsius
Critical Comp. Temp. Threshold: 80 Celsius
Supported Power States
St Op Max Active Idle RL RT WL WT Ent_Lat Ex_Lat
0 + 5.50W - - 0 0 0 0 0 0
1 + 3.60W - - 1 1 1 1 0 0
2 + 2.60W - - 2 2 2 2 0 0
3 - 0.0300W - - 3 3 3 3 5000 5000
4 - 0.0040W - - 4 4 4 4 5000 9000
Supported LBA Sizes (NSID 0x1)
Id Fmt Data Metadt Rel_Perf
0 + 512 0 0
=== START OF SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED
SMART/Health Information (NVMe Log 0x02, NSID 0x1)
Critical Warning: 0x00
Temperature: 32 Celsius
Available Spare: 100%
Available Spare Threshold: 10%
Percentage Used: 0%
Data Units Read: 9.228.998 [4,72 TB]
Data Units Written: 3.245.879 [1,66 TB]
Host Read Commands: 41.518.159
Host Write Commands: 14.046.787
Controller Busy Time: 365
Power Cycles: 40
Power On Hours: 1.239
Unsafe Shutdowns: 11
Media and Data Integrity Errors: 0
Error Information Log Entries: 0
Warning Comp. Temperature Time: 0
Critical Comp. Temperature Time: 0
Read Error Information Log failed: NVMe Status 0x02
Jun 23 07:49:20 skull kernel: [ 171.583390] vboxdrv: 0000000000000000 VBoxEhciR0.r0
Jun 23 07:52:35 skull kernel: [ 366.611276] sg[0] phys_addr:0x0000000372be9000 offset:0 length:60416 dma_address:0x0000000372be9000 dma_length:60416
Jun 23 07:52:35 skull kernel: [ 366.611277] sg[1] phys_addr:0x0000000372bf7c00 offset:3072 length:33792 dma_address:0x0000000372bf7c00 dma_length:33792
Jun 23 07:52:35 skull kernel: [ 366.611278] sg[2] phys_addr:0x0000000372929000 offset:0 length:36864 dma_address:0x0000000372929000 dma_length:36864
Jun 23 07:52:35 skull kernel: [ 366.611281] ------------[ cut here ]------------
Jun 23 07:52:35 skull kernel: [ 366.611282] Invalid SGL for payload:131072 nents:3
Jun 23 07:52:35 skull kernel: [ 366.611294] WARNING: CPU: 2 PID: 7675 at drivers/nvme/host/pci.c:748 nvme_queue_rq+0x9ed/0xa40
Jun 23 07:52:35 skull kernel: [ 366.611294] Modules linked in: ccm rfcomm ipt_MASQUERADE nf_conntrack_netlink xfrm_user xfrm_algo iptable_nat xt_addrtype iptable_filter xt_conntrack nf_nat
nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c br_netfilter bridge stp llc rpcsec_gss_krb5 auth_rpcgss pci_stub vboxpci(OE) vboxnetadp(OE) vboxnetflt(OE) vboxdrv(OE) nfsv4 nfs lockd grace
fscache dummy nfnetlink_queue nfnetlink_log nfnetlink cmac bnep input_leds joydev btusb btrtl overlay btbcm btintel bluetooth ecdh_generic binfmt_misc nls_iso8859_1 arc4 snd_hda_codec_hdmi
snd_hda_codec_realtek intel_rapl x86_pkg_temp_thermal snd_hda_codec_generic intel_powerclamp snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep crct10dif_pclmul snd_pcm crc32_pclmul
ghash_clmulni_intel snd_seq_midi snd_seq_midi_event iwlmvm snd_rawmidi aesni_intel mac80211 aes_x86_64 crypto_simd cryptd glue_helper intel_cstate intel_rapl_perf snd_seq iwlwifi snd_seq_device
snd_timer snd cfg80211 soundcore mei_me mei intel_pch_thermal ir_rc6_decoder wmi
Jun 23 07:52:35 skull kernel: [ 366.611322] rc_rc6_mce nuvoton_cir rc_core acpi_pad squashfs sch_fq_codel nct6775 hwmon_vid coretemp sunrpc ip_tables x_tables autofs4 hid_logitech_hidpp
hid_logitech_dj hid_generic usbhid hid i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops e1000e drm sdhci_pci cqhci i2c_i801 sdhci video
Jun 23 07:52:35 skull kernel: [ 366.611333] CPU: 2 PID: 7675 Comm: AioMgr0-N Tainted: G OE 5.1.14-363 #1
Jun 23 07:52:35 skull kernel: [ 366.611334] Hardware name: /NUC6i7KYB, BIOS KYSKLi70.86A.0062.2019.0507.1702 05/07/2019
Jun 23 07:52:35 skull kernel: [ 366.611336] RIP: 0010:nvme_queue_rq+0x9ed/0xa40
Jun 23 07:52:35 skull kernel: [ 366.611338] Code: 48 c7 c7 38 6a a3 b3 e8 a1 f0 e1 ff 41 8b 97 4c 01 00 00 41 f6 47 1e 04 75 57 41 8b 77 24 48 c7 c7 80 7e f2 b2 e8 bd e4 a2 ff <0f> 0b bd 0a 00 00 00
e9 fb fd ff ff 49 89 df bd 09 00 00 00 e9 ee
Jun 23 07:52:35 skull kernel: [ 366.611338] RSP: 0018:ffffa396c8fb75c8 EFLAGS: 00010282
Jun 23 07:52:35 skull kernel: [ 366.611340] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000006
Jun 23 07:52:35 skull kernel: [ 366.611340] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff97649ea954f0
Jun 23 07:52:35 skull kernel: [ 366.611341] RBP: 0000000000000000 R08: 000000000000067c R09: 0000000000000004
Jun 23 07:52:35 skull kernel: [ 366.611342] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000003
Jun 23 07:52:35 skull kernel: [ 366.611342] R13: ffff97649aa28000 R14: 0000000000011000 R15: ffff976491a7ac00
Jun 23 07:52:35 skull kernel: [ 366.611344] FS: 00007f148b0c8700(0000) GS:ffff97649ea80000(0000) knlGS:0000000000000000
Jun 23 07:52:35 skull kernel: [ 366.611344] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 23 07:52:35 skull kernel: [ 366.611345] CR2: 00007ffb890206c4 CR3: 00000005839f8005 CR4: 00000000003626e0
Jun 23 07:52:35 skull kernel: [ 366.611346] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jun 23 07:52:35 skull kernel: [ 366.611347] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Jun 23 07:52:35 skull kernel: [ 366.611347] Call Trace:
Jun 23 07:52:35 skull kernel: [ 366.611354] __blk_mq_try_issue_directly+0x114/0x1c0
Jun 23 07:52:35 skull kernel: [ 366.611357] blk_mq_request_issue_directly+0x48/0xe0
Jun 23 07:52:35 skull kernel: [ 366.611359] blk_mq_try_issue_list_directly+0x41/0xb0
Jun 23 07:52:35 skull kernel: [ 366.611361] blk_mq_sched_insert_requests+0xa5/0xf0
Jun 23 07:52:35 skull kernel: [ 366.611363] blk_mq_flush_plug_list+0x211/0x2c0
Jun 23 07:52:35 skull kernel: [ 366.611366] blk_flush_plug_list+0xc6/0xf0
Jun 23 07:52:35 skull kernel: [ 366.611368] blk_mq_make_request+0x208/0x580
Jun 23 07:52:35 skull kernel: [ 366.611370] generic_make_request+0x19e/0x400
Jun 23 07:52:35 skull kernel: [ 366.611373] submit_bio+0x45/0x140
Jun 23 07:52:35 skull kernel: [ 366.611376] do_blockdev_direct_IO+0x21e4/0x2e30
Jun 23 07:52:35 skull kernel: [ 366.611380] ? find_get_pages_range_tag+0x81/0x2d0
Jun 23 07:52:35 skull kernel: [ 366.611384] ? ext4_dio_get_block_unwritten_sync+0x50/0x50
Jun 23 07:52:35 skull kernel: [ 366.611386] ext4_direct_IO+0x359/0x740
Jun 23 07:52:35 skull kernel: [ 366.611388] ? touch_atime+0x33/0xe0
Jun 23 07:52:35 skull kernel: [ 366.611391] generic_file_read_iter+0x9c/0xc90
Jun 23 07:52:35 skull kernel: [ 366.611394] aio_read+0xec/0x160
Jun 23 07:52:35 skull kernel: [ 366.611397] ? tomoyo_init_request_info+0x84/0x90
Jun 23 07:52:35 skull kernel: [ 366.611399] ? tomoyo_path_number_perm+0x68/0x1e0
Jun 23 07:52:35 skull kernel: [ 366.611401] ? _cond_resched+0x15/0x30
Jun 23 07:52:35 skull kernel: [ 366.611403] ? __kmalloc+0x166/0x200
Jun 23 07:52:35 skull kernel: [ 366.611416] ? rtR0MemAllocEx+0x14c/0x240 [vboxdrv]
Jun 23 07:52:35 skull kernel: [ 366.611425] ? supdrvIOCtl+0xcc1/0x36e0 [vboxdrv]
Jun 23 07:52:35 skull kernel: [ 366.611426] ? kmem_cache_alloc+0x150/0x1c0
Jun 23 07:52:35 skull kernel: [ 366.611428] io_submit_one+0x171/0xb20
Jun 23 07:52:35 skull kernel: [ 366.611434] ? VBoxDrvLinuxIOCtl_6_0_6+0x188/0x240 [vboxdrv]
Jun 23 07:52:35 skull kernel: [ 366.611436] ? __x64_sys_io_submit+0xa9/0x190
Jun 23 07:52:35 skull kernel: [ 366.611441] ? lookup_ioctx+0x1d/0x90
Jun 23 07:52:35 skull kernel: [ 366.611442] __x64_sys_io_submit+0xa9/0x190
Jun 23 07:52:35 skull kernel: [ 366.611451] do_syscall_64+0x5f/0x190
Jun 23 07:52:35 skull kernel: [ 366.611453] entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jun 23 07:52:35 skull kernel: [ 366.611455] RIP: 0033:0x7f14ed70e2e9
Jun 23 07:52:35 skull kernel: [ 366.611457] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 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 73
01 c3 48 8b 0d 77 cb 0c 00 f7 d8 64 89 01 48
Jun 23 07:52:35 skull kernel: [ 366.611457] RSP: 002b:00007f148b0c7b98 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
Jun 23 07:52:35 skull kernel: [ 366.611459] RAX: ffffffffffffffda RBX: 00007f14948aaed0 RCX: 00007f14ed70e2e9
Jun 23 07:52:35 skull kernel: [ 366.611459] RDX: 00007f148b0c7c60 RSI: 000000000000000a RDI: 00007f14d81ab000
Jun 23 07:52:35 skull kernel: [ 366.611460] RBP: 00007f148b0c7bc0 R08: 0000000000000001 R09: 00007f148b0c7c70
Jun 23 07:52:35 skull kernel: [ 366.611461] R10: 00007f149c00ea00 R11: 0000000000000246 R12: 00007f148b0c7c60
Jun 23 07:52:35 skull kernel: [ 366.611461] R13: 000000000000000a R14: 00007f149493f5a0 R15: 000000000000000a
Jun 23 07:52:35 skull kernel: [ 366.611463] ---[ end trace d2b93cc190ac7a41 ]---
Jun 23 07:52:35 skull kernel: [ 366.611466] print_req_error: I/O error, dev nvme1n1, sector 741253002 flags 4000
grep -a sector /var/log/kern.log*
/var/log/kern.log:Jun 23 07:52:35 skull kernel: [ 366.611466] print_req_error: I/O error, dev nvme1n1, sector 741253002 flags 4000
/var/log/kern.log:Jun 23 07:55:24 skull kernel: [ 535.823599] print_req_error: I/O error, dev nvme1n1, sector 160612274 flags 4000
/var/log/kern.log:Jun 23 08:04:50 skull kernel: [ 70.839418] print_req_error: I/O error, dev nvme1n1, sector 161154970 flags 0
/var/log/kern.log:Jun 23 08:05:52 skull kernel: [ 132.746319] print_req_error: I/O error, dev nvme1n1, sector 161154970 flags 4000
/var/log/kern.log:Jun 23 08:05:52 skull kernel: [ 132.832546] print_req_error: I/O error, dev nvme1n1, sector 161154970 flags 0
/var/log/kern.log:Jun 23 08:05:52 skull kernel: [ 132.855611] print_req_error: I/O error, dev nvme1n1, sector 161154970 flags 4000
/var/log/kern.log:Jun 23 08:08:52 skull kernel: [ 312.957573] print_req_error: I/O error, dev nvme1n1, sector 161150857 flags 0
/var/log/kern.log:Jun 23 08:08:52 skull kernel: [ 312.958424] print_req_error: I/O error, dev nvme1n1, sector 161150857 flags 0
/var/log/kern.log:Jun 23 08:08:52 skull kernel: [ 312.959489] print_req_error: I/O error, dev nvme1n1, sector 161150857 flags 0
/var/log/kern.log:Jun 24 18:57:11 skull kernel: [ 3576.127767] print_req_error: I/O error, dev nvme1n1, sector 790335378 flags 0
/var/log/kern.log:Jun 24 18:57:11 skull kernel: [ 3576.130135] print_req_error: I/O error, dev nvme1n1, sector 790335378 flags 4000
/var/log/kern.log:Jun 24 18:57:11 skull kernel: [ 3576.132458] print_req_error: I/O error, dev nvme1n1, sector 790335378 flags 0
/var/log/kern.log:Jun 24 18:57:11 skull kernel: [ 3576.134669] print_req_error: I/O error, dev nvme1n1, sector 790335378 flags 4000
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.022567] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.023451] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.024407] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.037217] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.038041] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.038891] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 18:58:40 skull kernel: [ 3665.040467] print_req_error: I/O error, dev nvme1n1, sector 740323209 flags 0
/var/log/kern.log:Jun 24 20:18:56 skull kernel: [ 8481.617887] print_req_error: I/O error, dev nvme1n1, sector 1805959090 flags 8801
/var/log/kern.log:Jun 24 22:07:18 skull kernel: [ 5407.282088] print_req_error: I/O error, dev nvme1n1, sector 1988491146 flags 4000
/var/log/kern.log:Jun 25 07:23:32 skull kernel: [ 111.452844] print_req_error: I/O error, dev nvme1n1, sector 1988980610 flags 0
/var/log/kern.log:Jun 25 07:23:32 skull kernel: [ 111.455658] print_req_error: I/O error, dev nvme1n1, sector 1988980610 flags 4000
/var/log/kern.log:Jun 25 07:23:32 skull kernel: [ 111.458181] print_req_error: I/O error, dev nvme1n1, sector 1988980610 flags 0
/var/log/kern.log:Jun 25 07:23:32 skull kernel: [ 111.460729] print_req_error: I/O error, dev nvme1n1, sector 1988980610 flags 4000
/var/log/kern.log:Jun 25 08:33:22 skull kernel: [ 659.895032] print_req_error: I/O error, dev nvme1n1, sector 739135402 flags 0
/var/log/kern.log:Jun 25 08:33:22 skull kernel: [ 659.904044] print_req_error: I/O error, dev nvme1n1, sector 739135402 flags 0
/var/log/kern.log:Jun 25 08:33:22 skull kernel: [ 659.919253] print_req_error: I/O error, dev nvme1n1, sector 739135402 flags 4000
/var/log/kern.log:Jun 25 08:43:06 skull kernel: [ 108.723789] print_req_error: I/O error, dev nvme1n1, sector 1781874554 flags 0
/var/log/kern.log.1:Jun 19 18:35:10 skull kernel: [ 1209.920642] print_req_error: I/O error, dev nvme1n1, sector 313347962 flags 4000
--
mit freundlichen Gr?ssen
Wolfgang Rohdewald
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 7:51 [nvme] Invalid SGL for payload:91648 nents:3 Wolfgang Rohdewald
@ 2019-06-25 9:17 ` Ming Lei
[not found] ` <CAOSXXT5PgPJqouD0G7qJjar5tmy-9z+wWdFMqpD2K1=5vQZ+HA@mail.gmail.com>
0 siblings, 1 reply; 11+ messages in thread
From: Ming Lei @ 2019-06-25 9:17 UTC (permalink / raw)
Hi Wolfgang,
On Tue, Jun 25, 2019@09:51:04AM +0200, Wolfgang Rohdewald wrote:
> For some time now, I am getting this on an Intel SSD M.2, output of smartctl see below.
> This also happens with sgl_threshold=0.
>
> Untainted kernel 5.1.14 (happens also with 5.1.8 and 5.1.15) on Ubuntu 19.04
>
> I cannot say exactly when this started. I cannot trigger it with
> cp -a but after starting Virtualbox 6.0.6_Ubuntu r129722 with a Windows 10 client,
> it happens quickly. The first logged case is with Linux 5.1.11 but I did
> not use Virtualbox for some time before, so if that is what it triggers,
> the bug might be older.
>
> I have a Samsung SSD 950 PRO 512GB for the root partition, the Intel SSD
> holds a separate ext4 file system. According to smartctl, the Samsung
> has no problems. Using Virtualbox there also gives me unexplainable
> print_req_error messages but nothing else.
>
> After this happens, smartctl -a often says
>
> Read Error Information Log failed: NVMe Status 0x02
>
> Otherwise, smartctl finds no problems with the SSD, fsck -f is clean,
> fsck -c finds no bad blocks.
>
> The sector numbers in the print_req_error message vary, see below.
>
> smartctl 6.6 2017-11-05 r4594 [x86_64-linux-5.1.15-364] (local build)
> Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org
>
> === START OF INFORMATION SECTION ===
> Model Number: INTEL SSDPEKNW020T8
> Serial Number: BTNH903409YJ2P0C
> Firmware Version: 002C
> PCI Vendor/Subsystem ID: 0x8086
> IEEE OUI Identifier: 0x5cd2e4
> Controller ID: 1
> Number of Namespaces: 1
> Namespace 1 Size/Capacity: 2.048.408.248.320 [2,04 TB]
> Namespace 1 Formatted LBA Size: 512
> Local Time is: Tue Jun 25 08:57:41 2019 CEST
> Firmware Updates (0x14): 2 Slots, no Reset required
> Optional Admin Commands (0x0017): Security Format Frmw_DL Self_Test
> Optional NVM Commands (0x005f): Comp Wr_Unc DS_Mngmt Wr_Zero Sav/Sel_Feat Timestmp
> Maximum Data Transfer Size: 32 Pages
> Warning Comp. Temp. Threshold: 77 Celsius
> Critical Comp. Temp. Threshold: 80 Celsius
>
> Supported Power States
> St Op Max Active Idle RL RT WL WT Ent_Lat Ex_Lat
> 0 + 5.50W - - 0 0 0 0 0 0
> 1 + 3.60W - - 1 1 1 1 0 0
> 2 + 2.60W - - 2 2 2 2 0 0
> 3 - 0.0300W - - 3 3 3 3 5000 5000
> 4 - 0.0040W - - 4 4 4 4 5000 9000
>
> Supported LBA Sizes (NSID 0x1)
> Id Fmt Data Metadt Rel_Perf
> 0 + 512 0 0
>
> === START OF SMART DATA SECTION ===
> SMART overall-health self-assessment test result: PASSED
>
> SMART/Health Information (NVMe Log 0x02, NSID 0x1)
> Critical Warning: 0x00
> Temperature: 32 Celsius
> Available Spare: 100%
> Available Spare Threshold: 10%
> Percentage Used: 0%
> Data Units Read: 9.228.998 [4,72 TB]
> Data Units Written: 3.245.879 [1,66 TB]
> Host Read Commands: 41.518.159
> Host Write Commands: 14.046.787
> Controller Busy Time: 365
> Power Cycles: 40
> Power On Hours: 1.239
> Unsafe Shutdowns: 11
> Media and Data Integrity Errors: 0
> Error Information Log Entries: 0
> Warning Comp. Temperature Time: 0
> Critical Comp. Temperature Time: 0
>
> Read Error Information Log failed: NVMe Status 0x02
>
>
> Jun 23 07:49:20 skull kernel: [ 171.583390] vboxdrv: 0000000000000000 VBoxEhciR0.r0
> Jun 23 07:52:35 skull kernel: [ 366.611276] sg[0] phys_addr:0x0000000372be9000 offset:0 length:60416 dma_address:0x0000000372be9000 dma_length:60416
> Jun 23 07:52:35 skull kernel: [ 366.611277] sg[1] phys_addr:0x0000000372bf7c00 offset:3072 length:33792 dma_address:0x0000000372bf7c00 dma_length:33792
> Jun 23 07:52:35 skull kernel: [ 366.611278] sg[2] phys_addr:0x0000000372929000 offset:0 length:36864 dma_address:0x0000000372929000 dma_length:36864
The above sg supposes to not be in same IO request, given each one is unaligned
wrt. virt_boundary limit, and bvec_split_segs() did check the limit.
> Jun 23 07:52:35 skull kernel: [ 366.611281] ------------[ cut here ]------------
> Jun 23 07:52:35 skull kernel: [ 366.611282] Invalid SGL for payload:131072 nents:3
> Jun 23 07:52:35 skull kernel: [ 366.611294] WARNING: CPU: 2 PID: 7675 at drivers/nvme/host/pci.c:748 nvme_queue_rq+0x9ed/0xa40
So far, no idea how the issue is triggered, maybe we can find something
by dumping the request, could you apply the following patch against your
5.1 kernel source code and post the log after the issue is triggered?
diff --git a/drivers/nvme/host/pci.c b/drivers/nvme/host/pci.c
index a90cf5d63aac..c7999e362434 100644
--- a/drivers/nvme/host/pci.c
+++ b/drivers/nvme/host/pci.c
@@ -656,6 +656,29 @@ static void nvme_print_sgl(struct scatterlist *sgl, int nents)
}
}
+static void nvme_dump_rq(const struct request *rq)
+{
+ int i = 0;
+ struct req_iterator rq_iter;
+ struct bio_vec bvec;
+ struct bio *bio;
+
+ trace_printk("%s: bvec for %d(f:%x/%x, seg: %d)\n", __func__,
+ rq->tag, rq->cmd_flags, rq->rq_flags,
+ rq->nr_phys_segments);
+
+ __rq_for_each_bio(bio, rq)
+ printk("bio %d: %hx/%hx %u %llu %u\n", i++,
+ bio->bi_flags, bio->bi_opf,
+ bio->bi_phys_segments,
+ (unsigned long long)bio->bi_iter.bi_sector,
+ bio->bi_iter.bi_size);
+ i = 0;
+ rq_for_each_bvec(bvec, rq, rq_iter)
+ printk("%d: pfn %lu offset %u len %u\n", i++,
+ (unsigned long)page_to_pfn(bvec.bv_page),
+ bvec.bv_offset, bvec.bv_len);
+}
static blk_status_t nvme_pci_setup_prps(struct nvme_dev *dev,
struct request *req, struct nvme_rw_command *cmnd)
{
@@ -746,6 +769,7 @@ static blk_status_t nvme_pci_setup_prps(struct nvme_dev *dev,
WARN(DO_ONCE(nvme_print_sgl, iod->sg, iod->nents),
"Invalid SGL for payload:%d nents:%d\n",
blk_rq_payload_bytes(req), iod->nents);
+ nvme_dump_rq(req);
return BLK_STS_IOERR;
}
Thanks,
Ming
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
[not found] ` <CAOSXXT5PgPJqouD0G7qJjar5tmy-9z+wWdFMqpD2K1=5vQZ+HA@mail.gmail.com>
@ 2019-06-25 9:45 ` Ming Lei
2019-06-25 9:50 ` Christoph Hellwig
0 siblings, 1 reply; 11+ messages in thread
From: Ming Lei @ 2019-06-25 9:45 UTC (permalink / raw)
On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> The first two sg elements should have been merged to one and would have
> avoided the error. The bug is kernel, nothing to do with the device.
The default max segment size is 64k, so the first two can't be merged.
And the 1st sg should have been dispatched as single request.
Thanks,
Ming
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 9:45 ` Ming Lei
@ 2019-06-25 9:50 ` Christoph Hellwig
2019-06-25 10:07 ` Ming Lei
2019-06-25 12:11 ` Wolfgang Rohdewald
0 siblings, 2 replies; 11+ messages in thread
From: Christoph Hellwig @ 2019-06-25 9:50 UTC (permalink / raw)
On Tue, Jun 25, 2019@05:45:35PM +0800, Ming Lei wrote:
> On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> > The first two sg elements should have been merged to one and would have
> > avoided the error. The bug is kernel, nothing to do with the device.
>
> The default max segment size is 64k, so the first two can't be merged.
>
> And the 1st sg should have been dispatched as single request.
Well, that is exactly what I fixed with my patches that went into
5.2. Looks like we need to backport those as well.
Wolfgang, can you try the latest 5.2-rc git tree?
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 9:50 ` Christoph Hellwig
@ 2019-06-25 10:07 ` Ming Lei
2019-06-25 12:11 ` Wolfgang Rohdewald
1 sibling, 0 replies; 11+ messages in thread
From: Ming Lei @ 2019-06-25 10:07 UTC (permalink / raw)
Hi Christoph,
On Tue, Jun 25, 2019@11:50:13AM +0200, Christoph Hellwig wrote:
> On Tue, Jun 25, 2019@05:45:35PM +0800, Ming Lei wrote:
> > On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> > > The first two sg elements should have been merged to one and would have
> > > avoided the error. The bug is kernel, nothing to do with the device.
> >
> > The default max segment size is 64k, so the first two can't be merged.
> >
> > And the 1st sg should have been dispatched as single request.
>
> Well, that is exactly what I fixed with my patches that went into
> 5.2. Looks like we need to backport those as well.
Even though without your patch, this issue shouldn't happen given the
two sg shouldn't be submitted in single request. Something must be
wrong, I'd suggest to root cause it.
Thanks,
Ming
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 9:50 ` Christoph Hellwig
2019-06-25 10:07 ` Ming Lei
@ 2019-06-25 12:11 ` Wolfgang Rohdewald
2019-06-25 13:29 ` Ming Lei
1 sibling, 1 reply; 11+ messages in thread
From: Wolfgang Rohdewald @ 2019-06-25 12:11 UTC (permalink / raw)
On Di, 2019-06-25@11:50 +0200, Christoph Hellwig wrote:
> On Tue, Jun 25, 2019@05:45:35PM +0800, Ming Lei wrote:
> > On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> > > The first two sg elements should have been merged to one and would have
> > > avoided the error. The bug is kernel, nothing to do with the device.
> >
> > The default max segment size is 64k, so the first two can't be merged.
> >
> > And the 1st sg should have been dispatched as single request.
>
> Well, that is exactly what I fixed with my patches that went into
> 5.2. Looks like we need to backport those as well.
>
> Wolfgang, can you try the latest 5.2-rc git tree?
5.2.0-rc6 works fine.
Do you still want me to apply nvme_dump_rq() to 5.1 for finding the root cause?
--
mit freundlichen Gr?ssen
Wolfgang Rohdewald
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 12:11 ` Wolfgang Rohdewald
@ 2019-06-25 13:29 ` Ming Lei
2019-06-25 15:07 ` Wolfgang Rohdewald
0 siblings, 1 reply; 11+ messages in thread
From: Ming Lei @ 2019-06-25 13:29 UTC (permalink / raw)
On Tue, Jun 25, 2019@02:11:04PM +0200, Wolfgang Rohdewald wrote:
> On Di, 2019-06-25@11:50 +0200, Christoph Hellwig wrote:
> > On Tue, Jun 25, 2019@05:45:35PM +0800, Ming Lei wrote:
> > > On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> > > > The first two sg elements should have been merged to one and would have
> > > > avoided the error. The bug is kernel, nothing to do with the device.
> > >
> > > The default max segment size is 64k, so the first two can't be merged.
> > >
> > > And the 1st sg should have been dispatched as single request.
> >
> > Well, that is exactly what I fixed with my patches that went into
> > 5.2. Looks like we need to backport those as well.
> >
> > Wolfgang, can you try the latest 5.2-rc git tree?
>
> 5.2.0-rc6 works fine.
>
> Do you still want me to apply nvme_dump_rq() to 5.1 for finding the root cause?
Yeah, please dump the request, and maybe there is issue in merge code.
BTW, please replace the trace_printk with printk in the debug patch.
Also not sure if Christoph's patch can be backported safely, given there
is report wrt. too big max segment size recently.
Thanks,
Ming
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 13:29 ` Ming Lei
@ 2019-06-25 15:07 ` Wolfgang Rohdewald
2019-06-26 1:26 ` Ming Lei
0 siblings, 1 reply; 11+ messages in thread
From: Wolfgang Rohdewald @ 2019-06-25 15:07 UTC (permalink / raw)
On Di, 2019-06-25@21:29 +0800, Ming Lei wrote:
> On Tue, Jun 25, 2019@02:11:04PM +0200, Wolfgang Rohdewald wrote:
> > On Di, 2019-06-25@11:50 +0200, Christoph Hellwig wrote:
> > > On Tue, Jun 25, 2019@05:45:35PM +0800, Ming Lei wrote:
> > > > On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> > > > > The first two sg elements should have been merged to one and would have
> > > > > avoided the error. The bug is kernel, nothing to do with the device.
> > > >
> > > > The default max segment size is 64k, so the first two can't be merged.
> > > >
> > > > And the 1st sg should have been dispatched as single request.
> > >
> > > Well, that is exactly what I fixed with my patches that went into
> > > 5.2. Looks like we need to backport those as well.
> > >
> > > Wolfgang, can you try the latest 5.2-rc git tree?
> >
> > 5.2.0-rc6 works fine.
> >
> > Do you still want me to apply nvme_dump_rq() to 5.1 for finding the root cause?
>
> Yeah, please dump the request, and maybe there is issue in merge code.
> BTW, please replace the trace_printk with printk in the debug patch.
>
> Also not sure if Christoph's patch can be backported safely, given there
> is report wrt. too big max segment size recently.
>
> Thanks,
> Ming
Jun 25 17:05:05 skull kernel: [ 150.419778] sg[0] phys_addr:0x000000049cbe9000 offset:0 length:32256 dma_address:0x000000049cbe9000 dma_length:32256
Jun 25 17:05:05 skull kernel: [ 150.419780] sg[1] phys_addr:0x000000049cbf0e00 offset:3584 length:40960 dma_address:0x000000049cbf0e00 dma_length:40960
Jun 25 17:05:05 skull kernel: [ 150.419783] ------------[ cut here ]------------
Jun 25 17:05:05 skull kernel: [ 150.419784] Invalid SGL for payload:73216 nents:2
Jun 25 17:05:05 skull kernel: [ 150.419820] WARNING: CPU: 2 PID: 3566 at drivers/nvme/host/pci.c:771 nvme_pci_setup_prps.isra.48+0x372/0x3d0 [nvme]
Jun 25 17:05:05 skull kernel: [ 150.419821] Modules linked in: ccm rfcomm ipt_MASQUERADE nf_conntrack_netlink xfrm_user xfrm_algo iptable_nat xt_addrtype iptable_filter xt_conntrack nf_nat
nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c br_netfilter bridge stp llc rpcsec_gss_krb5 auth_rpcgss pci_stub vboxpci(OE) vboxnetadp(OE) vboxnetflt(OE) vboxdrv(OE) nfsv4 nfs lockd grace
fscache dummy nfnetlink_queue nfnetlink_log nfnetlink cmac bnep btusb btrtl btbcm btintel bluetooth joydev input_leds ecdh_generic overlay binfmt_misc nls_iso8859_1 arc4 snd_hda_codec_hdmi intel_rapl
x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel snd_hda_codec crct10dif_pclmul snd_hda_core crc32_pclmul snd_hwdep snd_pcm ghash_clmulni_intel
snd_seq_midi snd_seq_midi_event iwlmvm snd_rawmidi mac80211 iwlwifi snd_seq aesni_intel aes_x86_64 crypto_simd cryptd glue_helper snd_seq_device snd_timer intel_cstate intel_rapl_perf snd cfg80211
soundcore mei_me intel_pch_thermal mei ir_rc6_decoder wmi
Jun 25 17:05:05 skull kernel: [ 150.419845] rc_rc6_mce nuvoton_cir rc_core acpi_pad squashfs sch_fq_codel sunrpc nct6775 hwmon_vid coretemp ip_tables x_tables autofs4 hid_logitech_hidpp
hid_logitech_dj hid_generic usbhid hid i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops nvme sdhci_pci drm e1000e cqhci i2c_i801 nvme_core sdhci video
Jun 25 17:05:05 skull kernel: [ 150.419857] CPU: 2 PID: 3566 Comm: AioMgr0-N Tainted: G OE 5.1.15- #1
Jun 25 17:05:05 skull kernel: [ 150.419857] Hardware name: /NUC6i7KYB, BIOS KYSKLi70.86A.0062.2019.0507.1702 05/07/2019
Jun 25 17:05:05 skull kernel: [ 150.419860] RIP: 0010:nvme_pci_setup_prps.isra.48+0x372/0x3d0 [nvme]
Jun 25 17:05:05 skull kernel: [ 150.419861] Code: 48 c7 c7 c0 85 0b c0 e8 2c 08 fb da 41 8b 97 4c 01 00 00 41 f6 47 1e 04 75 57 41 8b 77 24 48 c7 c7 38 4a 0b c0 e8 78 fb bb da <0f> 0b e9 28 ff ff ff
b8 0a 00 00 00 e9 f3 fe ff ff 4c 8b 7d 98 4d
Jun 25 17:05:05 skull kernel: [ 150.419863] RSP: 0018:ffffa39186847558 EFLAGS: 00010282
Jun 25 17:05:05 skull kernel: [ 150.419864] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000006
Jun 25 17:05:05 skull kernel: [ 150.419865] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff95d61ea954f0
Jun 25 17:05:05 skull kernel: [ 150.419865] RBP: ffffa391868475e8 R08: 000000000000066d R09: 0000000000000004
Jun 25 17:05:05 skull kernel: [ 150.419866] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000002
Jun 25 17:05:05 skull kernel: [ 150.419867] R13: 0000000000000002 R14: 0000000000000007 R15: ffff95d60feed000
Jun 25 17:05:05 skull kernel: [ 150.419868] FS: 00007ff4d6168700(0000) GS:ffff95d61ea80000(0000) knlGS:0000000000000000
Jun 25 17:05:05 skull kernel: [ 150.419869] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 25 17:05:05 skull kernel: [ 150.419870] CR2: ffffe20ea05ec2e8 CR3: 0000000500d24004 CR4: 00000000003626e0
Jun 25 17:05:05 skull kernel: [ 150.419870] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jun 25 17:05:05 skull kernel: [ 150.419871] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Jun 25 17:05:05 skull kernel: [ 150.419872] Call Trace:
Jun 25 17:05:05 skull kernel: [ 150.419878] nvme_queue_rq+0x566/0x710 [nvme]
Jun 25 17:05:05 skull kernel: [ 150.419883] __blk_mq_try_issue_directly+0x114/0x1c0
Jun 25 17:05:05 skull kernel: [ 150.419886] ? ktime_get_raw_ts64+0x30/0xc0
Jun 25 17:05:05 skull kernel: [ 150.419888] blk_mq_request_issue_directly+0x48/0xe0
Jun 25 17:05:05 skull kernel: [ 150.419890] blk_mq_try_issue_list_directly+0x41/0xb0
Jun 25 17:05:05 skull kernel: [ 150.419893] blk_mq_sched_insert_requests+0xa5/0xf0
Jun 25 17:05:05 skull kernel: [ 150.419895] blk_mq_flush_plug_list+0x211/0x2c0
Jun 25 17:05:05 skull kernel: [ 150.419898] blk_flush_plug_list+0xc6/0xf0
Jun 25 17:05:05 skull kernel: [ 150.419900] blk_mq_make_request+0x208/0x580
Jun 25 17:05:05 skull kernel: [ 150.419902] generic_make_request+0x19e/0x400
Jun 25 17:05:05 skull kernel: [ 150.419904] submit_bio+0x45/0x140
Jun 25 17:05:05 skull kernel: [ 150.419908] do_blockdev_direct_IO+0x21e4/0x2e30
Jun 25 17:05:05 skull kernel: [ 150.419912] ? find_get_pages_range_tag+0x81/0x2d0
Jun 25 17:05:05 skull kernel: [ 150.419915] ? ext4_dio_get_block_unwritten_sync+0x50/0x50
Jun 25 17:05:05 skull kernel: [ 150.419917] ext4_direct_IO+0x359/0x740
Jun 25 17:05:05 skull kernel: [ 150.419920] ? touch_atime+0x33/0xe0
Jun 25 17:05:05 skull kernel: [ 150.419923] generic_file_read_iter+0x9c/0xc90
Jun 25 17:05:05 skull kernel: [ 150.419925] aio_read+0xec/0x160
Jun 25 17:05:05 skull kernel: [ 150.419929] ? tomoyo_init_request_info+0x84/0x90
Jun 25 17:05:05 skull kernel: [ 150.419930] ? tomoyo_path_number_perm+0x68/0x1e0
Jun 25 17:05:05 skull kernel: [ 150.419933] ? _cond_resched+0x15/0x30
Jun 25 17:05:05 skull kernel: [ 150.419934] ? __kmalloc+0x166/0x200
Jun 25 17:05:05 skull kernel: [ 150.419949] ? rtR0MemAllocEx+0x14c/0x240 [vboxdrv]
Jun 25 17:05:05 skull kernel: [ 150.419958] ? supdrvIOCtl+0xcc1/0x36e0 [vboxdrv]
Jun 25 17:05:05 skull kernel: [ 150.419959] ? kmem_cache_alloc+0x150/0x1c0
Jun 25 17:05:05 skull kernel: [ 150.419961] io_submit_one+0x171/0xb20
Jun 25 17:05:05 skull kernel: [ 150.419967] ? VBoxDrvLinuxIOCtl_6_0_6+0x188/0x240 [vboxdrv]
Jun 25 17:05:05 skull kernel: [ 150.419969] ? __x64_sys_io_submit+0xa9/0x190
Jun 25 17:05:05 skull kernel: [ 150.419971] ? lookup_ioctx+0x1d/0x90
Jun 25 17:05:05 skull kernel: [ 150.419973] __x64_sys_io_submit+0xa9/0x190
Jun 25 17:05:05 skull kernel: [ 150.419975] do_syscall_64+0x5f/0x190
Jun 25 17:05:05 skull kernel: [ 150.419978] entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jun 25 17:05:05 skull kernel: [ 150.419980] RIP: 0033:0x7ff539ace2e9
Jun 25 17:05:05 skull kernel: [ 150.419981] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 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 73
01 c3 48 8b 0d 77 cb 0c 00 f7 d8 64 89 01 48
Jun 25 17:05:05 skull kernel: [ 150.419982] RSP: 002b:00007ff4d6167b98 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
Jun 25 17:05:05 skull kernel: [ 150.419984] RAX: ffffffffffffffda RBX: 00007ff4b801c9b0 RCX: 00007ff539ace2e9
Jun 25 17:05:05 skull kernel: [ 150.419984] RDX: 00007ff4d6167c60 RSI: 0000000000000005 RDI: 00007ff50802c000
Jun 25 17:05:05 skull kernel: [ 150.419985] RBP: 00007ff4d6167bc0 R08: 0000000000000001 R09: 00007ff4d6167c70
Jun 25 17:05:05 skull kernel: [ 150.419986] R10: 00007ff4b801b960 R11: 0000000000000246 R12: 00007ff4d6167c60
Jun 25 17:05:05 skull kernel: [ 150.419986] R13: 0000000000000005 R14: 00007ff4e0940100 R15: 0000000000000005
Jun 25 17:05:05 skull kernel: [ 150.419988] ---[ end trace 581bcb8c21b397f6 ]---
Jun 25 17:05:05 skull kernel: [ 150.419994] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.420017] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.420022] 0: pfn 4836329 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.420027] 1: pfn 4836336 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.420034] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:05 skull kernel: [ 150.422640] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.422642] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.422644] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.422646] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.422649] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:05 skull kernel: [ 150.424948] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.424949] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.424951] 0: pfn 4834377 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.424952] 1: pfn 4834384 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.424954] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:05 skull kernel: [ 150.428223] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.428224] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.428225] 0: pfn 4835945 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.428226] 1: pfn 4835952 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.428229] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:05 skull kernel: [ 150.452483] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.452485] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.452487] 0: pfn 4835399 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.452488] 1: pfn 4835406 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.452490] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:05 skull kernel: [ 150.455112] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.455113] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.455114] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.455115] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.455118] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:05 skull kernel: [ 150.457630] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:05 skull kernel: [ 150.457632] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:05 skull kernel: [ 150.457633] 0: pfn 4835399 offset 0 len 32256
Jun 25 17:05:05 skull kernel: [ 150.457634] 1: pfn 4835406 offset 3584 len 40960
Jun 25 17:05:05 skull kernel: [ 150.457637] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:11 skull kernel: [ 155.479814] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.479817] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.479818] 0: pfn 4835945 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.479820] 1: pfn 4835952 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.479825] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:11 skull kernel: [ 155.482676] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.482679] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.482680] 0: pfn 4835945 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.482682] 1: pfn 4835952 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.482685] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:11 skull kernel: [ 155.485259] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.485261] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.485263] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.485264] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.485268] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:11 skull kernel: [ 155.487906] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.487908] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.487909] 0: pfn 4834377 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.487911] 1: pfn 4834384 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.487913] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:11 skull kernel: [ 155.513063] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.513066] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.513068] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.513069] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.513073] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:11 skull kernel: [ 155.515837] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.515839] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.515840] 0: pfn 4834569 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.515841] 1: pfn 4834576 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.515843] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:11 skull kernel: [ 155.518592] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.518594] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.518595] 0: pfn 4836329 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.518596] 1: pfn 4836336 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.518599] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:11 skull kernel: [ 155.523518] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:11 skull kernel: [ 155.523520] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:11 skull kernel: [ 155.523522] 0: pfn 4836329 offset 0 len 32256
Jun 25 17:05:11 skull kernel: [ 155.523523] 1: pfn 4836336 offset 3584 len 40960
Jun 25 17:05:11 skull kernel: [ 155.523527] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:16 skull kernel: [ 160.557994] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:16 skull kernel: [ 160.557997] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:16 skull kernel: [ 160.557999] 0: pfn 4835399 offset 0 len 32256
Jun 25 17:05:16 skull kernel: [ 160.558001] 1: pfn 4835406 offset 3584 len 40960
Jun 25 17:05:16 skull kernel: [ 160.558004] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:16 skull kernel: [ 160.560787] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:16 skull kernel: [ 160.560789] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:16 skull kernel: [ 160.560791] 0: pfn 4834377 offset 0 len 32256
Jun 25 17:05:16 skull kernel: [ 160.560792] 1: pfn 4834384 offset 3584 len 40960
Jun 25 17:05:16 skull kernel: [ 160.560794] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:16 skull kernel: [ 160.563253] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:16 skull kernel: [ 160.563254] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:16 skull kernel: [ 160.563255] 0: pfn 4835945 offset 0 len 32256
Jun 25 17:05:16 skull kernel: [ 160.563256] 1: pfn 4835952 offset 3584 len 40960
Jun 25 17:05:16 skull kernel: [ 160.563258] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:16 skull kernel: [ 160.565808] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:16 skull kernel: [ 160.565810] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:16 skull kernel: [ 160.565812] 0: pfn 4836329 offset 0 len 32256
Jun 25 17:05:16 skull kernel: [ 160.565813] 1: pfn 4836336 offset 3584 len 40960
Jun 25 17:05:16 skull kernel: [ 160.565816] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:21 skull kernel: [ 165.588911] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.588913] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.588914] 0: pfn 4835399 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.588915] 1: pfn 4835406 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.588917] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:21 skull kernel: [ 165.591515] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.591516] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.591517] 0: pfn 4835463 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.591518] 1: pfn 4835470 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.591521] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:21 skull kernel: [ 165.596861] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.596863] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.596864] 0: pfn 4835945 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.596865] 1: pfn 4835952 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.596867] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:21 skull kernel: [ 165.618673] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.618675] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.618677] 0: pfn 4835431 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.618678] 1: pfn 4835438 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.618681] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:21 skull kernel: [ 165.620969] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.620971] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.620972] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.620973] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.620975] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:21 skull kernel: [ 165.623245] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.623246] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.623248] 0: pfn 4834377 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.623249] 1: pfn 4834384 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.623251] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:21 skull kernel: [ 165.625474] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:21 skull kernel: [ 165.625475] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:21 skull kernel: [ 165.625477] 0: pfn 4835431 offset 0 len 32256
Jun 25 17:05:21 skull kernel: [ 165.625478] 1: pfn 4835438 offset 3584 len 40960
Jun 25 17:05:21 skull kernel: [ 165.625480] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:26 skull kernel: [ 170.647608] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.647610] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.647611] 0: pfn 4835945 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.647613] 1: pfn 4835952 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.647615] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:26 skull kernel: [ 170.650245] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.650247] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.650248] 0: pfn 4834377 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.650249] 1: pfn 4834384 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.650252] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:26 skull kernel: [ 170.652436] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.652437] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.652438] 0: pfn 4835463 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.652439] 1: pfn 4835470 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.652441] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:26 skull kernel: [ 170.655278] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.655280] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.655281] 0: pfn 4836329 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.655282] 1: pfn 4836336 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.655284] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:26 skull kernel: [ 170.678838] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.678839] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.678840] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.678841] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.678843] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:26 skull kernel: [ 170.681377] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.681377] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.681378] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.681379] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.681381] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:26 skull kernel: [ 170.683644] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.683645] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.683646] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.683647] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.683648] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:26 skull kernel: [ 170.686057] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:26 skull kernel: [ 170.686058] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:26 skull kernel: [ 170.686059] 0: pfn 4835463 offset 0 len 32256
Jun 25 17:05:26 skull kernel: [ 170.686059] 1: pfn 4835470 offset 3584 len 40960
Jun 25 17:05:26 skull kernel: [ 170.686061] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 4000
Jun 25 17:05:31 skull kernel: [ 175.693443] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:31 skull kernel: [ 175.693445] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:31 skull kernel: [ 175.693446] 0: pfn 4834601 offset 0 len 32256
Jun 25 17:05:31 skull kernel: [ 175.693448] 1: pfn 4834608 offset 3584 len 40960
Jun 25 17:05:31 skull kernel: [ 175.693451] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
Jun 25 17:05:31 skull kernel: [ 175.698118] bio 0: 7602/0 1 2105917377 32256
Jun 25 17:05:31 skull kernel: [ 175.698120] bio 1: 6602/0 1 2105917440 40960
Jun 25 17:05:31 skull kernel: [ 175.698121] 0: pfn 4834569 offset 0 len 32256
Jun 25 17:05:31 skull kernel: [ 175.698122] 1: pfn 4834576 offset 3584 len 40960
Jun 25 17:05:31 skull kernel: [ 175.698124] print_req_error: I/O error, dev nvme1n1, sector 2105917377 flags 0
--
mit freundlichen Gr?ssen
Wolfgang Rohdewald
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-25 15:07 ` Wolfgang Rohdewald
@ 2019-06-26 1:26 ` Ming Lei
2019-06-26 20:18 ` Wolfgang Rohdewald
2019-07-04 12:09 ` Wolfgang Rohdewald
0 siblings, 2 replies; 11+ messages in thread
From: Ming Lei @ 2019-06-26 1:26 UTC (permalink / raw)
On Tue, Jun 25, 2019@05:07:30PM +0200, Wolfgang Rohdewald wrote:
> On Di, 2019-06-25@21:29 +0800, Ming Lei wrote:
> > On Tue, Jun 25, 2019@02:11:04PM +0200, Wolfgang Rohdewald wrote:
> > > On Di, 2019-06-25@11:50 +0200, Christoph Hellwig wrote:
> > > > On Tue, Jun 25, 2019@05:45:35PM +0800, Ming Lei wrote:
> > > > > On Tue, Jun 25, 2019@06:38:58PM +0900, Keith Busch wrote:
> > > > > > The first two sg elements should have been merged to one and would have
> > > > > > avoided the error. The bug is kernel, nothing to do with the device.
> > > > >
> > > > > The default max segment size is 64k, so the first two can't be merged.
> > > > >
> > > > > And the 1st sg should have been dispatched as single request.
> > > >
> > > > Well, that is exactly what I fixed with my patches that went into
> > > > 5.2. Looks like we need to backport those as well.
> > > >
> > > > Wolfgang, can you try the latest 5.2-rc git tree?
> > >
> > > 5.2.0-rc6 works fine.
> > >
> > > Do you still want me to apply nvme_dump_rq() to 5.1 for finding the root cause?
> >
> > Yeah, please dump the request, and maybe there is issue in merge code.
> > BTW, please replace the trace_printk with printk in the debug patch.
> >
> > Also not sure if Christoph's patch can be backported safely, given there
> > is report wrt. too big max segment size recently.
> >
> > Thanks,
> > Ming
>
>
> Jun 25 17:05:05 skull kernel: [ 150.419778] sg[0] phys_addr:0x000000049cbe9000 offset:0 length:32256 dma_address:0x000000049cbe9000 dma_length:32256
> Jun 25 17:05:05 skull kernel: [ 150.419780] sg[1] phys_addr:0x000000049cbf0e00 offset:3584 length:40960 dma_address:0x000000049cbf0e00 dma_length:40960
> Jun 25 17:05:05 skull kernel: [ 150.419783] ------------[ cut here ]------------
> Jun 25 17:05:05 skull kernel: [ 150.419784] Invalid SGL for payload:73216 nents:2
> Jun 25 17:05:05 skull kernel: [ 150.419820] WARNING: CPU: 2 PID: 3566 at drivers/nvme/host/pci.c:771 nvme_pci_setup_prps.isra.48+0x372/0x3d0 [nvme]
> Jun 25 17:05:05 skull kernel: [ 150.419821] Modules linked in: ccm rfcomm ipt_MASQUERADE nf_conntrack_netlink xfrm_user xfrm_algo iptable_nat xt_addrtype iptable_filter xt_conntrack nf_nat
> nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c br_netfilter bridge stp llc rpcsec_gss_krb5 auth_rpcgss pci_stub vboxpci(OE) vboxnetadp(OE) vboxnetflt(OE) vboxdrv(OE) nfsv4 nfs lockd grace
> fscache dummy nfnetlink_queue nfnetlink_log nfnetlink cmac bnep btusb btrtl btbcm btintel bluetooth joydev input_leds ecdh_generic overlay binfmt_misc nls_iso8859_1 arc4 snd_hda_codec_hdmi intel_rapl
> x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel snd_hda_codec crct10dif_pclmul snd_hda_core crc32_pclmul snd_hwdep snd_pcm ghash_clmulni_intel
> snd_seq_midi snd_seq_midi_event iwlmvm snd_rawmidi mac80211 iwlwifi snd_seq aesni_intel aes_x86_64 crypto_simd cryptd glue_helper snd_seq_device snd_timer intel_cstate intel_rapl_perf snd cfg80211
> soundcore mei_me intel_pch_thermal mei ir_rc6_decoder wmi
> Jun 25 17:05:05 skull kernel: [ 150.419845] rc_rc6_mce nuvoton_cir rc_core acpi_pad squashfs sch_fq_codel sunrpc nct6775 hwmon_vid coretemp ip_tables x_tables autofs4 hid_logitech_hidpp
> hid_logitech_dj hid_generic usbhid hid i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops nvme sdhci_pci drm e1000e cqhci i2c_i801 nvme_core sdhci video
> Jun 25 17:05:05 skull kernel: [ 150.419857] CPU: 2 PID: 3566 Comm: AioMgr0-N Tainted: G OE 5.1.15- #1
> Jun 25 17:05:05 skull kernel: [ 150.419857] Hardware name: /NUC6i7KYB, BIOS KYSKLi70.86A.0062.2019.0507.1702 05/07/2019
> Jun 25 17:05:05 skull kernel: [ 150.419860] RIP: 0010:nvme_pci_setup_prps.isra.48+0x372/0x3d0 [nvme]
> Jun 25 17:05:05 skull kernel: [ 150.419861] Code: 48 c7 c7 c0 85 0b c0 e8 2c 08 fb da 41 8b 97 4c 01 00 00 41 f6 47 1e 04 75 57 41 8b 77 24 48 c7 c7 38 4a 0b c0 e8 78 fb bb da <0f> 0b e9 28 ff ff ff
> b8 0a 00 00 00 e9 f3 fe ff ff 4c 8b 7d 98 4d
> Jun 25 17:05:05 skull kernel: [ 150.419863] RSP: 0018:ffffa39186847558 EFLAGS: 00010282
> Jun 25 17:05:05 skull kernel: [ 150.419864] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000006
> Jun 25 17:05:05 skull kernel: [ 150.419865] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff95d61ea954f0
> Jun 25 17:05:05 skull kernel: [ 150.419865] RBP: ffffa391868475e8 R08: 000000000000066d R09: 0000000000000004
> Jun 25 17:05:05 skull kernel: [ 150.419866] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000002
> Jun 25 17:05:05 skull kernel: [ 150.419867] R13: 0000000000000002 R14: 0000000000000007 R15: ffff95d60feed000
> Jun 25 17:05:05 skull kernel: [ 150.419868] FS: 00007ff4d6168700(0000) GS:ffff95d61ea80000(0000) knlGS:0000000000000000
> Jun 25 17:05:05 skull kernel: [ 150.419869] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> Jun 25 17:05:05 skull kernel: [ 150.419870] CR2: ffffe20ea05ec2e8 CR3: 0000000500d24004 CR4: 00000000003626e0
> Jun 25 17:05:05 skull kernel: [ 150.419870] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> Jun 25 17:05:05 skull kernel: [ 150.419871] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> Jun 25 17:05:05 skull kernel: [ 150.419872] Call Trace:
> Jun 25 17:05:05 skull kernel: [ 150.419878] nvme_queue_rq+0x566/0x710 [nvme]
> Jun 25 17:05:05 skull kernel: [ 150.419883] __blk_mq_try_issue_directly+0x114/0x1c0
> Jun 25 17:05:05 skull kernel: [ 150.419886] ? ktime_get_raw_ts64+0x30/0xc0
> Jun 25 17:05:05 skull kernel: [ 150.419888] blk_mq_request_issue_directly+0x48/0xe0
> Jun 25 17:05:05 skull kernel: [ 150.419890] blk_mq_try_issue_list_directly+0x41/0xb0
> Jun 25 17:05:05 skull kernel: [ 150.419893] blk_mq_sched_insert_requests+0xa5/0xf0
> Jun 25 17:05:05 skull kernel: [ 150.419895] blk_mq_flush_plug_list+0x211/0x2c0
> Jun 25 17:05:05 skull kernel: [ 150.419898] blk_flush_plug_list+0xc6/0xf0
> Jun 25 17:05:05 skull kernel: [ 150.419900] blk_mq_make_request+0x208/0x580
> Jun 25 17:05:05 skull kernel: [ 150.419902] generic_make_request+0x19e/0x400
> Jun 25 17:05:05 skull kernel: [ 150.419904] submit_bio+0x45/0x140
> Jun 25 17:05:05 skull kernel: [ 150.419908] do_blockdev_direct_IO+0x21e4/0x2e30
> Jun 25 17:05:05 skull kernel: [ 150.419912] ? find_get_pages_range_tag+0x81/0x2d0
> Jun 25 17:05:05 skull kernel: [ 150.419915] ? ext4_dio_get_block_unwritten_sync+0x50/0x50
> Jun 25 17:05:05 skull kernel: [ 150.419917] ext4_direct_IO+0x359/0x740
> Jun 25 17:05:05 skull kernel: [ 150.419920] ? touch_atime+0x33/0xe0
> Jun 25 17:05:05 skull kernel: [ 150.419923] generic_file_read_iter+0x9c/0xc90
> Jun 25 17:05:05 skull kernel: [ 150.419925] aio_read+0xec/0x160
> Jun 25 17:05:05 skull kernel: [ 150.419929] ? tomoyo_init_request_info+0x84/0x90
> Jun 25 17:05:05 skull kernel: [ 150.419930] ? tomoyo_path_number_perm+0x68/0x1e0
> Jun 25 17:05:05 skull kernel: [ 150.419933] ? _cond_resched+0x15/0x30
> Jun 25 17:05:05 skull kernel: [ 150.419934] ? __kmalloc+0x166/0x200
> Jun 25 17:05:05 skull kernel: [ 150.419949] ? rtR0MemAllocEx+0x14c/0x240 [vboxdrv]
> Jun 25 17:05:05 skull kernel: [ 150.419958] ? supdrvIOCtl+0xcc1/0x36e0 [vboxdrv]
> Jun 25 17:05:05 skull kernel: [ 150.419959] ? kmem_cache_alloc+0x150/0x1c0
> Jun 25 17:05:05 skull kernel: [ 150.419961] io_submit_one+0x171/0xb20
> Jun 25 17:05:05 skull kernel: [ 150.419967] ? VBoxDrvLinuxIOCtl_6_0_6+0x188/0x240 [vboxdrv]
> Jun 25 17:05:05 skull kernel: [ 150.419969] ? __x64_sys_io_submit+0xa9/0x190
> Jun 25 17:05:05 skull kernel: [ 150.419971] ? lookup_ioctx+0x1d/0x90
> Jun 25 17:05:05 skull kernel: [ 150.419973] __x64_sys_io_submit+0xa9/0x190
> Jun 25 17:05:05 skull kernel: [ 150.419975] do_syscall_64+0x5f/0x190
> Jun 25 17:05:05 skull kernel: [ 150.419978] entry_SYSCALL_64_after_hwframe+0x44/0xa9
> Jun 25 17:05:05 skull kernel: [ 150.419980] RIP: 0033:0x7ff539ace2e9
> Jun 25 17:05:05 skull kernel: [ 150.419981] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 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 73
> 01 c3 48 8b 0d 77 cb 0c 00 f7 d8 64 89 01 48
> Jun 25 17:05:05 skull kernel: [ 150.419982] RSP: 002b:00007ff4d6167b98 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
> Jun 25 17:05:05 skull kernel: [ 150.419984] RAX: ffffffffffffffda RBX: 00007ff4b801c9b0 RCX: 00007ff539ace2e9
> Jun 25 17:05:05 skull kernel: [ 150.419984] RDX: 00007ff4d6167c60 RSI: 0000000000000005 RDI: 00007ff50802c000
> Jun 25 17:05:05 skull kernel: [ 150.419985] RBP: 00007ff4d6167bc0 R08: 0000000000000001 R09: 00007ff4d6167c70
> Jun 25 17:05:05 skull kernel: [ 150.419986] R10: 00007ff4b801b960 R11: 0000000000000246 R12: 00007ff4d6167c60
> Jun 25 17:05:05 skull kernel: [ 150.419986] R13: 0000000000000005 R14: 00007ff4e0940100 R15: 0000000000000005
> Jun 25 17:05:05 skull kernel: [ 150.419988] ---[ end trace 581bcb8c21b397f6 ]---
> Jun 25 17:05:05 skull kernel: [ 150.419994] bio 0: 7602/0 1 2105917377 32256
> Jun 25 17:05:05 skull kernel: [ 150.420017] bio 1: 6602/0 1 2105917440 40960
> Jun 25 17:05:05 skull kernel: [ 150.420022] 0: pfn 4836329 offset 0 len 32256
> Jun 25 17:05:05 skull kernel: [ 150.420027] 1: pfn 4836336 offset 3584 len 40960
I can understand the issue now, and the issue isn't related with bio
split, and it is in the normal bio merge code: biovec_phys_mergeable()
which merges two bios if their bvecs are physically continuous, and not consider
max segment size limit, which is still applied in blk_bvec_map_sg(),
then sg with unaligned virt boundary is made.
Christoph's patch 09324d32d2a08 ("block: force an unlimited segment size on queues
with a virt boundary") can fix the issue, but another regression might be
caused because of too big segment size from view of IOMMU.
And the following patch should fix the 5.1 issue too:
diff --git a/block/blk-merge.c b/block/blk-merge.c
index 1c9d4f0f96ea..ff69b7dd2179 100644
--- a/block/blk-merge.c
+++ b/block/blk-merge.c
@@ -60,7 +60,8 @@ static inline bool bio_will_gap(struct request_queue *q,
*/
bio_get_last_bvec(prev, &pb);
bio_get_first_bvec(next, &nb);
- if (bios_segs_mergeable(q, prev, &pb, &nb))
+ if (bios_segs_mergeable(q, prev, &pb, &nb) && prev->bi_seg_back_size +
+ next->bi_seg_front_size < queue_max_segment_size(q))
return false;
return __bvec_gap_to_prev(q, &pb, nb.bv_offset);
}
Thanks,
Ming
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-26 1:26 ` Ming Lei
@ 2019-06-26 20:18 ` Wolfgang Rohdewald
2019-07-04 12:09 ` Wolfgang Rohdewald
1 sibling, 0 replies; 11+ messages in thread
From: Wolfgang Rohdewald @ 2019-06-26 20:18 UTC (permalink / raw)
On Mi, 2019-06-26@09:26 +0800, Ming Lei wrote:
> And the following patch should fix the 5.1 issue too:
>
> diff --git a/block/blk-merge.c b/block/blk-merge.c
> index 1c9d4f0f96ea..ff69b7dd2179 100644
> --- a/block/blk-merge.c
> +++ b/block/blk-merge.c
> @@ -60,7 +60,8 @@ static inline bool bio_will_gap(struct request_queue *q,
> */
> bio_get_last_bvec(prev, &pb);
> bio_get_first_bvec(next, &nb);
> - if (bios_segs_mergeable(q, prev, &pb, &nb))
> + if (bios_segs_mergeable(q, prev, &pb, &nb) && prev->bi_seg_back_size +
> + next->bi_seg_front_size < queue_max_segment_size(q))
> return false;
> return __bvec_gap_to_prev(q, &pb, nb.bv_offset);
> }
So far, this works for me with 5.1.15. Before, the bug would trigger within
seconds after starting windows 10 update in virtualbox 6.0.6, now it does not.
--
mit freundlichen Gr?ssen
Wolfgang Rohdewald
^ permalink raw reply [flat|nested] 11+ messages in thread
* [nvme] Invalid SGL for payload:91648 nents:3
2019-06-26 1:26 ` Ming Lei
2019-06-26 20:18 ` Wolfgang Rohdewald
@ 2019-07-04 12:09 ` Wolfgang Rohdewald
1 sibling, 0 replies; 11+ messages in thread
From: Wolfgang Rohdewald @ 2019-07-04 12:09 UTC (permalink / raw)
On Mi, 2019-06-26@09:26 +0800, Ming Lei wrote:
> I can understand the issue now, and the issue isn't related with bio
> split, and it is in the normal bio merge code: biovec_phys_mergeable()
> which merges two bios if their bvecs are physically continuous, and not consider
> max segment size limit, which is still applied in blk_bvec_map_sg(),
> then sg with unaligned virt boundary is made.
>
> Christoph's patch 09324d32d2a08 ("block: force an unlimited segment size on queues
> with a virt boundary") can fix the issue, but another regression might be
> caused because of too big segment size from view of IOMMU.
>
> And the following patch should fix the 5.1 issue too:
>
> diff --git a/block/blk-merge.c b/block/blk-merge.c
> index 1c9d4f0f96ea..ff69b7dd2179 100644
> --- a/block/blk-merge.c
> +++ b/block/blk-merge.c
> @@ -60,7 +60,8 @@ static inline bool bio_will_gap(struct request_queue *q,
> */
> bio_get_last_bvec(prev, &pb);
> bio_get_first_bvec(next, &nb);
> - if (bios_segs_mergeable(q, prev, &pb, &nb))
> + if (bios_segs_mergeable(q, prev, &pb, &nb) && prev->bi_seg_back_size +
> + next->bi_seg_front_size < queue_max_segment_size(q))
> return false;
> return __bvec_gap_to_prev(q, &pb, nb.bv_offset);
> }
I wonder why this is not in 5.1.16
--
mit freundlichen Gr?ssen
Wolfgang Rohdewald
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2019-07-04 12:09 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-06-25 7:51 [nvme] Invalid SGL for payload:91648 nents:3 Wolfgang Rohdewald
2019-06-25 9:17 ` Ming Lei
[not found] ` <CAOSXXT5PgPJqouD0G7qJjar5tmy-9z+wWdFMqpD2K1=5vQZ+HA@mail.gmail.com>
2019-06-25 9:45 ` Ming Lei
2019-06-25 9:50 ` Christoph Hellwig
2019-06-25 10:07 ` Ming Lei
2019-06-25 12:11 ` Wolfgang Rohdewald
2019-06-25 13:29 ` Ming Lei
2019-06-25 15:07 ` Wolfgang Rohdewald
2019-06-26 1:26 ` Ming Lei
2019-06-26 20:18 ` Wolfgang Rohdewald
2019-07-04 12:09 ` Wolfgang Rohdewald
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.