Re: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init: ***ERROR*** Initialization timed out in state 3

[Oza Oza <oza.oza at broadcom.com>]

[-- Attachment #1: Type: text/plain, Size: 14203 bytes --]

We have more than one pcie controller in SOC. And I try to run the command
as following which is working fine.

But the IOPS do not scale up. Infact they go down.

If I run on single file
./fio --randrepeat=1
--ioengine=/home/oza/SPDK/spdk/examples/nvme/fio_plugin/fio_plugin
 --numjobs=1 --direct=1 --gtod_reduce=1 --thread=1 --name=readtest
--filename=0000.01.00.00
 --bs=4096 --iodepth=128  --size=16G --readwrite=read

As opposed to following
./fio --randrepeat=1
--ioengine=/home/oza/SPDK/spdk/examples/nvme/fio_plugin/fio_plugin
 --numjobs=1 --direct=1 --gtod_reduce=1 --thread=1 --name=readtest
--filename=0000.01.00.00/1:0001.01.00.00/1:0006.01.00.00/1
 --bs=4096 --iodepth=128  --size=16G --readwrite=read

The IOPS go down. Which I believe is because of CPU and number of threads.

SPDK seems to be creating only 1 thread to handle all the 3 file reads ?
and it is saturating one cpu.

Let me know if this is the case.

Regards,
Oza.
-----Original Message-----
From: Oza Oza [mailto:oza.oza(a)broadcom.com]
Sent: Wednesday, April 05, 2017 10:44 AM
To: 'Storage Performance Development Kit'
Subject: RE: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init: ***ERROR***
Initialization timed out in state 3

Ok I think fio runs and give good numbers for our SOC.
But same questions I have again.

1)  right now SPDK/fio_plugin doesnt support multiple threads right ? let us
say I want to create multiple threads to push data in order to utilize all
the cpus, then ? because I want to scale SPDK across cpu to effectively
utilize it.

2) the posted log in my previous mail:
	Why probing of spdk_nvme happens 3 times ? (rather multiple times ?)
	probe driver: 8086:953 spdk_nvme
is it normal ?

Regards,
Oza.
-----Original Message-----
From: Oza Oza [mailto:oza.oza(a)broadcom.com]
Sent: Wednesday, April 05, 2017 9:31 AM
To: 'Storage Performance Development Kit'
Subject: RE: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init: ***ERROR***
Initialization timed out in state 3

Also, couple of more questions.

1)  right now SPDK/fio_plugin doesnt support multiple threads right ? let us
say I want to create multiple threads to push data in order to utilize all
the cpus, then ? because I want to scale SPDK across cpu to effectively
utilize it.

2) the posted log in my previous mail:
	Why probing of spdk_nvme happens 3 times ? (rather multiple times ?)
	probe driver: 8086:953 spdk_nvme
is it normal ?

Regards,
Oza.
-----Original Message-----
From: Oza Oza [mailto:oza.oza(a)broadcom.com]
Sent: Wednesday, April 05, 2017 9:04 AM
To: 'Storage Performance Development Kit'
Subject: RE: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init: ***ERROR***
Initialization timed out in state 3

Ok, what is --thread=1 ?  (it means it will create one thread to handle the
IO ?)


./fio --randrepeat=1
--ioengine=/home/oza/SPDK/spdk/examples/nvme/fio_plugin/fio_plugin
 --direct=1 --gtod_reduce=1 --thread=1 --name=readtest
--filename=0000.01.00.00/1
 --bs=4096   --iodepth=128 --size=4G --readwrite=read

With that it went ahead but at the end it says "requested device can not be
used"
I don’t think actual data transfer took place.

/home/oza/fio /home/oza/SPDK/spdk
EAL: pci driver is being registered 0x1nreadtest: (g=0): rw=read,
bs=4096B-4096B,4096B-4096B,4096B-4096B, ioengine=spdk_fio, iodepth=128
fio-2.17-29-gf0ac1
Starting 1 thread
Starting Intel(R) DPDK initialization ...
[ DPDK EAL parameters: fio -c
1 --file-prefix=spdk_pid6412 --base-virtaddr=0x1000000000 --proc-type=auto ]
EAL: Detected 8 lcore(s)
EAL: Auto-detected process type: PRIMARY
EAL: Probing VFIO support...
EAL: VFIO support initialized
EAL: cannot open /proc/self/numa_maps, consider that all memory is in
socket_id 0
EAL: PCI device 0000:01:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
EAL:   using IOMMU type 1 (Type 1)
EAL: vfio_type1_dma_map dma_map.iova:0x965800000 dma_map.vaddr:0x1000000000
dma_map.size=0x200000
EAL: vfio_type1_dma_map dma_map.iova:0x965c00000 dma_map.vaddr:0x1000200000
dma_map.size=0x7fc00000
EAL: vfio_type1_dma_map dma_map.iova:0x9e6200000 dma_map.vaddr:0x107fe00000
dma_map.size=0x200000
EAL: vfio_group_fd=11 iommu_group_no=3 vfio_dev_fd=13
EAL: reg=0x2000 fd=13 cap_offset=0x50
EAL: the msi-x bar number is 0 0x2000 0x200
EAL: bar_addr 0x80000000
EAL: the dev->mem_resource[i].addr 0x80000000
EAL: Hotplug doesn't support vfio yet
spdk_fio_setup() is being called
............inside spdk_nvme_probe
............nvme_driver_init done
............nvme_transport availlable done
EAL: PCI device 0000:01:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
EAL: vfio_group_fd=11 iommu_group_no=3 vfio_dev_fd=16
EAL: reg=0x2000 fd=16 cap_offset=0x50
EAL: the msi-x bar number is 0 0x2000 0x200
EAL: bar_addr 0x80004000
EAL: the dev->mem_resource[i].addr 0x80004000 inside
nvme_pcie_ctrlr_construct
EAL: inside pci_vfio_write_config offset=4 Enabled PCI busmaster and disable
INTx nvme_ctrlr_init_cap cap=0x28010fff nvme_ctrlr_construct
nvme_pcie_ctrlr_construct_admin_qpair done..
nvme_ctrlr_add_process done..
.............nvme_transport_ctrlr_scan done...
.............before nvme_init_controllers...
Controller is currently disabled. We can jump straight to enabling it.
Controller is active
.............NVME_CTRLR_STATE_ENABLE_WAIT_FOR_READY_1...
going to start controller.
started controller.
.............nvme_init_controllers done.
EAL: Hotplug doesn't support vfio yetw=0KiB/s][r=0,w=0 IOPS][eta 00m:00s]
EAL: PCI device 0000:01:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
EAL: vfio_group_fd=11 iommu_group_no=3 vfio_dev_fd=18
EAL: reg=0x2000 fd=18 cap_offset=0x50
EAL: the msi-x bar number is 0 0x2000 0x200
EAL: bar_addr 0x80008000
EAL: the dev->mem_resource[i].addr 0x80008000
EAL: Hotplug doesn't support vfio yet
EAL: Requested device 0000:01:00.0 cannot be used

readtest: (groupid=0, jobs=1): err= 0: pid=6418: Wed Apr  5 03:31:23 2017
   read: IOPS=442k, BW=1726MiB/s (1810MB/s)(4096MiB/2373msec)
  cpu          : usr=99.83%, sys=0.00%, ctx=268, majf=0, minf=0
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%,
 >=64=100.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
 >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
 >=64=0.1%
     issued rwt: total=1048576,0,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=128

Run status group 0 (all jobs):
   READ: bw=1726MiB/s (1810MB/s), 1726MiB/s-1726MiB/s (1810MB/s-1810MB/s),
io=4096MiB (4295MB), run=2373-2373msec

-----Original Message-----
From: SPDK [mailto:spdk-bounces(a)lists.01.org] On Behalf Of Harris, James R
Sent: Tuesday, April 04, 2017 9:09 PM
To: Storage Performance Development Kit
Subject: Re: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init: ***ERROR***
Initialization timed out in state 3


> On Apr 4, 2017, at 7:18 AM, Oza Oza <oza.oza(a)broadcom.com> wrote:
>
> And I am using following command.
>
> fio --randrepeat=1
> --ioengine=/home/oza/SPDK/spdk/examples/nvme/fio_plugin/fio_plugin
> --direct=1 --numjobs=1 --gtod_reduce=1 --name=readtest
> --filename=0000.01.00.00/1 --bs=4096   --iodepth=128 --size=4G
> --readwrite=read

Hi Oza,

Please add —thread=1.  I will push a patch shortly that documents this
option for the SPDK plugin and checks for it at runtime.

Regarding your patches, you can submit them as a pull request to the SPDK
GitHub project.  See http://www.spdk.io/development/ for more details.

Thanks,

-Jim

>
> Regards,
> Oza.
> -----Original Message-----
> From: Oza Oza [mailto:oza.oza(a)broadcom.com]
> Sent: Tuesday, April 04, 2017 2:55 PM
> To: 'Storage Performance Development Kit'
> Subject: RE: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init:
> ***ERROR*** Initialization timed out in state 3
>
> Hi Harris,
>
> Thanks for the response.
>
> for time-being, I am stuck with one after the other problem. Although
> problems are being resolved.
>
> Whatever I posted on 1st of April is resolved, and that exposed bug in
> our RC driver where I was not checking competition status.
> That is now solved.
>
> The controller timeout also is resolved by adding some delay after
> SPDK nvme_ctrlr.c
>
> And I think all the errors have nothing to do with ARMv8 porting,
> because mostly it compiled straightly, there are some minor patches.
> Which I will let you know, also at the same time let me know how do I
> contribute/discuss any change ?
>
> Now I am stuck here: let me know if you have clue.
>
> odepth=128 --size=4G --readwrite=read --filename=0000.01.00.00/1
> --bs=4096 --i /home/oza/fio /home/oza/SPDK/spdk
> EAL: pci driver is being registered 0x1nreadtest: (g=0): rw=read,
> bs=4096B-4096B,4096B-4096B,4096B-4096B, ioengine=spdk_fio, iodepth=128
> fio-2.17-29-gf0ac1
> Starting 1 process
> Starting Intel(R) DPDK initialization ...
> [ DPDK EAL parameters: fio -c 1 --file-prefix=spdk_pid6177
> --base-virtaddr=0x1000000000 --proc-type=auto ]
> EAL: Detected 8 lcore(s)
> EAL: Auto-detected process type: PRIMARY
> EAL: Probing VFIO support...
> EAL: VFIO support initialized
> EAL: cannot open /proc/self/numa_maps, consider that all memory is in
> socket_id 0
> EAL: PCI device 0000:01:00.0 on NUMA socket 0
> EAL:   probe driver: 8086:953 spdk_nvme
> EAL:   using IOMMU type 1 (Type 1)
> EAL: vfio_group_fd=11 iommu_group_no=3 *vfio_dev_fd=13
> EAL: reg=0x2000 fd=13 cap_offset=0x50
> EAL: Hotplug doesn't support vfio yet
> EAL:   probe driver: 8086:953 spdk_nvme
> EAL: vfio_group_fd=11 iommu_group_no=3 *vfio_dev_fd=16
> EAL: reg=0x2000 fd=16 cap_offset=0x50
> nvme_pcie.c: 994:nvme_pcie_qpair_complete_pending_admin_request:[
> 1041.919073] pgd = ffff800975800000
> ***ERROR*** the active process (pid 6184) is not found for this[
> 1041.928312] [00000008] *pgd=00000009f5815003 controller.
> fio: pid=6184, got signal=11
>
> readtest: (groupid=0, jobs=1): err= 0: pid=6184: Tue Apr  4 09:12:28 2017
>   read: IOPS=442k, BW=1727MiB/s (1811MB/s)(4096MiB/2372msec)
>  cpu          : usr=99.87%, sys=0.00%, ctx=238, majf=0, minf=16
>  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%,
>> =64=100.0%
>     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>> =64=0.0%
>     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>> =64=0.1%
>     issued rwt: total=1048576,0,0, short=0,0,0, dropped=0,0,0
>     latency   : target=0, window=0, percentile=100.00%, depth=128
>
> Run status group 0 (all jobs):
>   READ: bw=1727MiB/s (1811MB/s), 1727MiB/s-1727MiB/s
> (1811MB/s-1811MB/s), io=4096MiB (4295MB), run=2372-2372msec
>
> Regards,
> Oza.
> -----Original Message-----
> From: SPDK [mailto:spdk-bounces(a)lists.01.org] On Behalf Of Harris,
> James R
> Sent: Monday, April 03, 2017 9:12 PM
> To: Storage Performance Development Kit
> Subject: Re: [SPDK] nvme_ctrlr.c:1224:nvme_ctrlr_process_init:
> ***ERROR*** Initialization timed out in state 3
>
> Hi Oza,
>
>> On Apr 3, 2017, at 2:01 AM, Oza Oza <oza.oza(a)broadcom.com> wrote:
>>
>> I have ported SPDK for ARMv8.
>
> Great!  Do you have patches that you can share?
>
>> And DPDK is compiled with version: 16.11.1
>>
>> init controller is failing.
>
> Does this mean that the previous issue you reported on April 1 has
> been resolved?  If so, can you share details?
>
>>
>> root(a)ubuntu:/home/oza/SPDK/spdk#
>> odepth=128 --size=4G --readwrite=read --filename=0000.01.00.00/1
>> --bs=4096 --i /home/oza/fio /home/oza/SPDK/spdk
>> EAL: pci driver is being registered 0x1nreadtest: (g=0): rw=read,
>> bs=4096B-4096B,4096B-4096B,4096B-4096B, ioengine=spdk_fio,
>> iodepth=128
>> fio-2.17-29-gf0ac1
>> Starting 1 process
>> Starting Intel(R) DPDK initialization ...
>> [ DPDK EAL parameters: fio -c 1 --file-prefix=spdk_pid6448
>> --base-virtaddr=0x1000000000 --proc-type=auto ]
>> EAL: Detected 8 lcore(s)
>> EAL: Auto-detected process type: PRIMARY
>> EAL: Probing VFIO support...
>> EAL: VFIO support initialized
>> EAL: cannot open /proc/self/numa_maps, consider that all memory is in
>> socket_id 0
>> EAL: PCI device 0000:01:00.0 on NUMA socket 0
>> EAL:   probe driver: 8086:953 spdk_nvme
>> EAL:   using IOMMU type 1 (Type 1)
>> EAL: vfio_group_fd=11 iommu_group_no=3 *vfio_dev_fd=13
>> EAL: reg=0x2000 fd=13 cap_offset=0x50
>> EAL: the msi-x bar number is 0 0x2000 0x200
>> EAL: Hotplug doesn't support vfio yet
>> spdk_fio_setup() is being called
>> EAL: PCI device 0000:01:00.0 on NUMA socket 0
>> EAL:   probe driver: 8086:953 spdk_nvme
>> EAL: vfio_group_fd=11 iommu_group_no=3 *vfio_dev_fd=16
>> EAL: reg=0x2000 fd=16 cap_offset=0x50
>> EAL: the msi-x bar number is 0 0x2000 0x200
>> EAL: inside pci_vfio_write_config offset=4
>> nvme_ctrlr.c:1224:nvme_ctrlr_process_init: ***ERROR*** Initialization
>> timed out in state 3
>> nvme_ctrlr.c: 403:nvme_ctrlr_shutdown: ***ERROR*** did not shutdown
>> within
>> 5 seconds
>
> I think this is where seeing your ARMv8 patches would help.  Then we
> could collaborate on if/how the ARMv8 changes you have made may be
> causing the initialization error.
>
>> EAL: Hotplug doesn't support vfio yet
>> EAL: PCI device 0000:01:00.0 on NUMA socket 0
>> EAL:   probe driver: 8086:953 spdk_nvme
>> EAL: vfio_group_fd=11 iommu_group_no=3 *vfio_dev_fd=18
>> EAL: reg=0x2000 fd=18 cap_offset=0x50
>> EAL: the msi-x bar number is 0 0x2000 0x200
>> EAL: Hotplug doesn't support vfio yet
>> EAL: Requested device 0000:01:00.0 cannot be used
>> spdk_nvme_probe() failed
>
> Thanks,
>
> -Jim
>
> _______________________________________________
> SPDK mailing list
> SPDK(a)lists.01.org
> https://lists.01.org/mailman/listinfo/spdk
> _______________________________________________
> SPDK mailing list
> SPDK(a)lists.01.org
> https://lists.01.org/mailman/listinfo/spdk

_______________________________________________
SPDK mailing list
SPDK(a)lists.01.org
https://lists.01.org/mailman/listinfo/spdk