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: 17509 bytes --]

Hi Seth,

 > Just because a buffer extends past a 2 MiB boundary doesn't mean that 
it exists in two different Memory Regions. It also won't fail the 
translation for being over two memory regions.

This makes sense. However, spdk_mem_map_translate() does following to 
calculate translation_len:

cur_size = VALUE_2MB - _2MB_OFFSET(vaddr);
...
*size = spdk_min(*size, cur_size); // *size is the translation_len from 
caller nvmf_rdma_fill_buffers()

In nvmf_rdma_fill_buffers(),

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

This just checks if buffer sits on 2 2MB pages, not about 2 RDMA memory 
regions. Is my understanding correct?

I still need some time to test. I will update you the result with -s as 
well.

Thanks,
JD


On 8/1/19 1:28 PM, Howell, Seth wrote:
> Hi JD,
> 
> The 2 MiB check is just because we always do memory registrations at at least 2 MiB granularity (the minimum hugepage size). Just because a buffer extends past a 2 MiB boundary doesn't mean that it exists in two different Memory Regions. It also won't fail the translation for being over two memory regions.
> 
> If you look at the definition of spdk_mem_map_translate we call map->ops->are_contiguous every time we cross a 2 MiB boundary. For RDMA, this function is registered to spdk_nvmf_rdma_check_contiguous_entries. IF this function returns true, then even if the buffer crosses a 2 MiB boundary, the translation will still be valid.
> The problem you are running into is not related to the buffer alignment, it is related to the fact that the two pages across which the buffer is split are registered to two different MRs in the NIC. This can only happen if those two pages are allocated independently and trigger two distinct memory event callbacks.
> 
> That is why I am so interested in seeing the results from the noticelog above ibv_reg_mr. It will tell me how your target application is allocating memory. Also, when you start the SPDK target, are you using the -s option? Something like ./app/nvmf_tgt/nvmf_tgt -s 512 or something like that (I don't know if it'll make a difference, it's more of a curiosity thing for me)?
> 
> Thanks,
> 
> Seth
> 
> -----Original Message-----
> From: JD Zheng [mailto:jiandong.zheng(a)broadcom.com]
> Sent: Thursday, August 1, 2019 11:24 AM
> 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,
> 
> 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
>>