module unload takes too long

[christophgysin]

$ time sudo rmmod applespi

real    6m40.507s
user    0m0.011s
sys     0m0.013s

$ dmesg
[ 7986.828264] INFO: task rmmod:10565 blocked for more than 120 seconds.
[ 7986.828280]       Tainted: G        W  O    4.11.0-rc7-g4f7d029b9bf0 #1
[ 7986.828285] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 7986.828291] rmmod           D    0 10565  10564 0x00000000
[ 7986.828302] Call Trace:
[ 7986.828324]  __schedule+0x2d3/0x8a0
[ 7986.828337]  ? __slab_alloc.isra.22+0x2b/0x40
[ 7986.828348]  schedule+0x3d/0x90
[ 7986.828356]  schedule_timeout+0x23f/0x3b0
[ 7986.828369]  wait_for_common+0xbe/0x190
[ 7986.828378]  ? wait_for_common+0xbe/0x190
[ 7986.828387]  ? wake_up_q+0x80/0x80
[ 7986.828398]  wait_for_completion+0x1d/0x20
[ 7986.828407]  flush_workqueue+0x14c/0x5a0
[ 7986.828431]  ? applespi_remove+0x40/0x40 [applespi]
[ 7986.828443]  acpi_os_wait_events_complete+0x31/0x40
[ 7986.828453]  ? acpi_os_wait_events_complete+0x31/0x40
[ 7986.828460]  acpi_remove_gpe_handler+0xc7/0x103
[ 7986.828470]  applespi_remove+0x2c/0x40 [applespi]
[ 7986.828481]  spi_drv_remove+0x29/0x50
[ 7986.828491]  device_release_driver_internal+0x155/0x210
[ 7986.828500]  driver_detach+0x3d/0x80
[ 7986.828507]  bus_remove_driver+0x55/0xd0
[ 7986.828514]  driver_unregister+0x2c/0x50
[ 7986.828523]  applespi_driver_exit+0x10/0x18b [applespi]
[ 7986.828533]  SyS_delete_module+0x192/0x260
[ 7986.828542]  ? exit_to_usermode_loop+0x43/0xa0
[ 7986.828551]  entry_SYSCALL_64_fastpath+0x1a/0xa9
[ 7986.828559] RIP: 0033:0x7f8870e379b7
[ 7986.828565] RSP: 002b:00007ffe15e3c628 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[ 7986.828574] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f8870e379b7
[ 7986.828579] RDX: 000000000000000a RSI: 0000000000000800 RDI: 00000000007d5258
[ 7986.828585] RBP: 0000000000000000 R08: 00007ffe15e3b5a1 R09: 000000000000000a
[ 7986.828590] R10: 0000000000000892 R11: 0000000000000206 R12: 00000000007d51f0
[ 7986.828595] R13: 00007ffe15e3b610 R14: 00000000007d51f0 R15: 00000000007d4010

[roadrunner2]

I've noticed that oddly enough this appears to be related to the screen blanking on idle (or something that happens at that time). After boot the unload times are fast, and over time as more screen blanks have occurred it gets longer. Also, I noticed that acpi related wakeups (see powertop) increase significantly after first screen blanking and subsequent wakeup (the acpi interrupt handle goes from < 1/s to 300/s, and the other acpi workers also see significant increases). It looks like acpi is suddenly generating a lot of events (though not keyboard/touchpad events - those continue to only be sent when an actual key press our touch event happens, so these must be other acpi interrupts).

[roadrunner2]

I take it back: this does not appear to be screen-blanking related at all. Instead, it appears to be related to A) something causing massive numbers of acpi interrupt gpe07 triggers (these are what are showing up in powertop, as I mentioned above), and B) how long these interrupts have been going on for. See also the discussion in Dunedan/mbp-2016-linux/issues/6. So fixing those interrupts should fix this issue.

[roadrunner2]

Btw., I traced this to the acpi_remove_gpe_handler() call taking a long time, and that in turn because it ends up calling acpi_os_wait_events_complete() which in turn calls flush_workqueue(kacpid_wq); and that is what's taking an (increasingly) long time - the number of entries in that workqueue increases over time. This appears to be related to the EC issue being discussed.

In short this isn't a bug in this module.

[roadrunner2]

We have a fix for the GPE storm which fixes this issue here. So I think this can be closed.