Skip to content
This repository has been archived by the owner on Dec 2, 2022. It is now read-only.

BUG: scheduling while atomic #12

Open
Tert-butyllithium opened this issue May 3, 2021 · 2 comments
Open

BUG: scheduling while atomic #12

Tert-butyllithium opened this issue May 3, 2021 · 2 comments
Assignees
@Tert-butyllithium
Labels
bug Something isn't working

Comments

@Tert-butyllithium
Copy link
Owner 

[ 1294.089988] DEBUG_LOCKS_WARN_ON(val > preempt_count())
[ 1294.090033] WARNING: CPU: 0 PID: 497 at kernel/sched/core.c:4212 preempt_count_sub+0x80/0xc8
[ 1294.090043] Modules linked in: my_sysdig(O) aes_neon_blk crypto_simd cryptd rfcomm fuse bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc vc4 cec drm_kms_helper brcmfmac brcmutil drm drm_panel_orientation_quirks sha256_generic snd_soc_core snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops backlight cfg80211 rfkill raspberrypi_hwmon bcm2835_isp(C) bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem snd_bcm2835(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 snd_pcm videobuf2_common snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio sg i2c_dev ip_tables x_tables ipv6
[ 1294.090272] CPU: 0 PID: 497 Comm: nginx Tainted: G        WC O      5.10.11-v8+ #1399
[ 1294.090278] Hardware name: Raspberry Pi 3 Model B Plus Rev 1.3 (DT)
[ 1294.090288] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO BTYPE=--)
[ 1294.090297] pc : preempt_count_sub+0x80/0xc8
[ 1294.090304] lr : preempt_count_sub+0x80/0xc8
[ 1294.090310] sp : ffffffc011c3bb20
[ 1294.090316] x29: ffffffc011c3bb20 x28: ffffff800bae0000
[ 1294.090329] x27: 0000000000000000 x26: 0000000000000000
[ 1294.090341] x25: 0000000000000000 x24: 0000000000000017
[ 1294.090352] x23: 0000000000000017 x22: ffffffc00910bd20
[ 1294.090364] x21: ffffffc011c3bba8 x20: ffffffc009101c00
[ 1294.090376] x19: ffffffc011228948 x18: 0000000000000010
[ 1294.090388] x17: 0000000000000000 x16: 0000000000000000
[ 1294.090400] x15: ffffffffffffffff x14: ffffffc011228948
[ 1294.090412] x13: ffffffc091c3b757 x12: ffffffc0112b5320
[ 1294.090423] x11: 0000000000000003 x10: ffffffc01129d2e0
[ 1294.090436] x9 : ffffffc0100e6530 x8 : 0000000000017fe8
[ 1294.090447] x7 : c0000000ffffefff x6 : ffffffc011c3b780
[ 1294.090460] x5 : 0000000000000001 x4 : 0000000000000000
[ 1294.090471] x3 : 0000000000000001 x2 : 0000000000000000
[ 1294.090483] x1 : bdcdb908d4bfd800 x0 : 0000000000000000
[ 1294.090497] Call trace:
[ 1294.090505]  preempt_count_sub+0x80/0xc8
[ 1294.090519]  _raw_spin_unlock+0x24/0x48
[ 1294.090535]  syscall_exit_probe+0x194/0x278 [my_sysdig]
[ 1294.090547]  syscall_trace_exit+0x178/0x210
[ 1294.090558]  el0_svc_common.constprop.2+0xd0/0x1d0
[ 1294.090567]  do_el0_svc+0x2c/0x98
[ 1294.090575]  el0_svc+0x20/0x30
[ 1294.090582]  el0_sync_handler+0x90/0xb8
[ 1294.090590]  el0_sync+0x174/0x180
[ 1294.090598] ---[ end trace 2f17136ad184fdb8 ]---
[ 1294.090814] BUG: scheduling while atomic: nginx/497/0xffffffff
[ 1294.090826] Modules linked in: my_sysdig(O) aes_neon_blk crypto_simd cryptd rfcomm fuse bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc vc4 cec drm_kms_helper brcmfmac brcmutil drm drm_panel_orientation_quirks sha256_generic snd_soc_core snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops backlight cfg80211 rfkill raspberrypi_hwmon bcm2835_isp(C) bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem snd_bcm2835(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 snd_pcm videobuf2_common snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio sg i2c_dev ip_tables x_tables ipv6
[ 1294.091029] Preemption disabled at:
[ 1294.091043] [<ffffffc0090fc758>] syscall_exit_probe+0x150/0x278 [my_sysdig]
[ 1294.091057] CPU: 0 PID: 497 Comm: nginx Tainted: G        WC O      5.10.11-v8+ #1399
[ 1294.091063] Hardware name: Raspberry Pi 3 Model B Plus Rev 1.3 (DT)
[ 1294.091070] Call trace:
[ 1294.091082]  dump_backtrace+0x0/0x1b8
[ 1294.091091]  show_stack+0x20/0x70
[ 1294.091101]  dump_stack+0xf0/0x158
[ 1294.091111]  __schedule_bug+0xb0/0xc0
[ 1294.091119]  __schedule+0x774/0x818
[ 1294.091126]  schedule+0x48/0x100
[ 1294.091135]  do_notify_resume+0x90/0x6c0
[ 1294.091142]  work_pending+0xc/0x3a4
[ 1305.080635] BUG: scheduling while atomic: nginx/497/0x00000003
[ 1305.080661] Modules linked in: my_sysdig(O) aes_neon_blk crypto_simd cryptd rfcomm fuse bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc vc4 cec drm_kms_helper brcmfmac brcmutil drm drm_panel_orientation_quirks sha256_generic snd_soc_core snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops backlight cfg80211 rfkill raspberrypi_hwmon bcm2835_isp(C) bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem snd_bcm2835(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 snd_pcm videobuf2_common snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio sg i2c_dev ip_tables x_tables ipv6
[ 1305.081090] Preemption disabled at:
[ 1305.081108] [<ffffffc0108e84d0>] release_sock+0x28/0x98
[ 1305.081127] CPU: 2 PID: 497 Comm: nginx Tainted: G        WC O      5.10.11-v8+ #1399
[ 1305.081134] Hardware name: Raspberry Pi 3 Model B Plus Rev 1.3 (DT)
[ 1305.081140] Call trace:
[ 1305.081153]  dump_backtrace+0x0/0x1b8
[ 1305.081162]  show_stack+0x20/0x70
[ 1305.081172]  dump_stack+0xf0/0x158
[ 1305.081181]  __schedule_bug+0xb0/0xc0
[ 1305.081190]  __schedule+0x774/0x818
[ 1305.081197]  schedule+0x48/0x100
[ 1305.081205]  io_schedule+0x24/0xb0
[ 1305.081213]  bit_wait_io+0x20/0x68
[ 1305.081220]  __wait_on_bit+0x80/0xf8
[ 1305.081228]  out_of_line_wait_on_bit+0x9c/0xc0
[ 1305.081237]  __wait_on_buffer+0x38/0x48
[ 1305.081248]  ext4_block_write_begin+0x438/0x5a0
[ 1305.081257]  ext4_da_write_begin+0x174/0x3d0
[ 1305.081266]  generic_perform_write+0xfc/0x1b0
[ 1305.081274]  ext4_buffered_write_iter+0xa4/0x188
[ 1305.081281]  ext4_file_write_iter+0x60/0x7a8
[ 1305.081291]  __kernel_write+0x10c/0x2a0
[ 1305.081300]  kernel_write+0x74/0x228
[ 1305.081315]  file_write+0x60/0xc0 [my_sysdig]
[ 1305.081325]  syscall_exit_probe+0x1b4/0x278 [my_sysdig]
[ 1305.081334]  syscall_trace_exit+0x178/0x210
[ 1305.081344]  el0_svc_common.constprop.2+0xd0/0x1d0
[ 1305.081353]  do_el0_svc+0x2c/0x98
[ 1305.081360]  el0_svc+0x20/0x30
[ 1305.081368]  el0_sync_handler+0x90/0xb8
[ 1305.081375]  el0_sync+0x174/0x180

and finally... crash?

[ 1468.794240] BUG: scheduling while atomic: nginx/495/0x00000003
[ 1468.794301] Modules linked in: my_sysdig(O) aes_neon_blk crypto_simd cryptd rfcomm fuse bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc vc4 cec drm_kms_helper brcmfmac brcmutil drm drm_panel_orientation_quirks sha256_generic snd_soc_core snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt fb_sys_fops backlight cfg80211 rfkill raspberrypi_hwmon bcm2835_isp(C) bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem snd_bcm2835(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 snd_pcm videobuf2_common snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio sg i2c_dev ip_tables x_tables ipv6 [last unloaded: my_sysdig]
[ 1468.794734] Preemption disabled at:
[ 1468.794753] [<ffffffc010326744>] do_epoll_ctl+0x85c/0xaa0
[ 1468.794772] CPU: 0 PID: 495 Comm: nginx Tainted: G        WC O      5.10.11-v8+ #1399
[ 1468.794779] Hardware name: Raspberry Pi 3 Model B Plus Rev 1.3 (DT)
[ 1468.794785] Call trace:
[ 1468.794797]  dump_backtrace+0x0/0x1b8
[ 1468.794806]  show_stack+0x20/0x70
[ 1468.794817]  dump_stack+0xf0/0x158
[ 1468.794826]  __schedule_bug+0xb0/0xc0
[ 1468.794834]  __schedule+0x774/0x818
[ 1468.794842]  schedule+0x48/0x100
[ 1468.794849]  io_schedule+0x24/0xb0
[ 1468.794857]  bit_wait_io+0x20/0x68
[ 1468.794865]  __wait_on_bit_lock+0x88/0x1a0
[ 1468.794873]  out_of_line_wait_on_bit_lock+0x9c/0xc0
[ 1468.794882]  __lock_buffer+0x30/0x68
[ 1468.794892]  do_get_write_access+0x98/0x4a0
[ 1468.794900]  jbd2_journal_get_write_access+0x68/0xc0
[ 1468.794910]  __ext4_journal_get_write_access+0x7c/0x138
[ 1468.794920]  ext4_reserve_inode_write+0xa0/0xf0
[ 1468.794929]  __ext4_mark_inode_dirty+0x7c/0x2b8
[ 1468.794937]  ext4_dirty_inode+0x8c/0xb8
[ 1468.794946]  __mark_inode_dirty+0x1e8/0x4c8
[ 1468.794954]  generic_update_time+0x88/0xf0
[ 1468.794961]  update_time+0x34/0x40
[ 1468.794969]  file_update_time+0xe0/0x120
[ 1468.794976]  file_modified+0x34/0x48
[ 1468.794984]  ext4_buffered_write_iter+0x6c/0x188
[ 1468.794991]  ext4_file_write_iter+0x60/0x7a8
[ 1468.795002]  __kernel_write+0x10c/0x2a0
[ 1468.795011]  kernel_write+0x74/0x228
[ 1468.795026]  file_write+0x60/0xc0 [my_sysdig]
[ 1468.795036]  syscall_exit_probe+0x1b4/0x278 [my_sysdig]
[ 1468.795045]  syscall_trace_exit+0x178/0x210
[ 1468.795055]  el0_svc_common.constprop.2+0xd0/0x1d0
[ 1468.795064]  do_el0_svc+0x2c/0x98
[ 1468.795071]  el0_svc+0x20/0x30
[ 1468.795078]  el0_sync_handler+0x90/0xb8
[ 1468.795086]  el0_sync+0x174/0x180
[ 1489.798283] rcu: INFO: rcu_preempt self-detected stall on CPU
[ 1489.798311] rcu: 	3-....: (5226 ticks this GP) idle=752/1/0x4000000000000002 softirq=123479/123490 fqs=2286
[ 1489.798320] 	(t=5250 jiffies g=142949 q=2753)
[ 1489.798327] Task dump for CPU 0:
[ 1489.798335] task:nginx           state:R  running task     stack:    0 pid:  494 ppid:   493 flags:0x0000040a
[ 1489.798352] Call trace:
[ 1489.798368]  __switch_to+0x110/0x168
[ 1489.798376]  0xffffffc01232bba8
[ 1489.798382] Task dump for CPU 3:
[ 1489.798388] task:nginx           state:R  running task     stack:    0 pid:  497 ppid:   493 flags:0x00000402
[ 1489.798401] Call trace:
[ 1489.798411]  dump_backtrace+0x0/0x1b8
[ 1489.798420]  show_stack+0x20/0x70
[ 1489.798429]  sched_show_task+0x16c/0x190
[ 1489.798439]  dump_cpu_task+0x4c/0x5c
[ 1489.798447]  rcu_dump_cpu_stacks+0xb8/0xf8
[ 1489.798457]  rcu_sched_clock_irq+0x9d0/0xce8
[ 1489.798466]  update_process_times+0x68/0xe0
[ 1489.798475]  tick_sched_handle.isra.19+0x48/0x60
[ 1489.798482]  tick_sched_timer+0x60/0xb8
[ 1489.798490]  __hrtimer_run_queues+0x11c/0x470
[ 1489.798498]  hrtimer_interrupt+0xfc/0x258
[ 1489.798509]  arch_timer_handler_phys+0x38/0x48
[ 1489.798519]  handle_percpu_devid_irq+0xa8/0x2a0
[ 1489.798527]  generic_handle_irq+0x38/0x50
[ 1489.798534]  __handle_domain_irq+0x9c/0x110
[ 1489.798542]  bcm2836_arm_irqchip_handle_irq+0x6c/0x80
[ 1489.798550]  el1_irq+0xc4/0x180
[ 1489.798559]  queued_spin_lock_slowpath+0x1f0/0x400
[ 1489.798568]  _raw_spin_lock+0x74/0x78
[ 1489.798583]  syscall_exit_probe+0x150/0x278 [my_sysdig]
[ 1489.798592]  syscall_trace_exit+0x178/0x210
[ 1489.798602]  el0_svc_common.constprop.2+0xd0/0x1d0
[ 1489.798611]  do_el0_svc+0x2c/0x98
[ 1489.798618]  el0_svc+0x20/0x30
[ 1489.798625]  el0_sync_handler+0x90/0xb8
[ 1489.798633]  el0_sync+0x174/0x180
@Tert-butyllithium Tert-butyllithium added the bug Something isn't working label May 3, 2021
@Tert-butyllithium Tert-butyllithium self-assigned this May 3, 2021
@Tert-butyllithium
Copy link
Owner Author

We found that this issue is because of writing to file during syscall writev...
Issue #9 with the same reason

@Tert-butyllithium
Copy link
Owner Author

Tert-butyllithium commented May 3, 2021 •
edited
Loading

Known syscalls induce this bug: (looks like all I/O related... syscalls)

  • open ralated
  • close realted
  • write realted

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@Tert-butyllithium Tert-butyllithium

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@Tert-butyllithium