While testing a new bdev module with bdevperf, I'm noticing the bdev's module_fini function being called multiple times. The module finish is synchronous and does not call spdk_bdev_module_finish_done(). Tracing the execution of spdk_bdev_module_finish_iter() shows the function working its way backwards through the list of modules until it reaches the first module: spdk_bdev_module_finish_iter:1151 start last(xxxx) spdk_bdev_module_finish_iter:1159 module xxxx(has fini) spdk_bdev_module_finish_iter:1159 module virtio_blk(no fini) spdk_bdev_module_finish_iter:1159 module virtio_scsi(has async fini) spdk_bdev_module_finish_iter:1163 g_resume_bdev_module NULL->virtio_scsi(async_fini) spdk_bdev_module_finish_iter:1155 start resume(aio) spdk_bdev_module_finish_iter:1159 module aio(has fini) spdk_bdev_module_finish_iter:1159 module nvme(has fini) spdk_bdev_module_finish_iter:1159 module null(has async fini) spdk_bdev_module_finish_iter:1163 g_resume_bdev_module virtio_scsi->null(async_fini) spdk_bdev_module_finish_iter:1155 start resume(malloc) spdk_bdev_module_finish_iter:1159 module malloc(no fini) spdk_bdev_module_finish_iter:1159 module lvol(no fini) spdk_bdev_module_finish_iter:1159 module ftl(has async fini) spdk_bdev_module_finish_iter:1163 g_resume_bdev_module null->ftl(async_fini) spdk_bdev_module_finish_iter:1155 start resume(passthru) spdk_bdev_module_finish_iter:1159 module passthru(has fini) spdk_bdev_module_finish_iter:1159 module error(has fini) spdk_bdev_module_finish_iter:1159 module gpt(no fini) spdk_bdev_module_finish_iter:1159 module split(has fini) spdk_bdev_module_finish_iter:1159 module delay(has fini) spdk_bdev_module_finish_iter:1159 module raid(has fini) Note that blank lines in the above trace indicate entry to spdk_bdev_module_finish_iter() and the 'xxxx' is the module under development. After this process finishes, it appears that one of the modules with an asynchronous finish functions kicks off the process again. Stopping in the new .module_fini with gdb shows a backtrace of: Thread 1 "reactor_0" hit Breakpoint 1, bdev_xxxx_finish () at bdev_xxxx.c:524 524 printf("%s: enter\n", __func__); (gdb) bt #0 bdev_xxxx_finish () at bdev_xxxx.c:524 #1 0x00005555555ffd61 in spdk_bdev_module_finish_iter (arg=0x0) at bdev.c:1170 #2 0x00005555555ffde9 in spdk_bdev_module_finish_done () at bdev.c:1191 #3 0x00005555555a304e in bdev_ftl_ftl_module_fini_cb (ctx=0x0, status=0) at bdev_ftl.c:1075 #4 0x00005555555e3aff in ftl_anm_unregister_poller_cb (ctx=0x555557a0c920) at ftl_anm.c:524 #5 0x0000555555612deb in _spdk_msg_queue_run_batch (thread=0x555555df7a10, max_msgs=8) at thread.c:406 #6 0x0000555555613005 in spdk_thread_poll (thread=0x555555df7a10, max_msgs=0, now=8284681201660426) at thread.c:462 #7 0x000055555560d1c9 in _spdk_reactor_run (arg=0x555555df7640) at reactor.c:272 #8 0x000055555560d59d in spdk_reactors_start () at reactor.c:381 #9 0x000055555560bc96 in spdk_app_start (opts=0x7fffffffe260, start_fn=0x555555573b14 <bdevperf_run>, arg1=0x0) at app.c:687 #10 0x0000555555574159 in main (argc=11, argv=0x7fffffffe3f8) at bdevperf.c:1404 Do bdev modules need to handle multiple calls to their .module_fini function or does this behavior indicate a problem in my bdev module? --chuck _______________________________________________ SPDK mailing list SPDK(a)lists.01.org https://lists.01.org/mailman/listinfo/spdk

-----Original Message----- From: SPDK [mailto:spdk-bounces@lists.01.org] On Behalf Of Chuck Tuffli Sent: Monday, August 19, 2019 9:05 AM To: Storage Performance Development Kit <spdk(a)lists.01.org&gt; Subject: Re: [SPDK] .module_fini called twice On Fri, Aug 9, 2019 at 9:53 AM Harris, James R <james.r.harris(a)intel.com&gt; wrote: > > On 8/9/19, 7:57 AM, "SPDK on behalf of Chuck Tuffli" <spdk- bounces(a)lists.01.org on behalf of ctuffli(a)gmail.com&gt; wrote: > > Yep, this was a bug in my code, but I'm curious as to why this breaks > SPDK. Essentially, the new module leveraged code that is itself > multi-threaded and that appears to be confusing/corrupting the SPDK > execution (BTW, having libunwind as an option helped immensely). > Moving the module's cleanup to be asynchronous fixed the double call > to module_fini. I vaguely remember seeing something in the > documentation or comments that suggested sleeping in certain contexts > was 'bad'. Any hypothesis as to what may have gone wrong when mixing > SPDK threads and other POSIX threads? TIA > > Hi Chuck, > > Can you explain more about the bug that was in your code? > Specifically what some of your non-SPDK threads may have been doing > during the context of your synchronous module_fini function. So I spent some time trying to figure out what was happening and now am very confused. While instrumenting spdk_bdev_module_finish_iter(), I noticed something odd, but that oddity remains even without my bdev module. All of this is on master (0c2db7db2). The instrumentation was a handful of printf's in the function (maybe that isn't legal?). They logged: - if processing the module list was starting anew or was being resumed - each module name processed in the while() loop - whether the function exited because it finished the list or hit a module with an async_fini The output for a run with bdevperf is: spdk_bdev_module_finish_iter:1149 start spdk_bdev_module_finish_iter:1158 finish virtio_blk spdk_bdev_module_finish_iter:1158 finish virtio_scsi spdk_bdev_module_finish_iter:1152 resume spdk_bdev_module_finish_iter:1158 finish aio spdk_bdev_module_finish_iter:1158 finish nvme spdk_bdev_module_finish_iter:1158 finish null spdk_bdev_module_finish_iter:1173 exit async spdk_bdev_module_finish_iter:1173 exit async spdk_bdev_module_finish_iter:1152 resume spdk_bdev_module_finish_iter:1158 finish malloc spdk_bdev_module_finish_iter:1158 finish ftl spdk_bdev_module_finish_iter:1173 exit async spdk_bdev_module_finish_iter:1152 resume spdk_bdev_module_finish_iter:1158 finish passthru spdk_bdev_module_finish_iter:1158 finish lvol spdk_bdev_module_finish_iter:1158 finish raid spdk_bdev_module_finish_iter:1158 finish error spdk_bdev_module_finish_iter:1158 finish gpt spdk_bdev_module_finish_iter:1158 finish split spdk_bdev_module_finish_iter:1158 finish delay spdk_bdev_module_finish_iter:1183 exit I expected each start/resume to be followed by some number of 'finish' lines and then one of the 'exit' messages. So having no 'exit' after virtio_scsi and two 'exit async' in a row after null leads me to believe either printf's are a no-no or I'm missing something fundamental. Thoughts? --chuck _______________________________________________ SPDK mailing list SPDK(a)lists.01.org https://lists.01.org/mailman/listinfo/spdk