search

alsa-project / alsa-lib

The Advanced Linux Sound Architecture (ALSA) - library
GNU Lesser General Public License v2.1
364 stars 177 forks source link

alsa-lib hangs when mounting a partition while playing a sound file using aplay #321

Open nachopitt opened 1 year ago

nachopitt commented 1 year ago

Hello,

I'm using alsa-lib to add sound playback functionality to a Embedded Linux system.

Recently I noticed that whenever I mount a UBI partition while there is a sound file being played back with the help of the aplay command, the aplay process hangs forever and the sound playback stops immediately.

# aplay -D output1 1.wav &
Playing WAVE '1.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Mono
#
#
# mount -t ubifs /dev/ubi0_5 /opt/conf/Logging
UBIFS (ubi0:5): background thread "ubifs_bgt0_5" started, PID 190
UBIFS (ubi0:5): UBIFS: mounted UBI device 0, volume 5, name "Logging"
UBIFS (ubi0:5): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
UBIFS (ubi0:5): FS size: 1650688 bytes (1 MiB, 13 LEBs), journal size 1142785 bytes (1 MiB, 8 LEBs)
underrun!!! (at least 0.044 ms loUBIFS (ubi0:5): reserved for root: 0 bytes (0 KiB)
ng)
UBIFS (ubi0:5): media format: w4/r0 (latest is w5/r0), UUID 26A3D522-A34F-4FE4-BF6C-931A9FE59854, small LPT model
#

I also prepared a small video that captures the exact moment where the issue is reproduced in case you want it to see it in action:

https://www.youtube.com/watch?v=M9bW2k2CTVs

The only way to recover from this scenario is to kill the stuck aplay process manually and execute it again.

Last time I tried to debug this, I attached the gdbserver to the still stuck aplay process and backtrace showed the following information:

(gdb) bt
arm-linux-gnueabihf-gdb bin/aplay       (wd: ~/home_volume/git_repos/alsa/alsa-install/usr)
(gdb) bt
#0  0x76d96ba4 in ?? ()
**#1  0x76f0e222 in snd1_pcm_wait_nocheck (pcm=0x879280, timeout=-1) at pcm.c:2898**
Backtrace stopped: previous frame inner to this frame (corrupt stack?)
(gdb) frame 1
#1  0x76f0e222 in snd1_pcm_wait_nocheck (pcm=0x879280, timeout=-1) at pcm.c:2898
2898                    err_poll = poll(pfd, npfds, timeout);
(gdb)

It is clear to me that the poll function is waiting for something to change in the file descriptors and it waits infinitely due to the timeout = -1 argument, but none of the file descriptors in pfd ever change or become ready after the mount command is executed during the sound playback.

I'm currently using both alsa-lib and alsa-utils v1.2.6. The SoC is an NXP i.MX6 Solo which includes an Armv7-A 32bits Cortex-A9 Core CPU Platform. Linux Kernel BSP is based on 4.14.98.

Most likely this is an issue with my system configuration, but since you guys are more familiar with alsa than anyone on the planet, I thought you might have some ideas to troubleshoot and debug this because I currently do not have any clue.

Do you know what could cause this behavior? Is there any possibility that there is an issue in alsa-lib? Do you have any suggestions to debug and troubleshoot the error to get more information?

Any help will be really appreciated.

Thanks a lot. Best regards.

perexg commented 1 year ago

It looks like a driver (kernel) issue. The poll() should return with an error. You can also check the stream status in /proc/asound/card0/pcm0p/sub0/* files.

nachopitt commented 1 year ago

Thanks for replying, @perexg .

Unfortunately I do not see anything listed under the /proc/asound/card0/ directory other than the id file:

# ls -lha /proc/asound/card0/
dr-xr-xr-x    2 root     0              0 Jan  1 00:05 .
dr-xr-xr-x    4 root     0              0 Jan  1 00:05 ..
-r--r--r--    1 root     0              0 Jan  1 00:05 id

Am I missing something?

Best regards.

nachopitt commented 1 year ago

Nevermind, it was my fault. I forgot I had to enable some CONFIG_SND* configuration options in in the kernel menuconfig.

So here is the output:

# cat /proc/asound/card0/pcm0p/sub0/status
state: RUNNING
owner_pid   : 152
trigger_time: 2.671492333
tstamp      : 57.520781006
delay       : -2416896
avail       : 2417408
avail_max   : 0
-----
hw_ptr      : 2416896
appl_ptr    : 0

# cat /proc/asound/card0/pcm0p/sub0/sw_params
tstamp_mode: ENABLE
period_step: 1
avail_min: 256
start_threshold: 1
stop_threshold: 1073741824
silence_threshold: 0
silence_size: 1073741824
boundary: 1073741824

At least it mentions that the playback stream status is RUNNING. Besides configuration parameters, the rest of the files didn't offer any other useful information.

Do you have any other idea that may cause this?

Thanks a lot again.

nachopitt commented 1 year ago

More news,

I just took some traces with the help of trace-cmd and here are the results:

# trace-cmd record -e snd_pcm aplay -D output1 1.wav &
# Playing WAVE '1.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Mono
mount -t ubifs /dev/ubi0_5 /opt/conf/Logging/
UBIFS (ubi0:5): background thread "ubifs_bgt0_5" started, PID 214
UBIFS (ubi0:5): UBIFS: mounted UBI device 0, volume 5, name "Logging"
UBIFS (ubi0:5): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
UBIFS (ubi0:5): FS size: 1650688 bytes (1 MiB, 13 LEBs), journal size 1142785 bytes (1 MiB, 8 LEBs)
UBIFS (ubi0:5): reserved for root: 0 bytes (0 KiB)
UBIFS (ubi0:5): media format: w4/r0 (latest is w5/r0), UUID 26A3D522-A34F-4FE4-BF6C-931A9FE59854, small LPT model
underrun!!! (at least 0.046 ms long)
# fg
trace-cmd record -e snd_pcm aplay -D output1 1.wav
^Z[1]+  Stopped                    trace-cmd record -e snd_pcm aplay -D output1 1.wav
# fg
trace-cmd record -e snd_pcm aplay -D output1 1.wav
Aborted by signal Interrupt...
aplay: pcm_write:2127: write error: Interrupted system call
^Clibtracecmd: No such file or directory
  No compression algorithms are supported
CPU0 data recorded at offset=0xce000
    45056 bytes in size
# trace-cmd report
version = 7
cpus=1
           aplay-212   [000]   674.040129: hw_mask_param:        pcmC0D0p:0 000/023 ACCESS 0000000000000000ffffffffffffffff 00000000000000000000000000000009
           aplay-212   [000]   674.040137: hw_mask_param:        pcmC0D0p:0 000/023 SUBFORMAT 0000000000000000ffffffffffffffff 00000000000000000000000000000001
           aplay-212   [000]   674.040140: hw_interval_param:    pcmC0D0p:0 000/023 SAMPLE_BITS 0 0 [0 4294967295] 0 1 [0 4294967295]
           aplay-212   [000]   674.040141: hw_interval_param:    pcmC0D0p:0 000/023 FRAME_BITS 0 0 [0 4294967295] 0 1 [0 4294967295]
           aplay-212   [000]   674.040143: hw_interval_param:    pcmC0D0p:0 000/023 PERIOD_SIZE 0 0 [0 4294967295] 0 1 [0 4294967295]
           aplay-212   [000]   674.040144: hw_interval_param:    pcmC0D0p:0 000/023 PERIOD_BYTES 0 0 [0 4294967295] 0 0 [128 65532]
           aplay-212   [000]   674.040146: hw_interval_param:    pcmC0D0p:0 000/023 PERIODS 0 0 [0 4294967295] 0 1 [2 255]
           aplay-212   [000]   674.040147: hw_interval_param:    pcmC0D0p:0 000/023 BUFFER_SIZE 0 0 [0 4294967295] 0 1 [0 4294967295]
           aplay-212   [000]   674.040149: hw_interval_param:    pcmC0D0p:0 000/023 BUFFER_BYTES 0 0 [0 4294967295] 0 1 [128 65536]
           aplay-212   [000]   674.040154: hw_interval_param:    pcmC0D0p:0 002/023 SAMPLE_BITS 0 1 [0 4294967295] 0 1 [16 16]
           aplay-212   [000]   674.040158: hw_interval_param:    pcmC0D0p:0 004/023 FRAME_BITS 0 1 [0 4294967295] 0 1 [64 64]
           aplay-212   [000]   674.040162: hw_interval_param:    pcmC0D0p:0 011/023 PERIOD_SIZE 0 1 [0 4294967295] 0 1 [0 2147483647]
           aplay-212   [000]   674.040164: hw_interval_param:    pcmC0D0p:0 012/023 PERIOD_SIZE 0 1 [0 2147483647] 0 1 [16 8191]
           aplay-212   [000]   674.040167: hw_interval_param:    pcmC0D0p:0 014/023 BUFFER_SIZE 0 1 [0 4294967295] 0 1 [32 2088705]
           aplay-212   [000]   674.040168: hw_interval_param:    pcmC0D0p:0 015/023 BUFFER_SIZE 0 1 [32 2088705] 0 1 [32 8192]
           aplay-212   [000]   674.040171: hw_interval_param:    pcmC0D0p:0 017/023 PERIOD_BYTES 0 0 [128 65532] 0 0 [128 65528]
           aplay-212   [000]   674.040172: hw_interval_param:    pcmC0D0p:0 018/023 BUFFER_BYTES 0 1 [128 65536] 0 1 [256 65536]
           aplay-212   [000]   674.040174: hw_interval_param:    pcmC0D0p:0 019/023 PERIOD_TIME 0 0 [0 4294967295] 0 0 (362 185737)
           aplay-212   [000]   674.040176: hw_interval_param:    pcmC0D0p:0 020/023 BUFFER_TIME 0 0 [0 4294967295] 0 0 (725 185760)
           aplay-212   [000]   674.040178: hw_interval_param:    pcmC0D0p:0 021/023 PERIOD_SIZE 0 1 [16 8191] 0 1 [16 8190]
           aplay-212   [000]   674.040181: hw_interval_param:    pcmC0D0p:0 023/023 RATE 0 0 [44100 44101) 0 1 [44100 44100]
           aplay-212   [000]   674.040187: hw_interval_param:    pcmC0D0p:0 011/023 PERIOD_SIZE 0 1 [16 8190] 0 1 [16 4096]
           aplay-212   [000]   674.040191: hw_interval_param:    pcmC0D0p:0 017/023 PERIOD_BYTES 0 0 [128 65528] 0 0 [128 32768]
           aplay-212   [000]   674.040193: hw_interval_param:    pcmC0D0p:0 019/023 PERIOD_TIME 0 0 (362 185737) 0 0 (362 92880)
           aplay-212   [000]   674.040246: hw_interval_param:    pcmC0D0p:0 018/023 BUFFER_BYTES 0 1 [256 65536] 0 1 [4096 65536]
           aplay-212   [000]   674.040249: hw_interval_param:    pcmC0D0p:0 020/023 BUFFER_TIME 0 0 (725 185760) 0 0 (11609 185760)
           aplay-212   [000]   674.040261: hw_interval_param:    pcmC0D0p:0 010/023 PERIODS 0 1 [2 255] 0 1 [2 32]
           aplay-212   [000]   674.040263: hw_interval_param:    pcmC0D0p:0 011/023 PERIOD_SIZE 0 1 [16 4096] 0 1 [16 256]
           aplay-212   [000]   674.040265: hw_interval_param:    pcmC0D0p:0 017/023 PERIOD_BYTES 0 0 [128 32768] 0 0 [128 2048]
           aplay-212   [000]   674.040267: hw_interval_param:    pcmC0D0p:0 018/023 BUFFER_BYTES 0 1 [4096 65536] 0 1 [4096 4096]
           aplay-212   [000]   674.040269: hw_interval_param:    pcmC0D0p:0 019/023 PERIOD_TIME 0 0 (362 92880) 0 0 (362 5805)
           aplay-212   [000]   674.040270: hw_interval_param:    pcmC0D0p:0 020/023 BUFFER_TIME 0 0 (11609 185760) 0 0 (11609 11610)
           aplay-212   [000]   674.040291: hw_interval_param:    pcmC0D0p:0 013/023 PERIOD_SIZE 0 1 [16 256] 0 1 [256 256]
           aplay-212   [000]   674.040293: hw_interval_param:    pcmC0D0p:0 017/023 PERIOD_BYTES 0 0 [128 2048] 0 1 [2048 2048]
           aplay-212   [000]   674.040295: hw_interval_param:    pcmC0D0p:0 019/023 PERIOD_TIME 0 0 [5804 5805) 0 0 (5804 5805)
           aplay-212   [000]   674.040299: hw_interval_param:    pcmC0D0p:0 010/023 PERIODS 0 1 [2 32] 0 1 [2 2]
           aplay-212   [000]   674.040337: hw_mask_param:        pcmC0D0p:0 000/023 FORMAT 00000000000000000000000000000004 00000000000000000000000000000004
           aplay-212   [000]   674.040340: hw_interval_param:    pcmC0D0p:0 000/023 CHANNELS 0 1 [4 4] 0 1 [4 4]
           aplay-212   [000]   674.040341: hw_interval_param:    pcmC0D0p:0 000/023 RATE 0 1 [44100 44100] 0 1 [44100 44100]
           aplay-212   [000]   674.040343: hw_interval_param:    pcmC0D0p:0 000/023 PERIOD_TIME 0 0 (5804 5805) 0 0 (5804 5805)
           aplay-212   [000]   674.040344: hw_interval_param:    pcmC0D0p:0 000/023 BUFFER_SIZE 0 1 [512 512] 0 1 [512 512]
           aplay-212   [000]   674.052327: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=0, base=0, period=256, buf=512
           aplay-212   [000]   674.052467: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=0, base=0, period=256, buf=512
           aplay-212   [000]   674.052475: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=0, base=0, period=256, buf=512
           aplay-212   [000]   674.052502: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=0, base=0, period=256, buf=512
           aplay-212   [000]   674.052526: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=0, base=0, period=256, buf=512
          <idle>-0     [000]   674.056893: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=0, base=0, period=256, buf=512
           aplay-212   [000]   674.056924: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=256, base=0, period=256, buf=512
           aplay-212   [000]   674.056936: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=256, base=0, period=256, buf=512
           aplay-212   [000]   674.056946: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=256, base=0, period=256, buf=512
           aplay-212   [000]   674.056961: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=256, base=0, period=256, buf=512
           aplay-212   [000]   674.057033: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=256, base=0, period=256, buf=512
           aplay-212   [000]   674.057040: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=256, base=0, period=256, buf=512
          <idle>-0     [000]   674.062706: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=256, base=0, period=256, buf=512
           aplay-212   [000]   674.062741: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=512, base=512, period=256, buf=512
           aplay-212   [000]   674.062754: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=512, base=512, period=256, buf=512
           aplay-212   [000]   674.062760: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=512, base=512, period=256, buf=512
...
...
...
           aplay-212   [000]   674.603069: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24320, base=24064, period=256, buf=512
           aplay-212   [000]   674.603089: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24320, base=24064, period=256, buf=512
           aplay-212   [000]   674.603198: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24320, base=24064, period=256, buf=512
           aplay-212   [000]   674.603210: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24320, base=24064, period=256, buf=512
          <idle>-0     [000]   674.608800: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=24320, base=24064, period=256, buf=512
           aplay-212   [000]   674.608842: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=24576, base=24576, period=256, buf=512
           aplay-212   [000]   674.608862: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=24576, base=24576, period=256, buf=512
           aplay-212   [000]   674.608873: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=24576, base=24576, period=256, buf=512
           aplay-212   [000]   674.608893: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=24576, base=24576, period=256, buf=512
           aplay-212   [000]   674.608998: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=24576, base=24576, period=256, buf=512
           aplay-212   [000]   674.609012: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=24576, base=24576, period=256, buf=512
           mount-213   [000]   674.614627: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=24576, base=24576, period=256, buf=512
           aplay-212   [000]   674.614749: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24832, base=24576, period=256, buf=512
           aplay-212   [000]   674.614774: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24832, base=24576, period=256, buf=512
           aplay-212   [000]   674.614785: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24832, base=24576, period=256, buf=512
           aplay-212   [000]   674.614813: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24832, base=24576, period=256, buf=512
           aplay-212   [000]   674.614946: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24832, base=24576, period=256, buf=512
           aplay-212   [000]   674.614961: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=24832, base=24576, period=256, buf=512
           mount-213   [000]   674.620436: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=24832, base=24576, period=256, buf=512
           aplay-212   [000]   674.620525: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25088, base=25088, period=256, buf=512
           aplay-212   [000]   674.620551: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25088, base=25088, period=256, buf=512
           aplay-212   [000]   674.620563: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25088, base=25088, period=256, buf=512
           aplay-212   [000]   674.620593: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25088, base=25088, period=256, buf=512
           aplay-212   [000]   674.620734: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25088, base=25088, period=256, buf=512
           aplay-212   [000]   674.620749: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25088, base=25088, period=256, buf=512
    ubifs_bgt0_5-214   [000]   674.626975: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=25088, base=25088, period=256, buf=512
           aplay-212   [000]   674.627062: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25344, base=25088, period=256, buf=512
           aplay-212   [000]   674.627086: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25344, base=25088, period=256, buf=512
           aplay-212   [000]   674.627098: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25344, base=25088, period=256, buf=512
           aplay-212   [000]   674.627123: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25344, base=25088, period=256, buf=512
           aplay-212   [000]   674.627242: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25344, base=25088, period=256, buf=512
           aplay-212   [000]   674.627257: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25344, base=25088, period=256, buf=512
           mount-213   [000]   674.632038: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=25344, base=25088, period=256, buf=512
           aplay-212   [000]   674.632097: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25600, base=25600, period=256, buf=512
           aplay-212   [000]   674.632110: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25600, base=25600, period=256, buf=512
           aplay-212   [000]   674.632117: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25600, base=25600, period=256, buf=512
           aplay-212   [000]   674.632130: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25600, base=25600, period=256, buf=512
           aplay-212   [000]   674.632212: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25600, base=25600, period=256, buf=512
           aplay-212   [000]   674.632220: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=25600, base=25600, period=256, buf=512
          <idle>-0     [000]   674.637849: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=25600, base=25600, period=256, buf=512
           aplay-212   [000]   674.637896: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25856, base=25600, period=256, buf=512
           aplay-212   [000]   674.637909: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25856, base=25600, period=256, buf=512
           aplay-212   [000]   674.637915: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25856, base=25600, period=256, buf=512
           aplay-212   [000]   674.637930: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25856, base=25600, period=256, buf=512
           aplay-212   [000]   674.638026: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25856, base=25600, period=256, buf=512
           aplay-212   [000]   674.638035: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=25856, base=25600, period=256, buf=512
           mount-213   [000]   674.643661: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=25856, base=25600, period=256, buf=512
           aplay-212   [000]   674.643703: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=26112, base=26112, period=256, buf=512
           aplay-212   [000]   674.643716: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=26112, base=26112, period=256, buf=512
           aplay-212   [000]   674.643722: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=26112, base=26112, period=256, buf=512
           aplay-212   [000]   674.643737: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=26112, base=26112, period=256, buf=512
           aplay-212   [000]   674.643827: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=26112, base=26112, period=256, buf=512
           aplay-212   [000]   674.643834: hwptr:                pcmC0D0p/sub0: POS: pos=0, old=26112, base=26112, period=256, buf=512
          <idle>-0     [000]   674.649467: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=26112, base=26112, period=256, buf=512
           aplay-212   [000]   674.649519: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=26368, base=26112, period=256, buf=512
           aplay-212   [000]   674.649531: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=26368, base=26112, period=256, buf=512
           aplay-212   [000]   674.649537: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=26368, base=26112, period=256, buf=512
           aplay-212   [000]   674.649552: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=26368, base=26112, period=256, buf=512
           aplay-212   [000]   674.649634: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=26368, base=26112, period=256, buf=512
           aplay-212   [000]   674.649642: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=26368, base=26112, period=256, buf=512
           mount-213   [000]   674.658118: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=26368, base=26112, period=256, buf=512
           mount-213   [000]   674.666783: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=26624, base=26624, period=256, buf=512
           mount-213   [000]   674.675601: hwptr:                pcmC0D0p/sub0: IRQ: pos=0, old=26880, base=26624, period=256, buf=512
           mount-213   [000]   674.675610: hwptr:                pcmC0D0p/sub0: IRQ: pos=256, old=27136, base=27136, period=256, buf=512
           aplay-212   [000]   674.690216: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512
           aplay-212   [000]   674.690275: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512
           aplay-212   [000]   674.690479: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512
           aplay-212   [000]   674.690607: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512
           aplay-212   [000]   674.690614: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512
           aplay-212   [000]   674.690628: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512
           aplay-212   [000]   674.690641: hwptr:                pcmC0D0p/sub0: POS: pos=256, old=27392, base=27136, period=256, buf=512