On Thu, Oct 28, 2021 at 08:57:31PM +0800, Ming Lei wrote: > Hello, > > The 1st patch moves module_put() to release handler of klp_patch > kobject. > > The 2nd patch changes to free klp_patch and other kobjects without > klp_mutex. > > The 3rd patch switches to synchronous kobject release for klp_patch. > Hi Ming, I gave the patchset a spin on top of linus tree @ 1fc596a56b33 and ended up with a stuck task: Test ---- Enable the livepatch selftests: $ grep CONFIG_TEST_LIVEPATCH .config CONFIG_TEST_LIVEPATCH=m Run a continuous kernel build in the background: $ while (true); do make clean && make -j$(nproc); done While continuously executing the selftests: $ while (true); do make -C tools/testing/selftests/livepatch/ run_tests; done Results ------- ... [ 366.862278] ===== TEST: multiple target modules ===== [ 366.877470] % modprobe test_klp_callbacks_busy block_transition=N [ 366.890468] test_klp_callbacks_busy: test_klp_callbacks_busy_init [ 366.897280] test_klp_callbacks_busy: busymod_work_func enter [ 366.903602] test_klp_callbacks_busy: busymod_work_func exit [ 366.920311] % modprobe test_klp_callbacks_demo [ 366.931737] livepatch: enabling patch 'test_klp_callbacks_demo' [ 366.938466] test_klp_callbacks_demo: pre_patch_callback: vmlinux [ 366.945173] test_klp_callbacks_demo: pre_patch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state [ 366.959322] livepatch: 'test_klp_callbacks_demo': starting patching transition [ 369.699278] test_klp_callbacks_demo: post_patch_callback: vmlinux [ 369.706118] test_klp_callbacks_demo: post_patch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state [ 369.718079] livepatch: 'test_klp_callbacks_demo': patching complete [ 369.786485] % modprobe test_klp_callbacks_mod [ 369.806918] livepatch: applying patch 'test_klp_callbacks_demo' to loading module 'test_klp_callbacks_mod' [ 369.818005] test_klp_callbacks_demo: pre_patch_callback: test_klp_callbacks_mod -> [MODULE_STATE_COMING] Full formed, running module_init [ 369.831826] test_klp_callbacks_demo: post_patch_callback: test_klp_callbacks_mod -> [MODULE_STATE_COMING] Full formed, running module_init [ 369.846259] test_klp_callbacks_mod: test_klp_callbacks_mod_init [ 369.865115] % rmmod test_klp_callbacks_mod [ 369.881713] test_klp_callbacks_mod: test_klp_callbacks_mod_exit [ 369.888790] test_klp_callbacks_demo: pre_unpatch_callback: test_klp_callbacks_mod -> [MODULE_STATE_GOING] Going away [ 369.900583] livepatch: reverting patch 'test_klp_callbacks_demo' on unloading module 'test_klp_callbacks_mod' [ 369.911696] test_klp_callbacks_demo: post_unpatch_callback: test_klp_callbacks_mod -> [MODULE_STATE_GOING] Going away [ 369.946082] % echo 0 > /sys/kernel/livepatch/test_klp_callbacks_demo/enabled [ 369.954544] test_klp_callbacks_demo: pre_unpatch_callback: vmlinux [ 369.962117] test_klp_callbacks_demo: pre_unpatch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state [ 369.974099] livepatch: 'test_klp_callbacks_demo': starting unpatching transition [ 370.022730] test_klp_callbacks_demo: post_unpatch_callback: vmlinux [ 370.029763] test_klp_callbacks_demo: post_unpatch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state [ 370.042065] livepatch: 'test_klp_callbacks_demo': unpatching complete [ 494.498310] INFO: task test-callbacks.:10039 blocked for more than 122 seconds. [ 494.506489] Tainted: G K 5.15.0-rc7+ #2 [ 494.512834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 494.521601] task:test-callbacks. state:D stack: 0 pid:10039 ppid: 10036 flags:0x00004000 [ 494.530958] Call Trace: [ 494.533706] __schedule+0x200/0x540 [ 494.537628] schedule+0x44/0xa0 [ 494.541161] __kernfs_remove.part.0+0x21e/0x2a0 [ 494.546251] ? do_wait_intr_irq+0xa0/0xa0 [ 494.550761] kernfs_remove_by_name_ns+0x50/0x90 [ 494.555852] remove_files+0x2b/0x60 [ 494.559783] sysfs_remove_group+0x38/0x80 [ 494.564300] sysfs_remove_groups+0x29/0x40 [ 494.568908] __kobject_del+0x1b/0x80 [ 494.572933] kobject_cleanup+0x9c/0x130 [ 494.577251] enabled_store+0xdc/0x1a0 [ 494.581379] kernfs_fop_write_iter+0x11c/0x1b0 [ 494.586374] new_sync_write+0x11f/0x1b0 [ 494.590690] ? msr_build_context.constprop.0+0x5d/0xbe [ 494.596462] vfs_write+0x1ce/0x260 [ 494.600291] ksys_write+0x5f/0xe0 [ 494.604024] do_syscall_64+0x3b/0x90 [ 494.608049] entry_SYSCALL_64_after_hwframe+0x44/0xae [ 494.613719] RIP: 0033:0x7f66cd5aea37 [ 494.617733] RSP: 002b:00007ffe6a5e16c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 [ 494.626209] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f66cd5aea37 [ 494.634196] RDX: 0000000000000002 RSI: 0000562e8101ba60 RDI: 0000000000000001 [ 494.642177] RBP: 0000562e8101ba60 R08: 0000000000000000 R09: 00007f66cd6634e0 [ 494.650166] R10: 00007f66cd6633e0 R11: 0000000000000246 R12: 0000000000000002 [ 494.658156] R13: 00007f66cd6a85a0 R14: 0000000000000002 R15: 00007f66cd6a87a0 ... [ 1600.420533] INFO: task test-callbacks.:10039 blocked for more than 1228 seconds. Let me know if you have any questions about the tests. If you look at the "^%" prefixed kernel messages in the above log, you can get a rough idea of the commands that the test ran. Regards, -- Joe
