tao Posted April 23, 2017 Posted April 23, 2017 I have an orange pi one running armbian 5.25 with a 2.4" ili9341 TF LCD initialized with "modprobe fbtft_device custom name=fb_ili9341 gpios=reset:198,dc:199 speed=16000000 rotate=90 busnum=0". Most of the time, after running a pygame program for about 25 minutes I get the error below. Then, often about 10 minutes after the error message the program freezes. ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred I've seen the same thing happen with several programs. The program below usually creates the error. Running the same program on raspbian generates no errors so I don't think it's the code itself, but something in the environment. Spoiler #TEST PYGAME PROGRAM import pygame, os os.putenv('SDL_VIDEODRIVER','fbcon') os.putenv('SDL_FBDEV','/dev/fb8') pygame.init() pygame.mouse.set_visible(False) clock = pygame.time.Clock() rect_change_x = rect_change_y = 5 rect_x = rect_y = 50 size = [320, 240] screen = pygame.display.set_mode(size) while 1: for event in pygame.event.get(): if event.type == pygame.QUIT: done = True screen.fill((0,0,0)) pygame.draw.rect(screen, (255,255,255), [rect_x, rect_y, 10, 10]) rect_x += rect_change_x rect_y += rect_change_y if rect_y > 240 or rect_y < 0: rect_change_y = rect_change_y * -1 if rect_x > 320 or rect_x < 0: rect_change_x = rect_change_x * -1 clock.tick(60) pygame.display.flip() pygame.quit() Here's dmesg info from the fb modprobe to just after the program freezes Spoiler [ 34.357584] fbtft_device: SPI devices registered: [ 34.357623] fbtft_device: spidev spi0.0 33000kHz 8 bits mode=0x00 [ 34.357644] fbtft_device: 'fb' Platform devices registered: [ 34.357772] fbtft_device: Deleting spi0.0 [ 34.358537] fbtft_device: GPIOS used by 'fb_ili9341': [ 34.358562] fbtft_device: 'reset' = GPIO198 [ 34.358579] fbtft_device: 'dc' = GPIO199 [ 34.358595] fbtft_device: SPI devices registered: [ 34.358618] fbtft_device: fb_ili9341 spi0.0 16000kHz 8 bits mode=0x00 [ 34.688784] graphics fb8: fb_ili9341 frame buffer, 320x240, 150 KiB video memory, 16 KiB buffer memory, fps=20, spi0.0 at 16 MHz [ 46.507506] vmouse_input_dev_open [ 960.460119] INFO: task kworker/u:0:5 blocked for more than 120 seconds. [ 960.460149] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 960.460171] kworker/u:0 D c061e084 0 5 2 0x00000000 [ 960.460253] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 960.460299] [<c061e39c>] (schedule+0x90/0x94) from [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) [ 960.460346] [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) from [<c061d878>] (wait_for_common+0x120/0x168) [ 960.460393] [<c061d878>] (wait_for_common+0x120/0x168) from [<c061d8e0>] (wait_for_completion+0x20/0x24) [ 960.460443] [<c061d8e0>] (wait_for_completion+0x20/0x24) from [<c03e39dc>] (sunxi_spi_work+0x748/0x88c) [ 960.460495] [<c03e39dc>] (sunxi_spi_work+0x748/0x88c) from [<c00445a0>] (process_one_work+0x248/0x404) [ 960.460543] [<c00445a0>] (process_one_work+0x248/0x404) from [<c00459d8>] (worker_thread+0x1b4/0x2d0) [ 960.460592] [<c00459d8>] (worker_thread+0x1b4/0x2d0) from [<c0049cf0>] (kthread+0x94/0xa0) [ 960.460641] [<c0049cf0>] (kthread+0x94/0xa0) from [<c000f1b0>] (kernel_thread_exit+0x0/0x8) [ 960.460680] INFO: task kworker/3:1:27 blocked for more than 120 seconds. [ 960.460700] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 960.460722] kworker/3:1 D c061e084 0 27 2 0x00000000 [ 960.460778] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 960.460822] [<c061e39c>] (schedule+0x90/0x94) from [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) [ 960.460866] [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) from [<c061d878>] (wait_for_common+0x120/0x168) [ 960.460913] [<c061d878>] (wait_for_common+0x120/0x168) from [<c061d8e0>] (wait_for_completion+0x20/0x24) [ 960.460959] [<c061d8e0>] (wait_for_completion+0x20/0x24) from [<c03e0854>] (spi_sync+0x84/0xa0) [ 960.461032] [<c03e0854>] (spi_sync+0x84/0xa0) from [<bf12134c>] (fbtft_write_spi+0xf0/0x104 [fbtft]) [ 960.461166] [<bf12134c>] (fbtft_write_spi+0xf0/0x104 [fbtft]) from [<bf121208>] (fbtft_write_vmem16_bus8+0x11c/0x138 [fbtft]) [ 960.461248] [<bf121208>] (fbtft_write_vmem16_bus8+0x11c/0x138 [fbtft]) from [<bf11e918>] (fbtft_update_display+0x150/0x2fc [fbtft]) [ 960.461324] [<bf11e918>] (fbtft_update_display+0x150/0x2fc [fbtft]) from [<bf11e2a8>] (fbtft_deferred_io+0x110/0x11c [fbtft]) [ 960.461388] [<bf11e2a8>] (fbtft_deferred_io+0x110/0x11c [fbtft]) from [<c0382b98>] (fb_deferred_io_work+0x84/0xcc) [ 960.461438] [<c0382b98>] (fb_deferred_io_work+0x84/0xcc) from [<c00445a0>] (process_one_work+0x248/0x404) [ 960.461483] [<c00445a0>] (process_one_work+0x248/0x404) from [<c00459d8>] (worker_thread+0x1b4/0x2d0) [ 960.461529] [<c00459d8>] (worker_thread+0x1b4/0x2d0) from [<c0049cf0>] (kthread+0x94/0xa0) [ 960.461575] [<c0049cf0>] (kthread+0x94/0xa0) from [<c000f1b0>] (kernel_thread_exit+0x0/0x8) [ 960.461632] INFO: task python:840 blocked for more than 120 seconds. [ 960.461652] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 960.461674] python D c061e084 0 840 831 0x00000000 [ 960.461732] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 960.461777] [<c061e39c>] (schedule+0x90/0x94) from [<c061e78c>] (schedule_preempt_disabled+0x30/0x40) [ 960.461824] [<c061e78c>] (schedule_preempt_disabled+0x30/0x40) from [<c061cf70>] (__mutex_lock_slowpath+0x160/0x1a8) [ 960.461872] [<c061cf70>] (__mutex_lock_slowpath+0x160/0x1a8) from [<c061d01c>] (mutex_lock+0x64/0x7c) [ 960.461917] [<c061d01c>] (mutex_lock+0x64/0x7c) from [<c0382a84>] (fb_deferred_io_mkwrite+0x2c/0xbc) [ 960.461963] [<c0382a84>] (fb_deferred_io_mkwrite+0x2c/0xbc) from [<c00ff630>] (do_wp_page+0x224/0x7a4) [ 960.462008] [<c00ff630>] (do_wp_page+0x224/0x7a4) from [<c0101210>] (handle_pte_fault+0x7b0/0x838) [ 960.462052] [<c0101210>] (handle_pte_fault+0x7b0/0x838) from [<c0101390>] (handle_mm_fault+0xf8/0x134) [ 960.462096] [<c0101390>] (handle_mm_fault+0xf8/0x134) from [<c001b180>] (do_page_fault+0x11c/0x344) [ 960.462140] [<c001b180>] (do_page_fault+0x11c/0x344) from [<c00083a8>] (do_DataAbort+0x44/0xa8) [ 960.462184] [<c00083a8>] (do_DataAbort+0x44/0xa8) from [<c000dcd8>] (__dabt_usr+0x38/0x40) [ 960.462211] Exception stack(0xd4a3dfb0 to 0xd4a3dff8) [ 960.462238] dfa0: b45ba000 016b16c8 00000280 00000000 [ 960.462275] dfc0: 000000f0 016b16a8 b45ba280 00000280 ffffffc0 00000280 be876854 00000000 [ 960.462309] dfe0: b45ba000 be876774 b6a1e52f b6d89398 80000010 ffffffff [ 1080.460137] INFO: task kworker/u:0:5 blocked for more than 120 seconds. [ 1080.460166] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1080.460190] kworker/u:0 D c061e084 0 5 2 0x00000000 [ 1080.460272] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 1080.460318] [<c061e39c>] (schedule+0x90/0x94) from [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) [ 1080.460365] [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) from [<c061d878>] (wait_for_common+0x120/0x168) [ 1080.460413] [<c061d878>] (wait_for_common+0x120/0x168) from [<c061d8e0>] (wait_for_completion+0x20/0x24) [ 1080.460463] [<c061d8e0>] (wait_for_completion+0x20/0x24) from [<c03e39dc>] (sunxi_spi_work+0x748/0x88c) [ 1080.460514] [<c03e39dc>] (sunxi_spi_work+0x748/0x88c) from [<c00445a0>] (process_one_work+0x248/0x404) [ 1080.460562] [<c00445a0>] (process_one_work+0x248/0x404) from [<c00459d8>] (worker_thread+0x1b4/0x2d0) [ 1080.460610] [<c00459d8>] (worker_thread+0x1b4/0x2d0) from [<c0049cf0>] (kthread+0x94/0xa0) [ 1080.460659] [<c0049cf0>] (kthread+0x94/0xa0) from [<c000f1b0>] (kernel_thread_exit+0x0/0x8) [ 1080.460698] INFO: task kworker/3:1:27 blocked for more than 120 seconds. [ 1080.460718] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1080.460739] kworker/3:1 D c061e084 0 27 2 0x00000000 [ 1080.460796] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 1080.460840] [<c061e39c>] (schedule+0x90/0x94) from [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) [ 1080.460885] [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) from [<c061d878>] (wait_for_common+0x120/0x168) [ 1080.460931] [<c061d878>] (wait_for_common+0x120/0x168) from [<c061d8e0>] (wait_for_completion+0x20/0x24) [ 1080.460977] [<c061d8e0>] (wait_for_completion+0x20/0x24) from [<c03e0854>] (spi_sync+0x84/0xa0) [ 1080.461050] [<c03e0854>] (spi_sync+0x84/0xa0) from [<bf12134c>] (fbtft_write_spi+0xf0/0x104 [fbtft]) [ 1080.461136] [<bf12134c>] (fbtft_write_spi+0xf0/0x104 [fbtft]) from [<bf121208>] (fbtft_write_vmem16_bus8+0x11c/0x138 [fbtft]) [ 1080.461216] [<bf121208>] (fbtft_write_vmem16_bus8+0x11c/0x138 [fbtft]) from [<bf11e918>] (fbtft_update_display+0x150/0x2fc [fbtft]) [ 1080.461292] [<bf11e918>] (fbtft_update_display+0x150/0x2fc [fbtft]) from [<bf11e2a8>] (fbtft_deferred_io+0x110/0x11c [fbtft]) [ 1080.461357] [<bf11e2a8>] (fbtft_deferred_io+0x110/0x11c [fbtft]) from [<c0382b98>] (fb_deferred_io_work+0x84/0xcc) [ 1080.461406] [<c0382b98>] (fb_deferred_io_work+0x84/0xcc) from [<c00445a0>] (process_one_work+0x248/0x404) [ 1080.461452] [<c00445a0>] (process_one_work+0x248/0x404) from [<c00459d8>] (worker_thread+0x1b4/0x2d0) [ 1080.461498] [<c00459d8>] (worker_thread+0x1b4/0x2d0) from [<c0049cf0>] (kthread+0x94/0xa0) [ 1080.461544] [<c0049cf0>] (kthread+0x94/0xa0) from [<c000f1b0>] (kernel_thread_exit+0x0/0x8) [ 1080.461601] INFO: task python:840 blocked for more than 120 seconds. [ 1080.461620] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1080.461642] python D c061e084 0 840 831 0x00000000 [ 1080.461699] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 1080.461744] [<c061e39c>] (schedule+0x90/0x94) from [<c061e78c>] (schedule_preempt_disabled+0x30/0x40) [ 1080.461792] [<c061e78c>] (schedule_preempt_disabled+0x30/0x40) from [<c061cf70>] (__mutex_lock_slowpath+0x160/0x1a8) [ 1080.461840] [<c061cf70>] (__mutex_lock_slowpath+0x160/0x1a8) from [<c061d01c>] (mutex_lock+0x64/0x7c) [ 1080.461884] [<c061d01c>] (mutex_lock+0x64/0x7c) from [<c0382a84>] (fb_deferred_io_mkwrite+0x2c/0xbc) [ 1080.461930] [<c0382a84>] (fb_deferred_io_mkwrite+0x2c/0xbc) from [<c00ff630>] (do_wp_page+0x224/0x7a4) [ 1080.461977] [<c00ff630>] (do_wp_page+0x224/0x7a4) from [<c0101210>] (handle_pte_fault+0x7b0/0x838) [ 1080.462021] [<c0101210>] (handle_pte_fault+0x7b0/0x838) from [<c0101390>] (handle_mm_fault+0xf8/0x134) [ 1080.462065] [<c0101390>] (handle_mm_fault+0xf8/0x134) from [<c001b180>] (do_page_fault+0x11c/0x344) [ 1080.462109] [<c001b180>] (do_page_fault+0x11c/0x344) from [<c00083a8>] (do_DataAbort+0x44/0xa8) [ 1080.462152] [<c00083a8>] (do_DataAbort+0x44/0xa8) from [<c000dcd8>] (__dabt_usr+0x38/0x40) [ 1080.462179] Exception stack(0xd4a3dfb0 to 0xd4a3dff8) [ 1080.462206] dfa0: b45ba000 016b16c8 00000280 00000000 [ 1080.462243] dfc0: 000000f0 016b16a8 b45ba280 00000280 ffffffc0 00000280 be876854 00000000 [ 1080.462278] dfe0: b45ba000 be876774 b6a1e52f b6d89398 80000010 ffffffff [ 1200.460115] INFO: task kworker/u:0:5 blocked for more than 120 seconds. [ 1200.460144] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.460167] kworker/u:0 D c061e084 0 5 2 0x00000000 [ 1200.460248] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 1200.460294] [<c061e39c>] (schedule+0x90/0x94) from [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) [ 1200.460340] [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) from [<c061d878>] (wait_for_common+0x120/0x168) [ 1200.460388] [<c061d878>] (wait_for_common+0x120/0x168) from [<c061d8e0>] (wait_for_completion+0x20/0x24) [ 1200.460439] [<c061d8e0>] (wait_for_completion+0x20/0x24) from [<c03e39dc>] (sunxi_spi_work+0x748/0x88c) [ 1200.460490] [<c03e39dc>] (sunxi_spi_work+0x748/0x88c) from [<c00445a0>] (process_one_work+0x248/0x404) [ 1200.460538] [<c00445a0>] (process_one_work+0x248/0x404) from [<c00459d8>] (worker_thread+0x1b4/0x2d0) [ 1200.460586] [<c00459d8>] (worker_thread+0x1b4/0x2d0) from [<c0049cf0>] (kthread+0x94/0xa0) [ 1200.460636] [<c0049cf0>] (kthread+0x94/0xa0) from [<c000f1b0>] (kernel_thread_exit+0x0/0x8) [ 1200.460673] INFO: task kworker/3:1:27 blocked for more than 120 seconds. [ 1200.460693] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.460715] kworker/3:1 D c061e084 0 27 2 0x00000000 [ 1200.460771] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 1200.460851] [<c061e39c>] (schedule+0x90/0x94) from [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) [ 1200.460898] [<c061c2dc>] (schedule_timeout+0x2c/0x2bc) from [<c061d878>] (wait_for_common+0x120/0x168) [ 1200.460944] [<c061d878>] (wait_for_common+0x120/0x168) from [<c061d8e0>] (wait_for_completion+0x20/0x24) [ 1200.460991] [<c061d8e0>] (wait_for_completion+0x20/0x24) from [<c03e0854>] (spi_sync+0x84/0xa0) [ 1200.461062] [<c03e0854>] (spi_sync+0x84/0xa0) from [<bf12134c>] (fbtft_write_spi+0xf0/0x104 [fbtft]) [ 1200.461148] [<bf12134c>] (fbtft_write_spi+0xf0/0x104 [fbtft]) from [<bf121208>] (fbtft_write_vmem16_bus8+0x11c/0x138 [fbtft]) [ 1200.461228] [<bf121208>] (fbtft_write_vmem16_bus8+0x11c/0x138 [fbtft]) from [<bf11e918>] (fbtft_update_display+0x150/0x2fc [fbtft]) [ 1200.461304] [<bf11e918>] (fbtft_update_display+0x150/0x2fc [fbtft]) from [<bf11e2a8>] (fbtft_deferred_io+0x110/0x11c [fbtft]) [ 1200.461368] [<bf11e2a8>] (fbtft_deferred_io+0x110/0x11c [fbtft]) from [<c0382b98>] (fb_deferred_io_work+0x84/0xcc) [ 1200.461417] [<c0382b98>] (fb_deferred_io_work+0x84/0xcc) from [<c00445a0>] (process_one_work+0x248/0x404) [ 1200.461462] [<c00445a0>] (process_one_work+0x248/0x404) from [<c00459d8>] (worker_thread+0x1b4/0x2d0) [ 1200.461508] [<c00459d8>] (worker_thread+0x1b4/0x2d0) from [<c0049cf0>] (kthread+0x94/0xa0) [ 1200.461554] [<c0049cf0>] (kthread+0x94/0xa0) from [<c000f1b0>] (kernel_thread_exit+0x0/0x8) [ 1200.461611] INFO: task python:840 blocked for more than 120 seconds. [ 1200.461631] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.461653] python D c061e084 0 840 831 0x00000000 [ 1200.461710] [<c061e084>] (__schedule+0x574/0x7fc) from [<c061e39c>] (schedule+0x90/0x94) [ 1200.461755] [<c061e39c>] (schedule+0x90/0x94) from [<c061e78c>] (schedule_preempt_disabled+0x30/0x40) [ 1200.461803] [<c061e78c>] (schedule_preempt_disabled+0x30/0x40) from [<c061cf70>] (__mutex_lock_slowpath+0x160/0x1a8) [ 1200.461851] [<c061cf70>] (__mutex_lock_slowpath+0x160/0x1a8) from [<c061d01c>] (mutex_lock+0x64/0x7c) [ 1200.461895] [<c061d01c>] (mutex_lock+0x64/0x7c) from [<c0382a84>] (fb_deferred_io_mkwrite+0x2c/0xbc) [ 1200.461941] [<c0382a84>] (fb_deferred_io_mkwrite+0x2c/0xbc) from [<c00ff630>] (do_wp_page+0x224/0x7a4) [ 1200.461988] [<c00ff630>] (do_wp_page+0x224/0x7a4) from [<c0101210>] (handle_pte_fault+0x7b0/0x838) [ 1200.462032] [<c0101210>] (handle_pte_fault+0x7b0/0x838) from [<c0101390>] (handle_mm_fault+0xf8/0x134) [ 1200.462075] [<c0101390>] (handle_mm_fault+0xf8/0x134) from [<c001b180>] (do_page_fault+0x11c/0x344) [ 1200.462119] [<c001b180>] (do_page_fault+0x11c/0x344) from [<c00083a8>] (do_DataAbort+0x44/0xa8) [ 1200.462163] [<c00083a8>] (do_DataAbort+0x44/0xa8) from [<c000dcd8>] (__dabt_usr+0x38/0x40) [ 1200.462189] Exception stack(0xd4a3dfb0 to 0xd4a3dff8) [ 1200.462216] dfa0: b45ba000 016b16c8 00000280 00000000 [ 1200.462254] dfc0: 000000f0 016b16a8 b45ba280 00000280 ffffffc0 00000280 be876854 00000000 [ 1200.462288] dfe0: b45ba000 be876774 b6a1e52f b6d89398 80000010 ffffffff
tao Posted April 24, 2017 Author Posted April 24, 2017 echo 0 > /proc/sys/kernel/hung_task_timeout_secs reduces the number of log messages, but the program still hangs. Not sure pygame is generating an ALSA error.
tao Posted April 26, 2017 Author Posted April 26, 2017 I might have misrepresented the problem by naming the message printed on the console (ALSA). I suspect the problem might be related to fbftft. Looking at issues such as https://github.com/notro/fbtft/issues/413 If that's the case, it may be hard to fix running with the legacy kernel.
Recommended Posts