Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDMA Memory Regions

[JD Zheng <jiandong.zheng at broadcom.com>]

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

Hi Seth,

Thanks for the detailed description, now I understand the reason behind 
the checking. But I have a question, why checking against 2MiB? Is it 
because DPDK uses 2MiB page size by default so that one RDMA memory 
region should not cross 2 pages?

 > Once I see what your memory registrations look like and what 
addresses you're failing on, it will help me understand what is going on 
better.

I've added some print in nvmf_rdma_fill_buffers()
@@ -1502,7 +1503,11 @@ nvmf_rdma_fill_buffers(struct 
spdk_nvmf_rdma_transport *rtransport,
                 remaining_length -= rdma_req->req.iov[iovcnt].iov_len;

                 if (translation_len < rdma_req->req.iov[iovcnt].iov_len) {
-                       SPDK_ERRLOG("Data buffer split over multiple 
RDMA Memory Regions\n");
+                       SPDK_ERRLOG("Data buffer split over multiple 
RDMA Memory Regions %p %d (%d) (%d) (%d) (%d)\n", 
rdma_req->buffers[iovcnt], iovcnt, length, remaining_length, 
translation_len, rdma_req->req.iov[iovcnt].iov_len);
                         return -EINVAL;
                 }

With this I can see which buffer failed the checking.
For example, when SPKD initializes the memory pool, one of the buffers 
starts with 0x2000193feb00, and when failed, I got following:

rdma.c:1510:nvmf_rdma_fill_buffers: *ERROR*: Data buffer split over 
multiple RDMA Memory Regions 0x2000193feb00 0 (8192) (0) (5376) (8192)

This buffer has 5376B on one 2MB page and the rest of it 
(8192-5376=2816B) is on another page.

The change https://review.gerrithub.io/c/spdk/spdk/+/463893 to use iov 
base should make it better as iov base is 4KiB aligned. In above case, 
iov_base is 0x2000193feb00 & 0xfff = 0x2000193fe000 and it should pass 
the checking.
However, another buffer in the pool is 0x2000192010c0 and iov_base is 
0x200019201000, which would fail the checking because it is only 4KiB to 
2MB boundary and IOUnitSize is 8KiB.

I will add the change from 
https://review.gerrithub.io/c/spdk/spdk/+/463892 and rerun the test to 
get more information.

I also attached the conf file too. The cmd line is "nvmf_tgt -m 0xff -j 
0x90000000:0x20000000 -c 16disk_1ns.conf"

Thanks,
JD


On 8/1/19 7:52 AM, Howell, Seth wrote:
> Hi JD,
> 
> I was doing a little bit of digging in the dpdk documentation around this process, and I have a little bit more information. We were pretty worried about the whole dynamic memory allocations thing a few releases ago, so Jim helped add a flag into DPDK that prevented allocations from being allocated and freed in different granularities. This flag also prevents malloc heap allocations from spanning multiple memory events. However, this flag didn't make it into DPDK until 19.02 (More documentation at https://doc.dpdk.org/guides/prog_guide/env_abstraction_layer.html#environment-abstraction-layer if you're interested). We have some code in the SPDK environment layer that tries to deal with that (see lib/env_dpdk/memory.c:memory_hotplug_cb) but I don't know that that function is entirely capable of handling the heap allocations spanning multiple memory events part of the problem.
> Since you are using dpdk 18.11, the memory callback inside of lib/env_dpdk looks like a good candidate for our issue. My best guess is that somehow a heap allocation from the buffer mempool is hitting across addresses from two dynamic memory allocation events. I'd still appreciate it if you could send me the information in my last e-mail, but I think we're onto something here.
> 
> Thanks,
> 
> Seth
> 
> -----Original Message-----
> From: SPDK [mailto:spdk-bounces(a)lists.01.org] On Behalf Of Howell, Seth
> Sent: Thursday, August 1, 2019 5:26 AM
> To: JD Zheng <jiandong.zheng(a)broadcom.com>; Storage Performance Development Kit <spdk(a)lists.01.org>
> Subject: Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDMA Memory Regions
> 
> Hi JD,
> 
> Thanks for doing that. Yeah, I am mainly looking to see how the mempool addresses are mapped into the NIC with ibv_reg_mr.
> 
> I think it's odd that we are using the buffer base for the memory check, we should be using the iov base, but I don't believe that would cause the issue you are seeing. Pushed a change to modify that behavior anyways though: https://review.gerrithub.io/c/spdk/spdk/+/463893
> 
> There was one registration that I wasn't able to catch from your last log. Sorry about that, I forgot there wasn’t a debug log for it. Can you try it again with this change which adds noticelogs for the relevant registrations. https://review.gerrithub.io/c/spdk/spdk/+/463892 You should be able to run your test without the -Lrdma argument this time to avoid the extra bloat in the logs.
> 
> The underlying assumption of the code is that any given object is not going to cross a dynamic memory allocation from DPDK. For a little background, when the mempool gets created, the dpdk code allocates some number of memzones to accommodate those buffer objects. Then it passes those memzones down one at a time and places objects inside the mempool from the given memzone until the memzone is exhausted. Then it goes back and grabs another memzone. This process continues until all objects are accounted for.
> This only works if each memzone corresponds to a single memory event when using dynamic memory allocation. My understanding was that this was always the case, but this error makes me think that it's possible that that's not true.
> 
> Once I see what your memory registrations look like and what addresses you're failing on, it will help me understand what is going on better.
> 
> Can you also provide the command line you are using to start the nvmf_tgt application and attach your configuration file?
> 
> Thanks,
> 
> Seth
> -----Original Message-----
> From: JD Zheng [mailto:jiandong.zheng(a)broadcom.com]
> Sent: Wednesday, July 31, 2019 3:13 PM
> To: Howell, Seth <seth.howell(a)intel.com>; Storage Performance Development Kit <spdk(a)lists.01.org>
> Subject: Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDMA Memory Regions
> 
> Hi Seth,
> 
> After I enabled debug and ran nvmf_tgt with -L rdma, I got some logs like:
> rdma.c: 746:nvmf_rdma_resources_create: *DEBUG*: Command Array:
> 0x2000084bf000 Length: 40000 LKey: e601
> rdma.c: 749:nvmf_rdma_resources_create: *DEBUG*: Completion Array:
> 0x200008621000 Length: 10000 LKey: e701
> rdma.c: 753:nvmf_rdma_resources_create: *DEBUG*: In Capsule Data Array:
> 0x200018600000 Length: 1000000 LKey: e801
> rdma.c: 746:nvmf_rdma_resources_create: *DEBUG*: Command Array:
> 0x20000847e000 Length: 40000 LKey: e701
> rdma.c: 749:nvmf_rdma_resources_create: *DEBUG*: Completion Array:
> 0x20000846d000 Length: 10000 LKey: e801
> rdma.c: 753:nvmf_rdma_resources_create: *DEBUG*: In Capsule Data Array:
> 0x200019800000 Length: 1000000 LKey: e901
> rdma.c: 746:nvmf_rdma_resources_create: *DEBUG*: Command Array:
> 0x200016ebb000 Length: 40000 LKey: e801
> rdma.c: 749:nvmf_rdma_resources_create: *DEBUG*: Completion Array:
> 0x20000845c000 Length: 10000 LKey: e901
> rdma.c: 753:nvmf_rdma_resources_create: *DEBUG*: In Capsule Data Array:
> 0x20001aa00000 Length: 1000000 LKey: ea01
> rdma.c: 746:nvmf_rdma_resources_create: *DEBUG*: Command Array:
> 0x200016e7a000 Length: 40000 LKey: e901
> rdma.c: 749:nvmf_rdma_resources_create: *DEBUG*: Completion Array:
> 0x20000844b000 Length: 10000 LKey: ea01
> rdma.c: 753:nvmf_rdma_resources_create: *DEBUG*: In Capsule Data Array:
> 0x20001bc00000 Length: 1000000 LKey: eb01 ...
> 
> Is this you are look for as memory regions registered for NIC?
> 
> I attached the complete log.
> 
> Thanks,
> JD
> 
> On 7/30/19 5:28 PM, JD Zheng wrote:
>> Hi Seth,
>>
>> Thanks for the prompt reply!
>>
>> Please find answers inline.
>>
>> JD
>>
>> On 7/30/19 5:01 PM, Howell, Seth wrote:
>>> Hi JD,
>>>
>>> Thanks for the report. I want to ask a few questions to start getting
>>> to the bottom of this. Since this issue doesn't currently reproduce
>>> on our per-patch or nightly tests, I would like to understand what's
>>> unique about your setup so that we can replicate it in a per patch
>>> test to prevent future regressions.
>> I am running it on aarch64 platform. I tried x86 platform and I can
>> see same buffer alignment in memory pool but can't run the real test
>> to reproduce it due to other missing pieces.
>>
>>>
>>> What options are you passing when you create the rdma transport? Are
>>> you creating it over RPC or in a configuration file?
>> I am using conf file. Pls let me know if you'd like to look into conf file.
>>
>>>
>>> Are you using the current DPDK submodule as your environment
>>> abstraction layer?
>> No. Our project uses specific version of DPDK, which is v18.11. I did
>> quick test using latest and DPDK submodule on x86, and the buffer
>> alignment is the same, i.e. 64B aligned.
>>
>>>
>>> I notice that your error log is printing from
>>> spdk_nvmf_transport_poll_group_create, which value exactly are you
>>> printing out?
>> Here is patch to add dbg print. Pls note that SPDK version is v19.04
>>
>> @@ -215,6 +222,7 @@ spdk_nvmf_transport_poll_group_create(st
>>                                   SPDK_NOTICELOG("Unable to reserve the
>> full number of buffers for the pg buffer cache.\n");
>>                                   break;
>>                           }
>> +                       SPDK_ERRLOG("%p %d(%d)\n", buf,
>> group->buf_cache_count, group->buf_cache_size);
>>                           STAILQ_INSERT_HEAD(&group->buf_cache, buf,
>> link);
>>                           group->buf_cache_count++;
>>                   }
>>
>>>
>>> Can you run your target with the -L rdma option to get a dump of the
>>> memory regions registered with the NIC?
>> Let me test and get back to you soon.
>>
>>>
>>> We made a couple of changes to this code when dynamic memory
>>> allocations were added to DPDK. There were some safeguards that we
>>> added to try and make sure this case wouldn't hit, so I'd like to
>>> make sure you are running on the latest DPDK submodule as well as the
>>> latest SPDK to narrow down where we need to look.
>> Unfortunately I can't easily update DPDK because other team maintains
>> it internally. But if it can be repro and fixed in latest, I will try
>> to pull in the fix.
>>
>>>
>>> Thanks,
>>>
>>> Seth
>>>
>>> -----Original Message-----
>>> From: SPDK [mailto:spdk-bounces(a)lists.01.org] On Behalf Of JD Zheng
>>> via SPDK
>>> Sent: Wednesday, July 31, 2019 3:00 AM
>>> To: spdk(a)lists.01.org
>>> Cc: JD Zheng <jiandong.zheng(a)broadcom.com>
>>> Subject: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple
>>> RDMA Memory Regions
>>>
>>> Hello,
>>>
>>> When I run nvmf_tgt over RDMA using latest SPDK code, I occasionally
>>> ran into this errors:
>>> "rdma.c:1505:nvmf_rdma_fill_buffers: *ERROR*: Data buffer split over
>>> multiple RDMA Memory Regions"
>>>
>>> After digging into the code, I found that nvmf_rdma_fill_buffers()
>>> calls spdk_mem_map_translate() to check if a data buffer sit on 2 2MB
>>> pages, and if it is the case, it reports this error.
>>>
>>> The following commit added change to use data buffer start address to
>>> calculate the size between buffer start address and 2MB boundary. The
>>> caller nvmf_rdma_fill_buffers() uses the size to compare with IO Unit
>>> size (which is 8KB in my conf) to determine if the buffer passes 2MB
>>> boundary.
>>>
>>> commit 37b7a308941b996f0e69049358a6119ed90d70a2
>>> Author: Darek Stojaczyk <dariusz.stojaczyk(a)intel.com>
>>> Date:   Tue Nov 13 17:43:46 2018 +0100
>>>
>>>        memory: fix contiguous memory calculation for unaligned buffers
>>>
>>> In nvmf_tgt, the buffers are pre-allocated as a memory pool and new
>>> request will use free buffer from that pool and the buffer start
>>> address is passed to nvmf_rdma_fill_buffers(). But I found that these
>>> buffers are not 2MB aligned and not IOUnitSize aligned (8KB in my
>>> case) either, instead, they are 64Byte aligned so that some buffers
>>> will fail the checking and leads to this problem.
>>>
>>> The corresponding code snippets are as following:
>>> spdk_nvmf_transport_create()
>>> {
>>> ...
>>>        transport->data_buf_pool =
>>> pdk_mempool_create(spdk_mempool_name,
>>>                                   opts->num_shared_buffers,
>>>                                   opts->io_unit_size +
>>> NVMF_DATA_BUFFER_ALIGNMENT,
>>>                                   SPDK_MEMPOOL_DEFAULT_CACHE_SIZE,
>>>                                   SPDK_ENV_SOCKET_ID_ANY); ...
>>> }
>>>
>>> Also some debug print I added shows the start address of the buffers:
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x200019258800 0(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x2000192557c0 1(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x200019252780 2(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x20001924f740 3(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x20001924c700 4(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x2000192496c0 5(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x200019246680 6(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x200019243640 7(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x200019240600 8(32)
>>> transport.c: 218:spdk_nvmf_transport_poll_group_create: *ERROR*:
>>> 0x20001923d5c0 9(32)
>>> ...
>>>
>>> It looks like either the buffer allocation has alignment issue or the
>>> checking is not correct.
>>>
>>> Please advice how to fix this problem.
>>>
>>> Thanks,
>>> JD Zheng
>>> _______________________________________________
>>> 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
> 

[-- Attachment #2: 16disk_1ns.conf --]
[-- Type: text/plain, Size: 1648 bytes --]

[Global]
  ReactorMask 0xff
  LogFacility "local7"
[Rpc]
  Enable No
  Listen 127.0.0.1
[Nvmf]
  AcceptorPollRate 10000
[Transport]
  Type RDMA
  MaxQueuesPerSession 32
  MaxQueueDepth 256
  InCapsuleDataSize 4096
  MaxIOSize 8192
  IOUnitSize 8192
  AcceptorCore 0
  NumSharedBuffers 512
[Nvme]
  Timeout 0
  AdminPollRate 100000
  TransportId "trtype:PCIe traddr:0000:06:00.0" nvme0
  TransportId "trtype:PCIe traddr:0000:0a:00.0" nvme1
  TransportId "trtype:PCIe traddr:0000:0e:00.0" nvme2
  TransportId "trtype:PCIe traddr:0000:12:00.0" nvme3
  TransportId "trtype:PCIe traddr:0001:05:00.0" nvme4
  TransportId "trtype:PCIe traddr:0001:09:00.0" nvme5
  TransportId "trtype:PCIe traddr:0001:0d:00.0" nvme6
  TransportId "trtype:PCIe traddr:0001:11:00.0" nvme7
  TransportId "trtype:PCIe traddr:0006:04:00.0" nvme8
  TransportId "trtype:PCIe traddr:0006:08:00.0" nvme9
  TransportId "trtype:PCIe traddr:0006:0c:00.0" nvme10
  TransportId "trtype:PCIe traddr:0006:10:00.0" nvme11
  TransportId "trtype:PCIe traddr:0007:03:00.0" nvme12
  TransportId "trtype:PCIe traddr:0007:07:00.0" nvme13
  TransportId "trtype:PCIe traddr:0007:0b:00.0" nvme14
  TransportId "trtype:PCIe traddr:0007:0f:00.0" nvme15
[Subsystem0]
  NQN nqn.2016-06.io.spdk:cnode0
  Listen RDMA 192.168.2.10:4420
  SN SPDK00000000000001
  Namespace nvme0n1
  Namespace nvme4n1
  Namespace nvme8n1
  Namespace nvme12n1
  Namespace nvme1n1
  Namespace nvme5n1
  Namespace nvme9n1
  Namespace nvme13n1
  Namespace nvme2n1
  Namespace nvme6n1
  Namespace nvme10n1
  Namespace nvme14n1
  Namespace nvme3n1
  Namespace nvme7n1
  Namespace nvme11n1
  Namespace nvme15n1
  AllowAnyHost Yes