BUG: scheduling while atomic: vfdd/2196/0x00000101

[7134956]

Здравствуй, Андрей. Спасибо за драйвер. Пользуюсь подправленной своей версией.
Не часто, но выскакивает предупреждение ядра.
На более старом коде пару раз было это:

[27886.254494] BUG: scheduling while atomic: vfdd/2180/0x00000101
[27886.254684] Modules linked in: fuse ipt_MASQUERADE nf_nat_masquerade_ipv4 8021q garp mrp xt_tcpudp xt_conntrack bridge cpufreq_powersave cpufreq_userspace stp cpufreq_conservative llc iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack bluetooth libcrc32c iptable_mangle iptable_filter ecdh_generic r8188eu(C) meson_dw_hdmi brcmfmac dw_hdmi meson_drm drm_kms_helper brcmutil syscopyarea dwmac_generic sysfillrect realtek sysimgblt cfg80211 fb_sys_fops drm dwmac_meson8b stmmac_platform rfkill stmmac meson_ir rc_core pwm_meson meson_gxbb_wdt meson_rng rng_core drm_panel_orientation_quirks crc32_ce ip_tables x_tables
[27886.310518] CPU: 1 PID: 2180 Comm: vfdd Tainted: G         C       4.16.0-rc4-em95-30075-ga855489d24b1-dirty #60
[27886.320578] Hardware name: Enybox EM95 TV box (DT)
[27886.325322] Call trace:
[27886.327747]  dump_backtrace+0x0/0x1c8
[27886.331361]  show_stack+0x14/0x20
[27886.334639]  dump_stack+0x9c/0xc0
[27886.337917]  __schedule_bug+0x4c/0x70
[27886.341538]  __schedule+0x548/0x5c8
[27886.344987]  schedule+0x38/0xa0
[27886.348092]  schedule_preempt_disabled+0x20/0x38
[27886.352664]  __mutex_lock.isra.0+0x574/0x5b0
[27886.356890]  __mutex_lock_slowpath+0x10/0x18
[27886.361116]  mutex_lock+0x30/0x38
[27886.364395]  vfd_timer_sr+0x80/0xb0
[27886.367844]  call_timer_fn+0x20/0x78
[27886.371379]  expire_timers+0xa4/0xb0
[27886.374916]  run_timer_softirq+0xe8/0x1a0
[27886.378884]  __do_softirq+0x12c/0x230
[27886.382507]  irq_exit+0xbc/0xf0
[27886.385613]  __handle_domain_irq+0x60/0xb8
[27886.389664]  gic_handle_irq+0x58/0xa8
[27886.393287]  el1_irq+0xb0/0x128
[27886.396393]  mutex_lock+0x24/0x38
[27886.399670]  dotled_store+0x170/0x1f8
[27886.403294]  dev_attr_store+0x18/0x28
[27886.406916]  sysfs_kf_write+0x3c/0x50
[27886.410537]  kernfs_fop_write+0x118/0x1e8
[27886.414506]  __vfs_write+0x30/0x150
[27886.417954]  vfs_write+0xa4/0x1b0
[27886.421232]  SyS_write+0x60/0xd8
[27886.424424]  el0_svc_naked+0x30/0x34
[27886.428025] NOHZ: local_softirq_pending 282


[15767.467621] BUG: scheduling while atomic: vfdd/2196/0x00000101
[15767.467814] Modules linked in: ipt_MASQUERADE nf_nat_masquerade_ipv4 fuse 8021q garp mrp xt_tcpudp xt_conntrack bridge stp llc cpufreq_powersave cpufreq_userspace cpufreq_conservative iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_mangle iptable_filter bluetooth ecdh_generic r8188eu(C) meson_dw_hdmi dw_hdmi brcmfmac meson_drm drm_kms_helper syscopyarea sysfillrect brcmutil sysimgblt fb_sys_fops cfg80211 drm dwmac_generic realtek dwmac_meson8b stmmac_platform stmmac rfkill meson_ir rc_core meson_rng drm_panel_orientation_quirks meson_gxbb_wdt pwm_meson rng_core crc32_ce ip_tables x_tables
[15767.523688] CPU: 0 PID: 2196 Comm: vfdd Tainted: G         C       4.16.0-rc5-em95-30341-g8e6a010c3408-dirty #62
[15767.533705] Hardware name: Enybox EM95 TV box (DT)
[15767.538450] Call trace:
[15767.540873]  dump_backtrace+0x0/0x1c8
[15767.544489]  show_stack+0x14/0x20
[15767.547767]  dump_stack+0x9c/0xc0
[15767.551045]  __schedule_bug+0x4c/0x70
[15767.554667]  __schedule+0x548/0x5c8
[15767.558115]  schedule+0x38/0xa0
[15767.561220]  schedule_preempt_disabled+0x20/0x38
[15767.565792]  __mutex_lock.isra.0+0x574/0x5b0
[15767.570018]  __mutex_lock_slowpath+0x10/0x18
[15767.574244]  mutex_lock+0x30/0x38
[15767.577524]  vfd_timer_sr+0x80/0xb0
[15767.580973]  call_timer_fn+0x20/0x78
[15767.584507]  expire_timers+0xa4/0xb0
[15767.588044]  run_timer_softirq+0xe8/0x1a0
[15767.592012]  __do_softirq+0x12c/0x230
[15767.595636]  irq_exit+0xbc/0xf0
[15767.598741]  __handle_domain_irq+0x60/0xb8
[15767.602792]  gic_handle_irq+0x58/0xa8
[15767.606415]  el1_irq+0xb0/0x128
[15767.609521]  dotled_store+0x170/0x1f8
[15767.613144]  dev_attr_store+0x18/0x28
[15767.616766]  sysfs_kf_write+0x3c/0x50
[15767.620387]  kernfs_fop_write+0x118/0x1e8
[15767.624357]  __vfs_write+0x30/0x150
[15767.627805]  vfs_write+0xa4/0x1b0
[15767.631082]  SyS_write+0x60/0xd8
[15767.634274]  el0_svc_naked+0x30/0x34

Мой последний код тут https://github.com/7134956/linux_vfd/commits/master
C ним выскочило это :

[23299.032084] BUG: scheduling while atomic: swapper/3/0/0x00000102
[23299.032489] Modules linked in: fuse ipt_MASQUERADE nf_nat_masquerade_ipv4 8021q garp mrp xt_tcpudp xt_conntrack cpufreq_powersave cpufreq_userspace cpufreq_conservative bridge stp llc iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_mangle iptable_filter bluetooth ecdh_generic brcmfmac brcmutil r8188eu(C) cfg80211 rfkill meson_dw_hdmi dwmac_generic dw_hdmi realtek meson_drm drm_kms_helper meson_rng rng_core syscopyarea sysfillrect meson_ir sysimgblt fb_sys_fops rc_core meson_gxbb_wdt dwmac_meson8b stmmac_platform drm stmmac pwm_meson drm_panel_orientation_quirks crc32_ce ip_tables x_tables
[23299.088315] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G         C       4.16.0-rc6-em95-test #20
[23299.096711] Hardware name: Enybox EM95 TV box (DT)
[23299.101455] Call trace:
[23299.103880]  dump_backtrace+0x0/0x1c8
[23299.107494]  show_stack+0x14/0x20
[23299.110772]  dump_stack+0x9c/0xc0
[23299.114050]  __schedule_bug+0x4c/0x70
[23299.117672]  __schedule+0x548/0x5c8
[23299.121120]  schedule+0x38/0xa0
[23299.124226]  schedule_preempt_disabled+0x20/0x38
[23299.128797]  __mutex_lock.isra.0+0x574/0x5b0
[23299.133023]  __mutex_lock_slowpath+0x10/0x18
[23299.137250]  mutex_lock+0x30/0x38
[23299.140529]  vfd_timer_sr+0x1c4/0x1d8
[23299.144151]  call_timer_fn+0x20/0x78
[23299.147685]  expire_timers+0xa4/0xb0
[23299.151222]  run_timer_softirq+0xe8/0x1a0
[23299.155190]  __do_softirq+0x12c/0x230
[23299.158814]  irq_exit+0xbc/0xf0
[23299.161919]  __handle_domain_irq+0x60/0xb8
[23299.165970]  gic_handle_irq+0x58/0xa8
[23299.169593]  el1_irq+0xb0/0x128
[23299.172699]  arch_cpu_idle+0x10/0x18
[23299.176235]  do_idle+0x130/0x1f0
[23299.179426]  cpu_startup_entry+0x20/0x28
[23299.183309]  secondary_start_kernel+0x180/0x1c0
[23299.187998] ------------[ cut here ]------------
[23299.192451] timer: vfd_timer_sr+0x0/0x1d8 preempt leak: 00000101 -> 00000000
[23299.199389] WARNING: CPU: 3 PID: 0 at kernel/time/timer.c:1333 call_timer_fn+0x70/0x78
[23299.207200] Modules linked in: fuse ipt_MASQUERADE nf_nat_masquerade_ipv4 8021q garp mrp xt_tcpudp xt_conntrack cpufreq_powersave cpufreq_userspace cpufreq_conservative bridge stp llc iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_mangle iptable_filter bluetooth ecdh_generic brcmfmac brcmutil r8188eu(C) cfg80211 rfkill meson_dw_hdmi dwmac_generic dw_hdmi realtek meson_drm drm_kms_helper meson_rng rng_core syscopyarea sysfillrect meson_ir sysimgblt fb_sys_fops rc_core meson_gxbb_wdt dwmac_meson8b stmmac_platform drm stmmac pwm_meson drm_panel_orientation_quirks crc32_ce ip_tables x_tables
[23299.263005] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        WC       4.16.0-rc6-em95-test #20
[23299.271454] Hardware name: Enybox EM95 TV box (DT)
[23299.276199] pstate: 40000005 (nZcv daif -PAN -UAO)
[23299.280944] pc : call_timer_fn+0x70/0x78
[23299.284823] lr : call_timer_fn+0x70/0x78
[23299.288703] sp : ffff00000801bde0
[23299.291981] x29: ffff00000801bde0 x28: 0000000000000020
[23299.297242] x27: ffff000008b36180 x26: ffff80007189b600
[23299.302503] x25: 0000000000000005 x24: 0000000000000101
[23299.307765] x23: dead000000000200 x22: ffff0000086db3e0
[23299.313026] x21: ffff0000086db3e0 x20: 0000000000000101
[23299.318287] x19: ffff80007189b600 x18: ffffffffffffffff
[23299.323548] x17: 0000ffff9e16d198 x16: ffff00000812e4a8
[23299.328809] x15: ffff000008b39b08 x14: ffff000088bcd627
[23299.334071] x13: ffff000008bcd635 x12: ffff000008b39b30
[23299.339332] x11: ffff00000848c1f0 x10: ffff00000801baa0
[23299.344593] x9 : 0000000000000007 x8 : 203e2d2031303130
[23299.349854] x7 : 30303030203a6b61 x6 : 0000000000000129
[23299.355116] x5 : 0000000000000000 x4 : 0000000000000008
[23299.360377] x3 : 0000000000000000 x2 : ffff000008b3c4d8
[23299.365638] x1 : 9a1d3f7a3d8b5300 x0 : 0000000000000000
[23299.370900] Call trace:
[23299.373317]  call_timer_fn+0x70/0x78
[23299.376852]  expire_timers+0xa4/0xb0
[23299.380389]  run_timer_softirq+0xe8/0x1a0
[23299.384357]  __do_softirq+0x12c/0x230
[23299.387981]  irq_exit+0xbc/0xf0
[23299.391086]  __handle_domain_irq+0x60/0xb8
[23299.395137]  gic_handle_irq+0x58/0xa8
[23299.398760]  el1_irq+0xb0/0x128
[23299.401866]  arch_cpu_idle+0x10/0x18
[23299.405402]  do_idle+0x130/0x1f0
[23299.408592]  cpu_startup_entry+0x20/0x28
[23299.412475]  secondary_start_kernel+0x180/0x1c0
[23299.416958] ---[ end trace cfcb1b6bbf437d8b ]---
[65154.553539] BUG: scheduling while atomic: swapper/3/0/0x00000102
[65154.553945] Modules linked in: fuse ipt_MASQUERADE nf_nat_masquerade_ipv4 8021q garp mrp xt_tcpudp xt_conntrack cpufreq_powersave cpufreq_userspace cpufreq_conservative bridge stp llc iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_mangle iptable_filter bluetooth ecdh_generic brcmfmac brcmutil r8188eu(C) cfg80211 rfkill meson_dw_hdmi dwmac_generic dw_hdmi realtek meson_drm drm_kms_helper meson_rng rng_core syscopyarea sysfillrect meson_ir sysimgblt fb_sys_fops rc_core meson_gxbb_wdt dwmac_meson8b stmmac_platform drm stmmac pwm_meson drm_panel_orientation_quirks crc32_ce ip_tables x_tables
[65154.609746] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        WC       4.16.0-rc6-em95-test #20
[65154.618165] Hardware name: Enybox EM95 TV box (DT)
[65154.622908] Call trace:
[65154.625333]  dump_backtrace+0x0/0x1c8
[65154.628947]  show_stack+0x14/0x20
[65154.632226]  dump_stack+0x9c/0xc0
[65154.635503]  __schedule_bug+0x4c/0x70
[65154.639124]  __schedule+0x548/0x5c8
[65154.642573]  schedule+0x38/0xa0
[65154.645679]  schedule_preempt_disabled+0x20/0x38
[65154.650250]  __mutex_lock.isra.0+0x574/0x5b0
[65154.654476]  __mutex_lock_slowpath+0x10/0x18
[65154.658702]  mutex_lock+0x30/0x38
[65154.661982]  vfd_timer_sr+0x1c4/0x1d8
[65154.665603]  call_timer_fn+0x20/0x78
[65154.669138]  expire_timers+0xa4/0xb0
[65154.672675]  run_timer_softirq+0xe8/0x1a0
[65154.676642]  __do_softirq+0x12c/0x230
[65154.680267]  irq_exit+0xbc/0xf0
[65154.683372]  __handle_domain_irq+0x60/0xb8
[65154.687423]  gic_handle_irq+0x58/0xa8
[65154.691046]  el1_irq+0xb0/0x128
[65154.694152]  arch_cpu_idle+0x10/0x18
[65154.697688]  do_idle+0x130/0x1f0
[65154.700879]  cpu_startup_entry+0x20/0x28
[65154.704761]  secondary_start_kernel+0x180/0x1c0

Баг стал проявляться при включении регулятора ondemand 2000 - 500 (Мгц)
Есть ли идеи по решению этой архитектурной проблемы?

[anpaza]

Судя по всему, во время блокировки семафора vfd->lock внутри процедуры dotled_store (которая, в свою очередь, вызывается из-за записи vfdd в "точечные" индикаторы), возникает прерывание по таймеру которое, в свою очередь, вызывает процедуру vfd_timer_sr (которая собственно и обновляет экран 10 раз в секунду). Внутри этой процедуры также блокируется семафор vfd->lock, что и приводит к ошибке (если бы ядро "честно" бы выполнило блокировку, всё бы повисло нафиг).

В целом, как мне кажется "по-быстрому", можно просто убрать mutex_lock(&vfd->lock) и mutex_unlock(&vfd->lock) из функции vfd_timer_sr(). В процедуре прерывания нельзя использовать семафоры.

P.S. Закоммитил 4bda273