From mboxrd@z Thu Jan 1 00:00:00 1970 Content-Type: multipart/mixed; boundary="===============8750961531263299882==" MIME-Version: 1.0 From: JD Zheng Subject: Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDMA Memory Regions Date: Thu, 01 Aug 2019 14:00:31 -0700 Message-ID: <932c163d-7a06-c5fa-7d8d-a5151561337e@broadcom.com> In-Reply-To: EA913ED399BBA34AA4EAC2EDC24CDD00B3150FBD@FMSMSX105.amr.corp.intel.com List-ID: To: spdk@lists.01.org --===============8750961531263299882== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable 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 =3D VALUE_2MB - _2MB_OFFSET(vaddr); ... *size =3D 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 l= east 2 MiB granularity (the minimum hugepage size). Just because a buffer e= xtends past a 2 MiB boundary doesn't mean that it exists in two different M= emory 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 functi= on is registered to spdk_nvmf_rdma_check_contiguous_entries. IF this functi= on returns true, then even if the buffer crosses a 2 MiB boundary, the tran= slation 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 spl= it 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 a= bove 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 ; Storage Performance Developme= nt Kit > Subject: Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDM= A Memory Regions > = > Hi Seth, > = > Thanks for the detailed description, now I understand the reason behind t= he checking. But I have a question, why checking against 2MiB? Is it becaus= e 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 addresse= s 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 -=3D 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[iovcn= t], iovcnt, length, remaining_length, translation_len, rdma_req->req.iov[io= vcnt].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 st= arts with 0x2000193feb00, and when failed, I got following: > = > rdma.c:1510:nvmf_rdma_fill_buffers: *ERROR*: Data buffer split over multi= ple RDMA Memory Regions 0x2000193feb00 0 (8192) (0) (5376) (8192) > = > This buffer has 5376B on one 2MB page and the rest of it > (8192-5376=3D2816B) is on another page. > = > The change https://review.gerrithub.io/c/spdk/spdk/+/463893 to use iov ba= se should make it better as iov base is 4KiB aligned. In above case, iov_ba= se is 0x2000193feb00 & 0xfff =3D 0x2000193fe000 and it should pass the chec= king. > However, another buffer in the pool is 0x2000192010c0 and iov_base is 0x2= 00019201000, which would fail the checking because it is only 4KiB to 2MB b= oundary and IOUnitSize is 8KiB. > = > I will add the change from > https://review.gerrithub.io/c/spdk/spdk/+/463892 and rerun the test to ge= t 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 thi= s 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 Ji= m helped add a flag into DPDK that prevented allocations from being allocat= ed and freed in different granularities. This flag also prevents malloc hea= p allocations from spanning multiple memory events. However, this flag didn= 't make it into DPDK until 19.02 (More documentation at https://doc.dpdk.or= g/guides/prog_guide/env_abstraction_layer.html#environment-abstraction-laye= r if you're interested). We have some code in the SPDK environment layer th= at tries to deal with that (see lib/env_dpdk/memory.c:memory_hotplug_cb) bu= t 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_dp= dk 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 somethin= g 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 ; Storage Performance >> Development Kit >> 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 lo= g. Sorry about that, I forgot there wasn=E2=80=99t a debug log for it. Can = you try it again with this change which adds noticelogs for the relevant re= gistrations. 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 e= xtra bloat in the logs. >> >> The underlying assumption of the code is that any given object is not go= ing to cross a dynamic memory allocation from DPDK. For a little background= , when the mempool gets created, the dpdk code allocates some number of mem= zones to accommodate those buffer objects. Then it passes those memzones do= wn one at a time and places objects inside the mempool from the given memzo= ne until the memzone is exhausted. Then it goes back and grabs another memz= one. This process continues until all objects are accounted for. >> This only works if each memzone corresponds to a single memory event whe= n using dynamic memory allocation. My understanding was that this was alway= s the case, but this error makes me think that it's possible that that's no= t true. >> >> Once I see what your memory registrations look like and what addresses y= ou'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_tg= t 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 ; Storage Performance >> Development Kit >> 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 lik= e: >> 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 f= ile. >>> >>>> >>>> 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 >>> =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 SPDK_NOTICELOG("Unable to res= erve >>> the full number of buffers for the pg buffer cache.\n"); >>> =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 break; >>> =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 } >>> +=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 SPDK_ERRLOG= ("%p %d(%d)\n", buf, >>> group->buf_cache_count, group->buf_cache_size); >>> =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 ST= AILQ_INSERT_HEAD(&group->buf_cache, buf, >>> link); >>> =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 gr= oup->buf_cache_count++; >>> =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0 } >>> >>>> >>>> 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 >>>> 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=C2=A0spdk_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=C2=A0nvmf_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 >>>> Date: =C2=A0 Tue Nov 13 17:43:46 2018 +0100 >>>> >>>> =C2=A0 =C2=A0 =C2=A0 memory: fix contiguous memory calculation for u= naligned >>>> 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=C2=A0nvmf_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() >>>> { >>>> ... >>>> =C2=A0 =C2=A0 =C2=A0 transport->data_buf_pool =3D >>>> pdk_mempool_create(spdk_mempool_name, >>>> =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0opts->num_shared_buffer= s, >>>> =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0opts->io_unit_size + >>>> NVMF_DATA_BUFFER_ALIGNMENT, >>>> =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0SPDK_MEMPOOL_DEFAULT_CA= CHE_SIZE, >>>> =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0SPDK_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 >> --===============8750961531263299882==--