From mboxrd@z Thu Jan 1 00:00:00 1970 Content-Type: multipart/mixed; boundary="===============4654723902835038166==" 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 11:23:51 -0700 Message-ID: In-Reply-To: EA913ED399BBA34AA4EAC2EDC24CDD00B3150CDA@FMSMSX105.amr.corp.intel.com List-ID: To: spdk@lists.01.org --===============4654723902835038166== Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable 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 -=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[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=3D2816B) 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 =3D 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 allocate= d 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 tha= t 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 a= llocations spanning multiple memory events part of the problem. > Since you are using dpdk 18.11, the memory callback inside of lib/env_dpd= k 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 ; Storage Performance Develop= ment Kit > Subject: Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDM= A Memory Regions > = > Hi JD, > = > Thanks for doing that. Yeah, I am mainly looking to see how the mempool a= ddresses 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 i= ssue 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=E2=80=99t a debug log for it. Can y= ou try it again with this change which adds noticelogs for the relevant reg= istrations. 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 ex= tra bloat in the logs. > = > The underlying assumption of the code is that any given object is not goi= ng to cross a dynamic memory allocation from DPDK. For a little background,= when the mempool gets created, the dpdk code allocates some number of memz= ones to accommodate those buffer objects. Then it passes those memzones dow= n one at a time and places objects inside the mempool from the given memzon= e until the memzone is exhausted. Then it goes back and grabs another memzo= ne. 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 yo= u'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 ; Storage Performance Developme= nt Kit > Subject: Re: [SPDK] nvmf_tgt *ERROR*: Data buffer split over multiple RDM= A 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 fi= le. >> >>> >>> 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 reserv= e 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 STAIL= Q_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 group= ->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 U= nit >>> 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 una= ligned 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 th= ese >>> 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_buffers, >>> =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_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=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 >=20 --===============4654723902835038166== Content-Type: text/plain MIME-Version: 1.0 Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="16disk_1ns.conf" W0dsb2JhbF0KICBSZWFjdG9yTWFzayAweGZmCiAgTG9nRmFjaWxpdHkgImxvY2FsNyIKW1JwY10K ICBFbmFibGUgTm8KICBMaXN0ZW4gMTI3LjAuMC4xCltOdm1mXQogIEFjY2VwdG9yUG9sbFJhdGUg MTAwMDAKW1RyYW5zcG9ydF0KICBUeXBlIFJETUEKICBNYXhRdWV1ZXNQZXJTZXNzaW9uIDMyCiAg TWF4UXVldWVEZXB0aCAyNTYKICBJbkNhcHN1bGVEYXRhU2l6ZSA0MDk2CiAgTWF4SU9TaXplIDgx OTIKICBJT1VuaXRTaXplIDgxOTIKICBBY2NlcHRvckNvcmUgMAogIE51bVNoYXJlZEJ1ZmZlcnMg NTEyCltOdm1lXQogIFRpbWVvdXQgMAogIEFkbWluUG9sbFJhdGUgMTAwMDAwCiAgVHJhbnNwb3J0 SWQgInRydHlwZTpQQ0llIHRyYWRkcjowMDAwOjA2OjAwLjAiIG52bWUwCiAgVHJhbnNwb3J0SWQg InRydHlwZTpQQ0llIHRyYWRkcjowMDAwOjBhOjAwLjAiIG52bWUxCiAgVHJhbnNwb3J0SWQgInRy dHlwZTpQQ0llIHRyYWRkcjowMDAwOjBlOjAwLjAiIG52bWUyCiAgVHJhbnNwb3J0SWQgInRydHlw ZTpQQ0llIHRyYWRkcjowMDAwOjEyOjAwLjAiIG52bWUzCiAgVHJhbnNwb3J0SWQgInRydHlwZTpQ Q0llIHRyYWRkcjowMDAxOjA1OjAwLjAiIG52bWU0CiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0ll IHRyYWRkcjowMDAxOjA5OjAwLjAiIG52bWU1CiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0llIHRy YWRkcjowMDAxOjBkOjAwLjAiIG52bWU2CiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0llIHRyYWRk cjowMDAxOjExOjAwLjAiIG52bWU3CiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0llIHRyYWRkcjow MDA2OjA0OjAwLjAiIG52bWU4CiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0llIHRyYWRkcjowMDA2 OjA4OjAwLjAiIG52bWU5CiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0llIHRyYWRkcjowMDA2OjBj OjAwLjAiIG52bWUxMAogIFRyYW5zcG9ydElkICJ0cnR5cGU6UENJZSB0cmFkZHI6MDAwNjoxMDow MC4wIiBudm1lMTEKICBUcmFuc3BvcnRJZCAidHJ0eXBlOlBDSWUgdHJhZGRyOjAwMDc6MDM6MDAu MCIgbnZtZTEyCiAgVHJhbnNwb3J0SWQgInRydHlwZTpQQ0llIHRyYWRkcjowMDA3OjA3OjAwLjAi IG52bWUxMwogIFRyYW5zcG9ydElkICJ0cnR5cGU6UENJZSB0cmFkZHI6MDAwNzowYjowMC4wIiBu dm1lMTQKICBUcmFuc3BvcnRJZCAidHJ0eXBlOlBDSWUgdHJhZGRyOjAwMDc6MGY6MDAuMCIgbnZt ZTE1CltTdWJzeXN0ZW0wXQogIE5RTiBucW4uMjAxNi0wNi5pby5zcGRrOmNub2RlMAogIExpc3Rl biBSRE1BIDE5Mi4xNjguMi4xMDo0NDIwCiAgU04gU1BESzAwMDAwMDAwMDAwMDAxCiAgTmFtZXNw YWNlIG52bWUwbjEKICBOYW1lc3BhY2UgbnZtZTRuMQogIE5hbWVzcGFjZSBudm1lOG4xCiAgTmFt ZXNwYWNlIG52bWUxMm4xCiAgTmFtZXNwYWNlIG52bWUxbjEKICBOYW1lc3BhY2UgbnZtZTVuMQog IE5hbWVzcGFjZSBudm1lOW4xCiAgTmFtZXNwYWNlIG52bWUxM24xCiAgTmFtZXNwYWNlIG52bWUy bjEKICBOYW1lc3BhY2UgbnZtZTZuMQogIE5hbWVzcGFjZSBudm1lMTBuMQogIE5hbWVzcGFjZSBu dm1lMTRuMQogIE5hbWVzcGFjZSBudm1lM24xCiAgTmFtZXNwYWNlIG52bWU3bjEKICBOYW1lc3Bh Y2UgbnZtZTExbjEKICBOYW1lc3BhY2UgbnZtZTE1bjEKICBBbGxvd0FueUhvc3QgWWVzCg== --===============4654723902835038166==--