nvmet: Kernel oops when doing mkfs on nvme-tcp device

nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

Using two different VMs with nvme-tcp, I tried to create a fs and it
hung with kernel oops on client VM.

Both client/initiator and server/target are running Fedora 31,
5.5.8-200.fc31.x86_64

Reproduces every time.  I also tried creating a gpt partition table on
it first, which worked.  However, when I tried to create FS it oops'd
again and hanged mkfs command.

Thanks,
-Tony

# cat /etc/nvmet/config.json
{
  "hosts": [
    {
      "nqn":
"nqn.2014-08.org.nvmexpress:uuid:faadcb53-9214-4fbb-a746-7d94c023b53e"
    }
  ],
  "ports": [
    {
      "addr": {
        "adrfam": "ipv4",
        "traddr": "192.168.2.80",
        "treq": "not specified",
        "trsvcid": "8009",
        "trtype": "tcp"
      },
      "ana_groups": [
        {
          "ana": {
            "state": "optimized"
          },
          "grpid": 1
        }
      ],
      "param": {
        "inline_data_size": "16384"
      },
      "portid": 1,
      "referrals": [],
      "subsystems": []
    }
  ],
  "subsystems": [
    {
      "allowed_hosts": [

"nqn.2014-08.org.nvmexpress:uuid:faadcb53-9214-4fbb-a746-7d94c023b53e"
      ],
      "attr": {
        "allow_any_host": "0",
        "serial": "967af933980faedc",
        "version": "1.3"
      },
      "namespaces": [
        {
          "ana_grpid": 1,
          "device": {
            "nguid": "00000000-0000-0000-0000-000000000000",
            "path": "/dev/sdc",
            "uuid": "c2c140e4-aff2-4df4-8926-1686a485e99d"
          },
          "enable": 1,
          "nsid": 1
        }
      ],
      "nqn":
"nqn.2014-08.org.nvmexpress:NVMf:uuid:23d9d3e0-a83e-45d7-a902-3e80679385f8"
    }
  ]
}


# mkfs.ext4 /dev/nvme0n1

[  125.031254] nvme-fabrics ctl: Failed to read smart log (error -5)
[  125.031509] nvme nvme0: new ctrl: NQN
"nqn.2014-08.org.nvmexpress.discovery", addr 192.168.2.80:8009
[  125.034133] nvme nvme0: Removing ctrl: NQN
"nqn.2014-08.org.nvmexpress.discovery"
[  125.246827] nvme nvme0: creating 1 I/O queues.
[  125.249356] nvme nvme0: mapped 1/0/0 default/read/poll queues.
[  125.250788] nvme nvme0: new ctrl: NQN
"nqn.2014-08.org.nvmexpress:NVMf:uuid:23d9d3e0-a83e-45d7-a902-3e80679385f8",
addr 192.168.2.80:8009
[  125.257115] nvme0n1: detected capacity change from 0 to 34359738368
[  153.188620] blk_update_request: I/O error, dev nvme0c0n1, sector
67108736 op 0x9:(WRITE_ZEROES) flags 0x5000800 phys_seg 0 prio class 0
[  153.191395] BUG: kernel NULL pointer dereference, address:
0000000000000008
[  153.191440] #PF: supervisor read access in kernel mode
[  153.191468] #PF: error_code(0x0000) - not-present page
[  153.191495] PGD 0 P4D 0
[  153.191513] Oops: 0000 [#1] SMP PTI
[  153.191534] CPU: 0 PID: 237 Comm: kworker/0:1H Not tainted
5.5.9-200.fc31.x86_64 #1
[  153.191574] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS
VirtualBox 12/01/2006
[  153.191619] Workqueue: nvme_tcp_wq nvme_tcp_io_work [nvme_tcp]
[  153.191660] RIP: 0010:nvme_tcp_io_work+0x303/0x790 [nvme_tcp]
[  153.191692] Code: ff ff 41 8b 86 98 00 00 00 83 f8 02 0f 85 6d fd ff
ff 49 8b 46 28 48 89 04 24 49 8b 46 78 49 8b 56 68 41 8b 6e 34 41 2b 6e
38 <8b> 58 08 44 8b 60 0c 4c 8b 38 48 29 d3 49 01 d4 48 39 eb 48 0f 47
[  153.191783] RSP: 0018:ffffbc118020fde8 EFLAGS: 00010206
[  153.191810] RAX: 0000000000000000 RBX: 00000000579f5801 RCX:
0000000000000000
[  153.191863] RDX: 0000000000000000 RSI: 0000000000000011 RDI:
ffff9322579f5900
[  153.191907] RBP: 0000000000001000 R08: 0000000000001000 R09:
0000000000000000
[  153.191944] R10: 0000000000000009 R11: 0000000000000000 R12:
ffff932259d90ee0
[  153.191981] R13: 0000000000000048 R14: ffff9322579f58a0 R15:
0000000000000048
[  153.192018] FS:  0000000000000000(0000) GS:ffff93225bc00000(0000)
knlGS:0000000000000000
[  153.192059] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  153.192087] CR2: 0000000000000008 CR3: 0000000116ff2005 CR4:
00000000000606f0
[  153.192126] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[  153.192163] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[  153.192199] Call Trace:
[  153.192228]  process_one_work+0x1b5/0x360
[  153.192263]  worker_thread+0x50/0x3c0
[  153.192286]  kthread+0xf9/0x130
[  153.192311]  ? process_one_work+0x360/0x360
[  153.192334]  ? kthread_park+0x90/0x90
[  153.192361]  ret_from_fork+0x35/0x40
[  153.192390] Modules linked in: nvme_tcp nvme_fabrics nvme_core rfkill
snd_intel8x0 intel_rapl_msr intel_rapl_common intel_powerclamp
snd_ac97_codec crct10dif_pclmul crc32_pclmul ghash_clmulni_intel
snd_pcsp ac97_bus snd_pcm e1000 snd_timer intel_rapl_perf joydev snd
soundcore i2c_piix4 vboxguest ip_tables xfs libcrc32c vmwgfx
drm_kms_helper ttm drm crc32c_intel serio_raw ata_generic pata_acpi video
[  153.194139] CR2: 0000000000000008
[  153.194619] ---[ end trace 94d1bf7f7728b447 ]---
[  153.195102] RIP: 0010:nvme_tcp_io_work+0x303/0x790 [nvme_tcp]
[  153.195565] Code: ff ff 41 8b 86 98 00 00 00 83 f8 02 0f 85 6d fd ff
ff 49 8b 46 28 48 89 04 24 49 8b 46 78 49 8b 56 68 41 8b 6e 34 41 2b 6e
38 <8b> 58 08 44 8b 60 0c 4c 8b 38 48 29 d3 49 01 d4 48 39 eb 48 0f 47
[  153.197031] RSP: 0018:ffffbc118020fde8 EFLAGS: 00010206
[  153.197525] RAX: 0000000000000000 RBX: 00000000579f5801 RCX:
0000000000000000
[  153.198026] RDX: 0000000000000000 RSI: 0000000000000011 RDI:
ffff9322579f5900
[  153.198511] RBP: 0000000000001000 R08: 0000000000001000 R09:
0000000000000000
[  153.198997] R10: 0000000000000009 R11: 0000000000000000 R12:
ffff932259d90ee0
[  153.199828] R13: 0000000000000048 R14: ffff9322579f58a0 R15:
0000000000000048
[  153.200406] FS:  0000000000000000(0000) GS:ffff93225bc00000(0000)
knlGS:0000000000000000
[  153.200876] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  153.201347] CR2: 0000000000000008 CR3: 0000000116ff2005 CR4:
00000000000606f0
[  153.201816] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[  153.202284] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[  183.652086] block nvme0n1: no usable path - requeuing I/O


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Chaitanya Kulkarni]

On 03/20/2020 02:37 PM, Tony Asleson wrote:
> Using two different VMs with nvme-tcp, I tried to create a fs and it
> hung with kernel oops on client VM.
>
> Both client/initiator and server/target are running Fedora 31,
> 5.5.8-200.fc31.x86_64
>
>
> # mkfs.ext4 /dev/nvme0n1
>
> [  125.031254] nvme-fabrics ctl: Failed to read smart log (error -5)

Seems like your controller does not support smart log (just an 
observation, though I wonder we do implement the smart-log for block
device name-space).

> [  125.031509] nvme nvme0: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery", addr 192.168.2.80:8009
> [  125.034133] nvme nvme0: Removing ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery"
> [  125.246827] nvme nvme0: creating 1 I/O queues.
> [  125.249356] nvme nvme0: mapped 1/0/0 default/read/poll queues.
> [  125.250788] nvme nvme0: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress:NVMf:uuid:23d9d3e0-a83e-45d7-a902-3e80679385f8",
> addr 192.168.2.80:8009
> [  125.257115] nvme0n1: detected capacity change from 0 to 34359738368
> [  153.188620] blk_update_request: I/O error, dev nvme0c0n1, sector
> 67108736 op 0x9:(WRITE_ZEROES) flags 0x5000800 phys_seg 0 prio class 0

Seems like it failed to execute write-zeroes request which may be
a part of the mkfs.ext4. (although not sure though)

Is your back-end device (/dev/sdc) supports write-zeroes
(handling of request REQ_OP_WRITE_ZEROES) ? Even if not block layer 
should just emulate write-zeroes, so I wonder if protection is needed
when we report oncs (which Ideally shouldn't).

> [  153.191395] BUG: kernel NULL pointer dereference, address:
> 0000000000000008
> [  153.191440] #PF: supervisor read access in kernel mode
> [  153.191468] #PF: error_code(0x0000) - not-present page
> [  153.191495] PGD 0 P4D 0
> [  153.191513] Oops: 0000 [#1] SMP PTI
> [  153.191534] CPU: 0 PID: 237 Comm: kworker/0:1H Not tainted
> 5.5.9-200.fc31.x86_64 #1
> [  153.191574] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS
> VirtualBox 12/01/2006
> [  153.191619] Workqueue: nvme_tcp_wq nvme_tcp_io_work [nvme_tcp]
> [  153.191660] RIP: 0010:nvme_tcp_io_work+0x303/0x790 [nvme_tcp]
> [  153.191692] Code: ff ff 41 8b 86 98 00 00 00 83 f8 02 0f 85 6d fd ff
> ff 49 8b 46 28 48 89 04 24 49 8b 46 78 49 8b 56 68 41 8b 6e 34 41 2b 6e
> 38 <8b> 58 08 44 8b 60 0c 4c 8b 38 48 29 d3 49 01 d4 48 39 eb 48 0f 47
> [  153.191783] RSP: 0018:ffffbc118020fde8 EFLAGS: 00010206
> [  153.191810] RAX: 0000000000000000 RBX: 00000000579f5801 RCX:



_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/20/20 5:23 PM, Chaitanya Kulkarni wrote:
> Is your back-end device (/dev/sdc) supports write-zeroes
> (handling of request REQ_OP_WRITE_ZEROES) ? Even if not block layer 
> should just emulate write-zeroes, so I wonder if protection is needed
> when we report oncs (which Ideally shouldn't).

The block device in the nvmet VM does not support write zeros,

# cat /sys/block/sdc/queue/write_zeroes_max_bytes
0


The same device attached to the client over nvme-tcp is showing:

# cat /sys/block/nvme0n1/queue/write_zeroes_max_bytes
33554432

I can create a ext4 fs locally in the VM, so mkfs.ext4 must use write
same if available.

-Tony




_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

Thanks Toni for reporting,

> # mkfs.ext4 /dev/nvme0n1
> 
> [  125.031254] nvme-fabrics ctl: Failed to read smart log (error -5)
> [  125.031509] nvme nvme0: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery", addr 192.168.2.80:8009
> [  125.034133] nvme nvme0: Removing ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery"
> [  125.246827] nvme nvme0: creating 1 I/O queues.
> [  125.249356] nvme nvme0: mapped 1/0/0 default/read/poll queues.
> [  125.250788] nvme nvme0: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress:NVMf:uuid:23d9d3e0-a83e-45d7-a902-3e80679385f8",
> addr 192.168.2.80:8009
> [  125.257115] nvme0n1: detected capacity change from 0 to 34359738368
> [  153.188620] blk_update_request: I/O error, dev nvme0c0n1, sector
> 67108736 op 0x9:(WRITE_ZEROES) flags 0x5000800 phys_seg 0 prio class 0
> [  153.191395] BUG: kernel NULL pointer dereference, address:
> 0000000000000008
> [  153.191440] #PF: supervisor read access in kernel mode
> [  153.191468] #PF: error_code(0x0000) - not-present page
> [  153.191495] PGD 0 P4D 0
> [  153.191513] Oops: 0000 [#1] SMP PTI
> [  153.191534] CPU: 0 PID: 237 Comm: kworker/0:1H Not tainted
> 5.5.9-200.fc31.x86_64 #1
> [  153.191574] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS
> VirtualBox 12/01/2006
> [  153.191619] Workqueue: nvme_tcp_wq nvme_tcp_io_work [nvme_tcp]
> [  153.191660] RIP: 0010:nvme_tcp_io_work+0x303/0x790 [nvme_tcp]

Can you share which line *(nvme_tcp_io_work+0x303) map to?

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

> Thanks Toni for reporting,
> 
>> # mkfs.ext4 /dev/nvme0n1
>>
>> [  125.031254] nvme-fabrics ctl: Failed to read smart log (error -5)
>> [  125.031509] nvme nvme0: new ctrl: NQN
>> "nqn.2014-08.org.nvmexpress.discovery", addr 192.168.2.80:8009
>> [  125.034133] nvme nvme0: Removing ctrl: NQN
>> "nqn.2014-08.org.nvmexpress.discovery"
>> [  125.246827] nvme nvme0: creating 1 I/O queues.
>> [  125.249356] nvme nvme0: mapped 1/0/0 default/read/poll queues.
>> [  125.250788] nvme nvme0: new ctrl: NQN
>> "nqn.2014-08.org.nvmexpress:NVMf:uuid:23d9d3e0-a83e-45d7-a902-3e80679385f8", 
>>
>> addr 192.168.2.80:8009
>> [  125.257115] nvme0n1: detected capacity change from 0 to 34359738368
>> [  153.188620] blk_update_request: I/O error, dev nvme0c0n1, sector
>> 67108736 op 0x9:(WRITE_ZEROES) flags 0x5000800 phys_seg 0 prio class 0
>> [  153.191395] BUG: kernel NULL pointer dereference, address:
>> 0000000000000008
>> [  153.191440] #PF: supervisor read access in kernel mode
>> [  153.191468] #PF: error_code(0x0000) - not-present page
>> [  153.191495] PGD 0 P4D 0
>> [  153.191513] Oops: 0000 [#1] SMP PTI
>> [  153.191534] CPU: 0 PID: 237 Comm: kworker/0:1H Not tainted
>> 5.5.9-200.fc31.x86_64 #1
>> [  153.191574] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS
>> VirtualBox 12/01/2006
>> [  153.191619] Workqueue: nvme_tcp_wq nvme_tcp_io_work [nvme_tcp]
>> [  153.191660] RIP: 0010:nvme_tcp_io_work+0x303/0x790 [nvme_tcp]
> 
> Can you share which line *(nvme_tcp_io_work+0x303) map to?

Also, does this reproduce with file backend? I'm not able to
reproduce this on my vms (running KVM though).

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/20/20 5:59 PM, Sagi Grimberg wrote:
> Also, does this reproduce with file backend? I'm not able to
> reproduce this on my vms (running KVM though).

Do you mean a loopback device using a file on a FS or nvmet using a file
on a FS directly?  I wasn't aware that nvmet supported a file back end?

In my particular case the VM is representing a block device that is
backed by a file on the host, it's not doing pass through.

Thanks,
Tony


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Chaitanya Kulkarni]

On 03/20/2020 04:46 PM, Tony Asleson wrote:
> On 3/20/20 5:59 PM, Sagi Grimberg wrote:
>> >Also, does this reproduce with file backend? I'm not able to
>> >reproduce this on my vms (running KVM though).
> Do you mean a loopback device using a file on a FS or nvmet using a file
> on a FS directly?  I wasn't aware that nvmet supported a file back end?
>
nvmet does support file backend, please have a look at blktests [1]
under the test 025 in {BLKTEST_HOME}/tests/nvme about how to setup
target with file backend.

> In my particular case the VM is representing a block device that is
> backed by a file on the host, it's not doing pass through.
>
Not this file. (which I think is VBOX image attached to the VM).
> Thanks,
> Tony
>

[1] https://github.com/osandov/blktests.git.

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/20/20 7:43 PM, Chaitanya Kulkarni wrote:
> nvmet does support file backend, please have a look at blktests [1]
> under the test 025 in {BLKTEST_HOME}/tests/nvme about how to setup
> target with file backend.

I created a sparse file and used nvmetcli to change device to the
specified file.  I connected the client, ran dd and that worked fine.  I
tried using mkfs.ext4 and I got the same kernel oops.  Apparently it
doesn't matter if I use a file or device as the backing store for this
issue.

-Tony


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

>> nvmet does support file backend, please have a look at blktests [1]
>> under the test 025 in {BLKTEST_HOME}/tests/nvme about how to setup
>> target with file backend.
> 
> I created a sparse file and used nvmetcli to change device to the
> specified file.  I connected the client, ran dd and that worked fine.  I
> tried using mkfs.ext4 and I got the same kernel oops.  Apparently it
> doesn't matter if I use a file or device as the backing store for this
> issue.

Interesting, did you see the write_zeroes error though?

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/23/20 2:42 PM, Sagi Grimberg wrote:
> 
>>> nvmet does support file backend, please have a look at blktests [1]
>>> under the test 025 in {BLKTEST_HOME}/tests/nvme about how to setup
>>> target with file backend.
>>
>> I created a sparse file and used nvmetcli to change device to the
>> specified file.  I connected the client, ran dd and that worked fine.  I
>> tried using mkfs.ext4 and I got the same kernel oops.  Apparently it
>> doesn't matter if I use a file or device as the backing store for this
>> issue.
> 
> Interesting, did you see the write_zeroes error though?

Yes, write zeros error is still present.


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/20/20 5:54 PM, Sagi Grimberg wrote:
> Can you share which line *(nvme_tcp_io_work+0x303) map to?

I'm not running a debug kernel so I don't think I have that available?
Please advise if otherwise.

Thanks,
Tony


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

>> Can you share which line *(nvme_tcp_io_work+0x303) map to?
> 
> I'm not running a debug kernel so I don't think I have that available?
> Please advise if otherwise.

Maybe you will still have frame pointers though?

If you run:
gdb <path_to_mod>
...
 > l *(nvme_tcp_io_work+0x303)

Do you get anything useful?

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/23/20 3:33 AM, Sagi Grimberg wrote:
> 
>>> Can you share which line *(nvme_tcp_io_work+0x303) map to?
>>
>> I'm not running a debug kernel so I don't think I have that available?
>> Please advise if otherwise.
> 
> Maybe you will still have frame pointers though?
> 
> If you run:
> gdb <path_to_mod>
> ...
>> l *(nvme_tcp_io_work+0x303)
> 
> Do you get anything useful?

Nope, sorry.


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

>>>> Can you share which line *(nvme_tcp_io_work+0x303) map to?
>>>
>>> I'm not running a debug kernel so I don't think I have that available?
>>> Please advise if otherwise.
>>
>> Maybe you will still have frame pointers though?
>>
>> If you run:
>> gdb <path_to_mod>
>> ...
>>> l *(nvme_tcp_io_work+0x303)
>>
>> Do you get anything useful?
> 
> Nope, sorry.

Maybe install also kernel-debuginfo?

I tried looking at the sources myself, addr2line got me to:
--
gdb nvme-tcp.ko.debug
GNU gdb (Ubuntu 8.2.91.20190405-0ubuntu3) 8.2.91.20190405-git
Copyright (C) 2019 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
<http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
     <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from nvme-tcp.ko.debug...
(gdb) l *(nvme_tcp_io_work+0x303)
0x1c33 is in nvme_tcp_io_work (drivers/nvme/host/tcp.c:181).
--

Which is:
--
static inline struct page *nvme_tcp_req_cur_page(struct nvme_tcp_request 
*req)
{
         return req->iter.bvec->bv_page; // <== this
}
--

This means that we are trying to send data from a bio that doesn't
reference any data. So something here is strange.

Anyways, is it possible to add some information the the source?
--
diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c
index 11e10fe1760f..95c9e40037b4 100644
--- a/drivers/nvme/host/tcp.c
+++ b/drivers/nvme/host/tcp.c
@@ -888,6 +888,8 @@ static int nvme_tcp_try_send_data(struct 
nvme_tcp_request *req)
                 else
                         flags |= MSG_MORE;

+               pr_info("sending req %d len %lu page %p\n", 
blk_mq_rq_from_pdu(req)->tag, len, page);
+
                 /* can't zcopy slab pages */
                 if (unlikely(PageSlab(page))) {
                         ret = sock_no_sendpage(queue->sock, page, 
offset, len,
--

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Chaitanya Kulkarni]

On 03/23/2020 12:42 PM, Sagi Grimberg wrote:
>
>>>>> Can you share which line *(nvme_tcp_io_work+0x303) map to?
>>>>
>>>> I'm not running a debug kernel so I don't think I have that available?
>>>> Please advise if otherwise.
>>>
>>> Maybe you will still have frame pointers though?
>>>
>>> If you run:
>>> gdb <path_to_mod>
>>> ...
>>>> l *(nvme_tcp_io_work+0x303)
>>>
>>> Do you get anything useful?
>>
>> Nope, sorry.
>
> Maybe install also kernel-debuginfo?
>
> I tried looking at the sources myself, addr2line got me to:
> --
> gdb nvme-tcp.ko.debug
> GNU gdb (Ubuntu 8.2.91.20190405-0ubuntu3) 8.2.91.20190405-git
> Copyright (C) 2019 Free Software Foundation, Inc.
> License GPLv3+: GNU GPL version 3 or later
> <http://gnu.org/licenses/gpl.html>
> This is free software: you are free to change and redistribute it.
> There is NO WARRANTY, to the extent permitted by law.
> Type "show copying" and "show warranty" for details.
> This GDB was configured as "x86_64-linux-gnu".
> Type "show configuration" for configuration details.
> For bug reporting instructions, please see:
> <http://www.gnu.org/software/gdb/bugs/>.
> Find the GDB manual and other documentation resources online at:
>       <http://www.gnu.org/software/gdb/documentation/>.
>
> For help, type "help".
> Type "apropos word" to search for commands related to "word"...
> Reading symbols from nvme-tcp.ko.debug...
> (gdb) l *(nvme_tcp_io_work+0x303)
> 0x1c33 is in nvme_tcp_io_work (drivers/nvme/host/tcp.c:181).
> --
>
> Which is:
> --
> static inline struct page *nvme_tcp_req_cur_page(struct nvme_tcp_request
> *req)
> {
>           return req->iter.bvec->bv_page; // <== this
> }
> --
>
> This means that we are trying to send data from a bio that doesn't
> reference any data. So something here is strange.
>
> Anyways, is it possible to add some information the the source?
> --
> diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c
> index 11e10fe1760f..95c9e40037b4 100644
> --- a/drivers/nvme/host/tcp.c
> +++ b/drivers/nvme/host/tcp.c
> @@ -888,6 +888,8 @@ static int nvme_tcp_try_send_data(struct
> nvme_tcp_request *req)
>                   else
>                           flags |= MSG_MORE;
>
> +               pr_info("sending req %d len %lu page %p\n",
> blk_mq_rq_from_pdu(req)->tag, len, page);
> +
>                   /* can't zcopy slab pages */
>                   if (unlikely(PageSlab(page))) {
>                           ret = sock_no_sendpage(queue->sock, page,
> offset, len,
> --
>

FYI, not a tcp fabrics expert.

I remember a following fix for write-zeroes target/loop.c.

commit eb464833a2e787996474ad33dafa2c5336d4c477
Author: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
Date:   Fri May 11 02:38:15 2018 -0400

     nvmet-loop: use nr_phys_segments when map rq to sgl

     Use blk_rq_nr_phys_segments() instead of blk_rq_payload_bytes() to 
check
     if a command contains data to me mapped.  This fixes the case where
     a struct requests contains LBAs, but no data will actually be send,
     e.g. the pending Write Zeroes support.

     Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
     Signed-off-by: Christoph Hellwig <hch@lst.de>


I can see that :-
nvme_tcp_queue_rq()
  nvme_tcp_setup_cmd_pdu()

   req->data_len = blk_rq_payload_bytes(rq); <--


Based on the above fix maybe something like following fix the problem ?

diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c
index 814ea2317f4e..f9aac34c87ac 100644
--- a/drivers/nvme/host/tcp.c
+++ b/drivers/nvme/host/tcp.c
@@ -2187,7 +2187,7 @@ static blk_status_t nvme_tcp_setup_cmd_pdu(struct 
nvme_ns *ns,
         req->data_sent = 0;
         req->pdu_len = 0;
         req->pdu_sent = 0;
-       req->data_len = blk_rq_payload_bytes(rq);
+       req->data_len = blk_rq_nr_phys_segments(rq);
         req->curr_bio = rq->bio;

         if (rq_data_dir(rq) == WRITE &&
> _______________________________________________
> linux-nvme mailing list
> linux-nvme@lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-nvme
>


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

> FYI, not a tcp fabrics expert.
> 
> I remember a following fix for write-zeroes target/loop.c.
> 
> commit eb464833a2e787996474ad33dafa2c5336d4c477
> Author: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
> Date:   Fri May 11 02:38:15 2018 -0400
> 
>       nvmet-loop: use nr_phys_segments when map rq to sgl
> 
>       Use blk_rq_nr_phys_segments() instead of blk_rq_payload_bytes() to
> check
>       if a command contains data to me mapped.  This fixes the case where
>       a struct requests contains LBAs, but no data will actually be send,
>       e.g. the pending Write Zeroes support.
> 
>       Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
>       Signed-off-by: Christoph Hellwig <hch@lst.de>
> 
> 
> I can see that :-
> nvme_tcp_queue_rq()
>    nvme_tcp_setup_cmd_pdu()
> 
>     req->data_len = blk_rq_payload_bytes(rq); <--

The analysis looks correct, the only problem is why I cannot reproduce
this. If this is the case, I need to understand why this does not
reproduce.

> Based on the above fix maybe something like following fix the problem ?
> 
> diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c
> index 814ea2317f4e..f9aac34c87ac 100644
> --- a/drivers/nvme/host/tcp.c
> +++ b/drivers/nvme/host/tcp.c
> @@ -2187,7 +2187,7 @@ static blk_status_t nvme_tcp_setup_cmd_pdu(struct
> nvme_ns *ns,
>           req->data_sent = 0;
>           req->pdu_len = 0;
>           req->pdu_sent = 0;
> -       req->data_len = blk_rq_payload_bytes(rq);
> +       req->data_len = blk_rq_nr_phys_segments(rq);

data_len is length in bytes, but the inline_data call should
perhaps take it into account.

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Sagi Grimberg]

>> I can see that :-
>> nvme_tcp_queue_rq()
>>    nvme_tcp_setup_cmd_pdu()
>>
>>     req->data_len = blk_rq_payload_bytes(rq); <--
> 
> The analysis looks correct, the only problem is why I cannot reproduce
> this. If this is the case, I need to understand why this does not
> reproduce.
> 
>> Based on the above fix maybe something like following fix the problem ?
>>
>> diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c
>> index 814ea2317f4e..f9aac34c87ac 100644
>> --- a/drivers/nvme/host/tcp.c
>> +++ b/drivers/nvme/host/tcp.c
>> @@ -2187,7 +2187,7 @@ static blk_status_t nvme_tcp_setup_cmd_pdu(struct
>> nvme_ns *ns,
>>           req->data_sent = 0;
>>           req->pdu_len = 0;
>>           req->pdu_sent = 0;
>> -       req->data_len = blk_rq_payload_bytes(rq);
>> +       req->data_len = blk_rq_nr_phys_segments(rq);
> 
> data_len is length in bytes, but the inline_data call should
> perhaps take it into account.

Managed to reproduce, the issue was that the write_zeroes were in
size that is larger than the in-capsule data size. Once I increased
that I was able to reproduce the issue (at mount time, not mkfs time).

Chaitanya, you were correct, that was the root cause.
Tony, does this patch work for you? It makes the issue disappear
on my end.

--
diff --git a/drivers/nvme/host/tcp.c b/drivers/nvme/host/tcp.c
index 11e10fe1760f..b545a9e96327 100644
--- a/drivers/nvme/host/tcp.c
+++ b/drivers/nvme/host/tcp.c
@@ -177,16 +177,14 @@ static inline bool nvme_tcp_async_req(struct 
nvme_tcp_request *req)
  static inline bool nvme_tcp_has_inline_data(struct nvme_tcp_request *req)
  {
         struct request *rq;
-       unsigned int bytes;

         if (unlikely(nvme_tcp_async_req(req)))
                 return false; /* async events don't have a request */

         rq = blk_mq_rq_from_pdu(req);
-       bytes = blk_rq_payload_bytes(rq);

-       return rq_data_dir(rq) == WRITE && bytes &&
-               bytes <= nvme_tcp_inline_data_size(req->queue);
+       return rq_data_dir(rq) == WRITE && req->data_len &&
+               req->data_len <= nvme_tcp_inline_data_size(req->queue);
  }

  static inline struct page *nvme_tcp_req_cur_page(struct 
nvme_tcp_request *req)
@@ -2182,7 +2180,9 @@ static blk_status_t nvme_tcp_map_data(struct 
nvme_tcp_queue *queue,

         c->common.flags |= NVME_CMD_SGL_METABUF;

-       if (rq_data_dir(rq) == WRITE && req->data_len &&
+       if (!blk_rq_nr_phys_segments(rq))
+               nvme_tcp_set_sg_null(c);
+       else if (rq_data_dir(rq) == WRITE &&
             req->data_len <= nvme_tcp_inline_data_size(queue))
                 nvme_tcp_set_sg_inline(queue, c, req->data_len);
         else
@@ -2209,7 +2209,8 @@ static blk_status_t nvme_tcp_setup_cmd_pdu(struct 
nvme_ns *ns,
         req->data_sent = 0;
-       req->data_len = blk_rq_payload_bytes(rq);
+       req->data_len = blk_rq_nr_phys_segments(rq) ?
+                               blk_rq_payload_bytes(rq) : 0;
         req->curr_bio = rq->bio;

         if (rq_data_dir(rq) == WRITE &&
--

_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme

Re: nvmet: Kernel oops when doing mkfs on nvme-tcp device

[Tony Asleson]

On 3/23/20 5:02 PM, Sagi Grimberg wrote:
> Tony, does this patch work for you? It makes the issue disappear
> on my end.

I built a generic 5.5 kernel and modules with debug.  I recreated the
issue and using gdb I get:

...
Reading symbols from
/lib/modules/5.5.0/kernel/drivers/nvme/host/nvme-tcp.ko...
(gdb) l nvme_tcp_io_work+0x303
Function "nvme_tcp_io_work+0x303" not defined.
(gdb) l *(nvme_tcp_io_work+0x303)
0x1c03 is in nvme_tcp_io_work (drivers/nvme/host/tcp.c:181).

179  static inline struct page *nvme_tcp_req_cur_page(struct
nvme_tcp_request *req)
 180 {
 181         return req->iter.bvec->bv_page;
 182 }

which matches what Chaitanya found.

After applying your patch I'm no longer hitting this issue!

Thanks everyone!

-Tony


_______________________________________________
linux-nvme mailing list
linux-nvme@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-nvme