dMZX Forums: 3DS: intermittent audio crashes, likely Tremor-related -> MegaZeux Bugs -> Tracker

Games using ogg vorbis music tend to crash MZX after several music changes. I've only encountered this specifically when the current music changes i.e. not with sound effects, though I wouldn't count them out. The crashes disappear when disabling music/samples globally and in builds with vorbis disabled, and I've yet to replicate this crash with mods, rads, or wavs. The number of attempts it takes to cause a crash varies, but it typically happens very quickly while rapidly switching between different oggs.

Info from the crash dumps indicate a function in libctru's synchronization.c being the source of the crash but MZX doesn't use that function directly (and despite fixing some audio lock misuse this issue is unaffected). This needs to be actually debugged when I get a chance.

Finally, when the only 3DS-specific hack in the vorbis loader is commented out (setvbuf), instead of crashing MZX will just hang the system.

Updating status to: Confirmed

This seems to be (at least) three different crashes with various causes.

The first happens in the main thread and can be replicated by loading xx̊y and rapidly entering/leaving the house repeatedly (this loads an OGG and immediately sets MOD_POSITION).

Thread 1 received signal SIGSEGV, Segmentation fault.
0x001c83b4 in res2_inverse ()
(gdb) bt
#0  0x001c83b4 in res2_inverse ()
#1  0x001c8744 in mapping0_inverse ()
#2  0x001c0560 in _fetch_and_process_packet.constprop.10 ()
#3  0x001c2028 in ov_pcm_seek ()
#4  0x0018e4cc in audio_set_module_position (pos=119811)
    at src/audio/audio.c:656
#5  0x0010f8cc in set_counter (mzx_world=0x220c10 <mzx_world>,
    name=0x8007c58 "MOD_POSITION", value=119811, id=5) at src/counter.c:3719
#6  0x001461e0 in run_robot (ctx=ctx@entry=0x817cf50, id=id@entry=5,
    x=<optimized out>, x@entry=7, y=<optimized out>, y@entry=0)
    at src/run_robot.c:1529
#7  0x001221e8 in update_board (ctx=0x817cf50, ctx@entry=0x0)
    at src/game_update_board.c:138
#8  0x00120adc in update_world (ctx=0x0, ctx@entry=0x817cf50,
    is_title=<optimized out>) at src/game_update.c:717
#9  0x001184bc in game_draw (ctx=0x817cf50) at src/game.c:432
#10 game_draw (ctx=0x817cf50) at src/game.c:404
#11 0x00107a10 in core_draw (root=0x800e6f0) at src/core.c:713
#12 core_run (root=root@entry=0x800e6f0) at src/core.c:1014
#13 0x001010c4 in real_main (argc=<optimized out>, argc@entry=1,
    argv=<optimized out>, argv@entry=0x8000000) at src/main.c:303
#14 0x00163bcc in main (argc=1, argv=0x8000000) at arch/3ds/platform.c:149

The second happens in the audio thread and is likely related to an invalid call to ogg_stream_clear performed when ov_raw_seek fails. This is a bug that was fixed in vorbis but seems to not have been ported to tremor.

#0  0x001d00b4 in _free_r ()
#1  0x001caab0 in ogg_stream_clear ()
#2  0x001c0f18 in ov_raw_seek ()
#3  0x00191b7c in vorbis_mix_data (a_src=0x807ace0, buffer=0x8018bc0,
    len=4096) at src/audio/audio_vorbis.c:104
#4  0x0018dfb0 in audio_callback (stream=0x3028ac00, len=4096)
    at src/audio/audio.c:258
#5  0x00166718 in ndsp_callback (dud=<optimized out>) at arch/3ds/audio.c:40

The third happens in the audio thread when an ogg sample ends and its stream is destructed.

#0  0x001d0278 in _free_r ()
#1  0x001c6234 in vorbis_book_clear ()
#2  0x001c3794 in vorbis_info_clear ()
#3  0x001c08fc in ov_clear ()
#4  0x00191b28 in vorbis_destruct (a_src=0x9102fc8)
    at src/audio/audio_vorbis.c:205
#5  0x0018dfc4 in audio_callback (stream=0x3028ac00, len=4096)
    at src/audio/audio.c:263

These crashes still occur when loading the ogg to memory and initializing the ogg with ov_open_callbacks, so the filesystem doesn't seem to be (directly) to blame. However, they became noticeably less frequent. I've had no luck reproducing any of them in the Wii port (which also uses tremor) or with Linux builds configured to use tremor.

I built libvorbis 1.3.7 for the 3DS just to compare. The second and third crashes in the post above appear to be gone entirely.

This crash is reproducible by loading xx̊y and repeatedly leaving and entering the house at the start. Appears to be the same or a similar crash from the fraction of usable backtrace I got.

#0  0x0010f508 in vorbis_book_decodevv_add ()
#1  0x00119cf4 in res2_inverse ()
#2  0x00119b5c in _encodepart ()
#3  0x00000000 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

This crash has happened for me exclusively when destructing the primary stream while playing Bee Simulator 2019 Pro. Either OGG will do it.

#0  0x00108eac in vorbis_synthesis_halfrate_p ()
#1  0x0010152c in _fetch_and_process_packet.constprop.1 ()
#2  0x00101bc8 in ov_read_filter.part ()
#3  0x080fb218 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Note: most OGGs sound broken when played by libvorbis on the 3DS and I don't know why. Notably lol.ogg from Bee Simulator 2019 Pro, which was encoded by Lancer-X with AoTuV at -q-2 something like 14 years ago, plays fine (this is the only one I've found so far that does).

Updating Introduced In Version to: 2.91

Full backtrace for the first libvorbis crash built with -O1 -g.

Thread 1 received signal SIGSEGV, Segmentation fault.
0x00116144 in res2_inverse (vb=0x0, vl=0x8119100, in=0x20,
    nonzero=<optimized out>, ch=2) at res0.c:836
836               if(info->secondstages[partword[l][k]]&(1<<s)){
(gdb) bt full
#0  0x00116144 in res2_inverse (vb=0x0, vl=0x8119100, in=0x20,
    nonzero=<optimized out>, ch=2) at res0.c:836
        partvals = 59
        partwords = 30
        partword = 0x20
        i = 0
        k = 0
        l = <optimized out>
        s = 134680204
        look = 0x8119100
        info = 0x81590e0
        samples_per_partition = <optimized out>
        partitions_per_word = <optimized out>
        max = <optimized out>
        end = <optimized out>
        n = <optimized out>
#1  0x0011666c in mapping0_inverse (vb=0x8070e88, l=0x82104f0)
    at mapping0.c:748
        ch_in_bundle = <optimized out>
        vd = <optimized out>
        vi = 0x80a0868
        ci = 0x8218d30
        b = 0x8043f90
        info = 0x82104f0
        i = 0
        j = <optimized out>
        n = 2048
        pcmbundle = 0x80075b8
        zerobundle = 0x80075b0
        nonzero = <optimized out>
        floormemo = 0x80075a0
#2  0x00106fec in vorbis_synthesis (vb=0x8070e88, vb@entry=0x8070e18,
    op=op@entry=0x8007640) at synthesis.c:87
        vd = <optimized out>
        b = <optimized out>
        vi = <optimized out>
        ci = <optimized out>
        opb = 0x8070e8c
        type = <optimized out>
        mode = <optimized out>
        i = <optimized out>
#3  0x00100c4c in _fetch_and_process_packet (vf=vf@entry=0x8070c38,
    op_in=op_in@entry=0x0, readp=readp@entry=1, spanp=spanp@entry=1)
    at vorbisfile.c:709
        op = {packet = 0x804d286 "▒▒▒\034\037▒\377\037\200", bytes = 332,
          b_o_s = 0, e_o_s = 0, granulepos = -1, packetno = 26}
        op_ptr = 0x8007640
        result = <optimized out>
        granulepos = -1
        hs = 136417876
        og = {header = 0x8070e18 "", header_len = 136416560,
          body = 0x100 <error: Cannot access memory at address 0x100>,
          body_len = 256}
#4  0x00103218 in ov_pcm_seek (vf=0x8070c38, pos=<optimized out>)
    at vorbisfile.c:1768
        target = 768
        samples = 0
        hs = 0
        thisblock = <optimized out>
        lastblock = <optimized out>
        ret = 0
#5  0x001a9d7c in audio_set_module_position (pos=1271811)
    at src/audio/audio.c:658
No locals.
#6  0x00128878 in set_counter (mzx_world=0x2336ec <mzx_world>,
    name=0x8007c20 "MOD_POSITION", value=1271811, id=12) at src/counter.c:3759
        counter_list = 0x233a60 <mzx_world+884>
        fdest = <optimized out>
        cdest = <optimized out>
        next = 0
#7  0x0015e430 in run_robot (ctx=ctx@entry=0x8162d80, id=id@entry=12,
    x=<optimized out>, x@entry=18, y=<optimized out>, y@entry=0)
    at src/run_robot.c:1631
        value = <optimized out>
        dest_string = 0x8118042 "j\fjustentered"
        src_string = 0x81183dd "\006LOCAL"
        src_buffer = "$\000\000_NAME\000\000\000ldB\000\000:5,Facing:1,Frame:2\000U\377\377\000\377UU\000\377U\377\000\377\377U\000\377\377\377\000h`\b\b(`\b\b▒_\b\b▒_\b\bh_\b\b(_\b\b▒^\b\b▒^\b\bh^\b\b(^\b\b▒]\b\b▒]\b\bh]\b\b(]\b\b▒\\\b\b▒\\\b\bh\\\b\b(\\\b\b▒[\b\b▒[\b\b\b;&\b\b▒\000\000ME\000\000▒\026\000\000▒▒\t\b\200▒\t\b@▒\t\b\000▒\t\b▒▒\t\b\200▒\t\b@▒\t\b\000▒\t\b▒▒\t\b\200▒\t\b@▒\t\b\000▒\t\b"...
        dest_buffer = "MOD_POSITION\000\000homeworldB.ogg*\000\000\000\000▒\000\b▒\025#\000\030\036#\000\000\060▒\037\004\000\000\000▒q\033\000h\b\n\b▒\025#\000\030\036#\000\000\060▒\037\000\000\000\000▒q\033\000@t\004\b▒\025#\000\210\025#\000\000\060▒\037\000\000\000\000▒q\033\000\000▒\000\b▒\025#\000\000\000\000\000▒▒\035\000▒6#\000\060v\031\b▒6#\000\064▒\027\000\000\000\000\000INE_ROBOTS\000\000e1.pal\000\b\a\000\000\000ؔ\033\000\060▒'\000\005\000\000\000\005\000\000\000\020}\000\b\004\000\000\000ؔ\033\000\v\000\000\000▒▒'\000\000\000"...
        mzx_world = <optimized out>
        src_board = 0x0
        cur_robot = 0x828dd30
        cmd = <optimized out>
        lines_run = <optimized out>
        gotoed = 0
        old_pos = 135893416
        last_label = 134249504
        _bl = {1, 0, 1, 0}
        program = 0x8263ae0 "\b;&\b\b▒"
        cmd_ptr = 0x8118040 "\377\016j\fjustentered"
        done = 0 '\000'
        update_blocked = 208 '▒'
        first_cmd = <optimized out>
        level_id = <optimized out>
        level_param = <optimized out>
        level_color = <optimized out>
        level_under_id = <optimized out>
        board_width = <optimized out>
        board_height = <optimized out>
#8  0x00139058 in update_board (ctx=0x8162d80, ctx@entry=0x0)
    at src/game_update_board.c:138
        mzx_world = 0x2336ec <mzx_world>
        i = <optimized out>
        x = <optimized out>
        y = 0
        level_offset = 18
        src_board = <optimized out>
        cur_robot = <optimized out>
        level_id = <optimized out>
        level_param = <optimized out>
        level_color = <optimized out>
        level_under_id = <optimized out>
        level_under_color = <optimized out>
        board_width = <optimized out>
        board_height = <optimized out>
        slow_down = <optimized out>
        current_id = <optimized out>
        current_param = 12 '\f'
        current_color = <optimized out>
        current_under_id = <optimized out>
        update_done = <optimized out>
#9  0x0013794c in update_world (ctx=0x0, ctx@entry=0x8162d80,
    is_title=<optimized out>) at src/game_update.c:723
        mzx_world = 0x2336ec <mzx_world>
#10 0x0012ed64 in game_draw (ctx=0x8162d80) at src/game.c:457
        game = 0x8162d80
        conf = 0x2353a8 <user_conf>
        mzx_world = 0x2336ec <mzx_world>
#11 0x00120294 in core_draw (root=0x8015e10) at src/core.c:717
        ctx = <optimized out>
        ctx_data = 0x804b968
        ret = 0 '\000'
        sub_data = <optimized out>
        sub = <optimized out>
        ctx = <optimized out>
        ctx_data = <optimized out>
        sub_data = <optimized out>
        sub = <optimized out>
        ret = <optimized out>
#12 core_run (root=root@entry=0x8015e10) at src/core.c:1052
        conf = 0x8162d80
        ctx = <optimized out>
        initial_stack_size = 0
        start_ticks = 134250408
        delta_ticks = <optimized out>
        total_ticks = <optimized out>
        need_update_screen = <optimized out>
#13 0x00118ecc in real_main (argc=<optimized out>, argc@entry=1,
    argv=<optimized out>, argv@entry=0x8000000) at src/main.c:315
        _backup_argv = {0x21b0dc "/3ds/megazeux/megazeux"}
        err = 1
        core_data = 0x8015e10
        conf = <optimized out>
        mzx_world = {active = 1,
          name = "~0@f xx~4y ", '\000' <repeats 13 times>, version = 603,
          status_counters_shown = {'\000' <repeats 14 times>,
            '\000' <repeats 14 times>, '\000' <repeats 14 times>,
            '\000' <repeats 14 times>, '\000' <repeats 14 times>,
            '\000' <repeats 14 times>}, keys = '\177' <repeats 16 times>,
          blind_dur = 0, firewalker_dur = 0, freeze_time_dur = 0,
          slow_time_dur = 0, wind_dur = 0, pl_saved_x = {0, 0, 0, 0, 0, 0, 0,
            0}, pl_saved_y = {0, 0, 0, 0, 0, 0, 0, 0}, pl_saved_board = {0,
            0, 0, 0, 0, 0, 0, 0}, saved_pl_color = 27, under_player_id = 0,
          under_player_color = 7, under_player_param = 0, mesg_edges = 1,
          scroll_base_color = 143, scroll_corner_color = 135,
          scroll_pointer_color = 128, scroll_title_color = 143,
          scroll_arrow_color = 142,
          real_mod_playing = "xxydata/m/xxy-homeworldB.ogg", '\000' <repeats 483 times>, max_samples = -1, smzx_message = 1, edge_color = 0,
          first_board = 3, endgame_board = 255, death_board = 255,
          endgame_x = 0, endgame_y = 0, game_over_sfx = 1, death_x = 0,
          death_y = 0, starting_lives = 7, lives_limit = 99,
          starting_health = 100, health_limit = 200, enemy_hurt_enemy = 0,
          clear_on_exit = 0, only_from_swap = 0, counter_list = {
            num_counters = 797, num_counters_allocated = 1024,
            counters = 0x82529b8, hash_table = 0x8103590}, string_list = {
            num_strings = 5835, num_strings_allocated = 8192,
            strings = 0x82435b8, hash_table = 0x819aab0},
          player_restart_x = 0, player_restart_y = 0, num_sprites = 256,
          num_sprites_allocated = 0, sprite_num = 0, sprite_list = 0x808a418,
          active_sprites = 2, sprite_y_order = 0, collision_count = 0,
          collision_list = 0x82071b0, multiplier = 10000, divider = 10000,
          c_divisions = 360, fread_delimiter = 0, fwrite_delimiter = 0,
          bi_shoot_status = 1, bi_mesg_status = 0,
          output_file_name = "\000ontinue\000ettings", '\000' <repeats 495 times>, output_file = 0x0,
          input_file_name = "\000ontinue\000ettings\000ion", '\000' <repeats 491 times>, input_file = 0x0, input_is_dir = 0 '\000', input_directory = {
            path = "xxydata/t\000it", '\000' <repeats 499 times>,
            opaque = 0x0, entries = 0, pos = 0}, temp_input_pos = 0,
          temp_output_pos = 0, commands = 10000000, commands_stop = 2000000,
          vlayer_size = 10240, vlayer_width = 160, vlayer_height = 64,
          vlayer_chars = 0x80efa90 "",
          vlayer_colors = 0x81cbc58 '\b' <repeats 200 times>...,
          num_boards = 73, num_boards_allocated = 73, board_list = 0x81ce460,
          current_board = 0x8197630, current_board_id = 45,
          temporary_board = 0, global_robot = {world_version = 603,
            program_source_length = 0, program_source = 0x0,
            program_bytecode_length = 8047,
            program_bytecode = 0x81d0530 "\377\rj\vjustloaded",
            robot_name = "loader\000\000\000\000\000\000\000\000",
            robot_char = 2 '\002', cur_prog_line = 0, pos_within_line = 0,
            robot_cycle = 0, cycle_count = 0, bullet_type = 1 '\001',
            is_locked = 0 '\000', can_lavawalk = 0 '\000',
            can_goopwalk = 0 '\000', walk_dir = IDLE, last_touch_dir = IDLE,
            last_shot_dir = IDLE, xpos = -1, ypos = -1, compat_xpos = -1,
            compat_ypos = -1, status = 2 '\002', used = 1 '\001',
            loop_count = 25, num_labels = 29, label_list = 0x81d2640,
            stack_size = 4, stack_pointer = 0, stack = 0x804ba48, local = {
              793, 788, 1, 0, 77, 0 <repeats 26 times>, 38}},
          custom_sfx_on = 0, custom_sfx = '\000' <repeats 3449 times>,
          player_x = 0, player_y = 0, player_shoot_cooldown = 0,
          target_where = TARGET_NONE, target_board = 45, target_x = 0,
          target_y = 0, target_id = SPACE, target_color = 0,
          target_d_id = SPACE, target_d_color = 0, bomb_type = 1,
          dead = 0 '\000', current_cycle_frozen = 0 '\000',
          current_cycle_odd = 1 '\001', player_moved = 1 '\001',
          player_was_on_entrance = 0 '\000', was_zapped = 0 '\000',
          key_up_delay = 0, key_down_delay = 0, key_right_delay = 0,
          key_left_delay = 0, first_prefix = 0, mid_prefix = 0,
          last_prefix = 0, special_counter_return = FOPEN_NONE,
          robotic_save_type = SAVE_NONE,
          robotic_save_path = '\000' <repeats 511 times>,
          change_game_state = CHANGE_STATE_NONE, mzx_speed = 3,
          lock_speed = 1, joystick_simulate_keys = 1 '\001',
          editing = 0 '\000', debug_mode = 0 '\000', raw_world_info = 0x0,
          raw_world_info_size = 0, help_file = 0x0,
          update_done = 0x80267e0 "", update_done_size = 10000}
#14 0x0017f43c in main (argc=1, argv=0x8000000) at arch/3ds/platform.c:149
        _argv0 = "/3ds/megazeux/mzxrun.3dsx"
        _argv = {0x230594 <_argv0.18835> "/3ds/megazeux/mzxrun.3dsx"}

Full backtrace for the second libvorbis crash (-O1 -g).

Thread 2 received signal SIGSEGV, Segmentation fault.
[Switching to Thread 267]
0x00107244 in vorbis_synthesis_halfrate_p (vi=0x804a5b0) at synthesis.c:178
178       return ci->halfrate_flag;
(gdb) bt full
#0  0x00107244 in vorbis_synthesis_halfrate_p (vi=0x804a5b0)
    at synthesis.c:178
        ci = 0x0
#1  0x00100bcc in _fetch_and_process_packet (vf=vf@entry=0x8088130,
    op_in=op_in@entry=0x0, readp=readp@entry=1, spanp=spanp@entry=1)
    at vorbisfile.c:696
        hs = <optimized out>
        og = {header = 0x8042680 "OggS", header_len = 113,
          body = 0x80426f1 "▒mz▒▒e▒▒-3▒▒[9▒▒F▒▒sp=▒▒+▒\200▒▒\004\001|▒▒",
          body_len = 4118}
#2  0x00103cfc in ov_read_filter (vf=vf@entry=0x8088130,
    buffer=buffer@entry=0x8089b60 "▒▒▒▒▒▒▒\024", length=length@entry=744,
    bigendianp=bigendianp@entry=0, word=2, word@entry=1024, sgned=1,
    sgned@entry=1758232, bitstream=0x8025b3c, bitstream@entry=0x2,
    filter=filter@entry=0x0, filter_param=filter_param@entry=0x0)
    at vorbisfile.c:1977
        ret = <optimized out>
        i = <optimized out>
        j = <optimized out>
        hs = <optimized out>
        pcm = 0x8047aa0
        samples = <optimized out>
#3  0x00104150 in ov_read (vf=vf@entry=0x8088130,
    buffer=buffer@entry=0x8089b60 "▒▒▒▒▒▒▒\024", length=length@entry=744,
    bigendianp=bigendianp@entry=0, word=word@entry=2, sgned=sgned@entry=1,
    bitstream=bitstream@entry=0x8025b3c) at vorbisfile.c:2099
No locals.
#4  0x001ad418 in vorbis_mix_data (a_src=0x80880a0, buffer=0x80164e8,
    len=4096) at src/audio/audio_vorbis.c:85
        read_len = 0
        v_stream = 0x80880a0
        read_wanted = 744
        pos = 2928
        read_buffer = 0x8089b60 "▒▒▒▒▒▒▒\024"
        current_section = 0
#5  0x001a9860 in audio_callback (stream=0x30289c00, len=4096)
    at src/audio/audio.c:260
        next_astream = 0x0
        destroy_flag = <optimized out>
        current_astream = 0x80880a0
#6  0x00181f60 in ndsp_callback (dud=<optimized out>) at arch/3ds/audio.c:40
No locals.
#7  0x001b9b04 in ndspThreadMain (arg=<optimized out>)
    at /home/davem/projects/devkitpro/pacman-packages/libctru/src/libctru-2.0.0/libctru/source/ndsp/ndsp.c:435
No locals.
#8  0x001b7eb8 in _thread_begin (arg=<optimized out>)
    at /home/davem/projects/devkitpro/pacman-packages/libctru/src/libctru-2.0.0/libctru/source/thread.c:37
        t = <optimized out>
        tv = <optimized out>
#9  0x00000000 in ?? ()
No symbol table info available.
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Updating status to: Awaiting Feedback
Issue fixed in: 2.92f

All 5 crashes here appear to have been fixed by GIT b2e66818. The problem was the 3DS implementation of platform_mutex_lock was using the non-blocking libctru function LightLock_TryLock instead of the blocking version LightLock_Lock. This fix probably needs to be verified by more thorough testing than what I've done, though (particularly the second tremor crash, which has been verified to be a real upstream tremor bug that hasn't been fixed but doesn't happen anymore when I test for it).