Input/output error while playing a file using aplay

Input/output error while playing a file using aplay

[Pharaoh .]

Hi

I am testing my audio driver using aplay. I trying to play an audio file using:

#aplay -Dplughw:0,0 --rate=44100 --format=S16 --channels=2 test.wav
 The log is as follows,

snd_card_omap_alsa_open start
snd_card_omap_alsa_open end
Playing WAVE 'test.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
snd_omap_alsa_hw_params start
snd_omap_alsa_prepare start
snd_omap_alsa_prepare end
snd_omap_alsa_trigger start
audio_start_dma_chain start
audio_start_dma_chain end
omap_start_alsa_sound_dma end
snd_omap_alsa_trigger end
snd_omap_alsa_pointer start
audio_get_dma_pos start
audio_get_dma_pos end

It waits here for sometime and then I get
snd_omap_alsa_trigger starte error: Input/output error

Then the things are wound up as:

audio_stop_dma start
omap_stop_alsa_sound_dma start
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end

snd_omap_alsa_hw_free start
snd_omap_alsa_hw_free end
snd_card_omap_alsa_close start
snd_card_omap_alsa_close end


So basically the problem is in trigger where it waits for something
and then winds up things. Any idea, what could be the reason. I am
thinking it has to do something with
DMA interrupts etc.

Re: Input/output error while playing a file using aplay

[Pharaoh .]

>So basically the problem is in trigger where it waits for something
>and then winds up things

It is not a problem with trigger, Strace revealed that this is an
ioctl error and after that the aplay pcm write fails. I do not get the
DMA interrupts which I should be getting.

Here is the entire log:

execve("/usr/local/bin/aplay", ["aplay", "-Dplughw:0,0",
"--rate=44100", "--format=S16", "--channels=2", "startup.wav"], [/* 7
vars */]) = 0
uname({sys="Linux", node="192.168.200.214", ...}) = 0
brk(0)                                  = 0x20000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=12436, ...}) = 0
mmap2(NULL, 12436, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40015000
close(3)                                = 0
open("/usr/local/lib/libasound.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\314\353\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0775, st_size=2164893, ...}) = 0
mmap2(NULL, 777620, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x4001e000
mprotect(0x400d0000, 48532, PROT_NONE)  = 0
mmap2(0x400d8000, 16384, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xb2) = 0x400d8000
close(3)                                = 0
open("/lib/libm.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\00003\0\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=778699, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40019000
mmap2(NULL, 713068, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x400dc000
mprotect(0x40182000, 33132, PROT_NONE)  = 0
mmap2(0x40189000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa5) = 0x40189000
close(3)                                = 0
open("/lib/libdl.so.2", O_RDONLY)       = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\344\v\0\000"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=16868, ...}) = 0
mmap2(NULL, 41152, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x4018b000
mprotect(0x4018d000, 32960, PROT_NONE)  = 0
mmap2(0x40194000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1) = 0x40194000
close(3)                                = 0
open("/lib/libpthread.so.0", O_RDONLY)  = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0p?\0\0004"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=99172, ...}) = 0
mmap2(NULL, 367928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x40196000
mprotect(0x401a5000, 306488, PROT_NONE) = 0
mmap2(0x401ac000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xe) = 0x401ac000
mmap2(0x401ae000, 269624, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x401ae000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0HM\1\0004"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=1424946, ...}) = 0
mmap2(NULL, 1132932, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0x401f0000
mprotect(0x402f7000, 55684, PROT_NONE)  = 0
mmap2(0x402ff000, 16384, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x107) = 0x402ff000
mmap2(0x40303000, 6532, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40303000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x4001a000
mprotect(0x402ff000, 8192, PROT_READ)   = 0
mprotect(0x401ac000, 4096, PROT_READ)   = 0
mprotect(0x40194000, 4096, PROT_READ)   = 0
mprotect(0x40189000, 4096, PROT_READ)   = 0
mprotect(0x4001c000, 4096, PROT_READ)   = 0
munmap(0x40015000, 12436)               = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
setrlimit(RLIMIT_STACK, {rlim_cur=2044*1024, rlim_max=RLIM_INFINITY}) = 0
getpid()                                = 586
rt_sigaction(SIGRTMIN, {0x4019e980, [], 0x4000000 /* SA_??? */}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x4019ea3c, [RTMIN], 0x4000000 /* SA_??? */},
NULL, 8) = 0
rt_sigaction(SIGRT_2, {0x4019eba8, [], 0x4000000 /* SA_??? */}, NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RTMIN], NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RT_1], NULL, 8) = 0
_sysctl({{CTL_KERN, KERN_VERSION}, 2, 0xbe863ad8, 40, (nil), 0}) = 0
brk(0)                                  = 0x20000
brk(0x41000)                            = 0x41000
stat64("/usr/local/share/alsa/alsa.conf", {st_mode=S_IFREG|0664,
st_size=7764, ...}) = 0
open("/usr/local/share/alsa/alsa.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0664, st_size=7764, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40015000
read(3, "#\n#  ALSA library configuration "..., 4096) = 4096
read(3, "cards.pcm.surround40\npcm.surroun"..., 4096) = 3668
read(3, "", 4096)                       = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x40015000, 4096)                = 0
access("/etc/asound.conf", R_OK)        = 0
open("/etc/asound.conf", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0664, st_size=690, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40015000
read(3, "pcm.headset {\n\t@args [BDADDR TIM"..., 4096) = 690
read(3, "", 4096)                       = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x40015000, 4096)                = 0
access("//.asoundrc", R_OK)             = -1 ENOENT (No such file or directory)
open("/dev/snd/controlC0", O_RDONLY)    = 3
close(3)                                = 0
open("/dev/snd/controlC0", O_RDWR)      = 3
ioctl(3, USBDEVFS_CONTROL, 0xbe863874)  = 0
ioctl(3, 0x4snd_card_omap_alsa_open start
eac->base = c4954000        = 0

open("/dev/snd/pcmC0D0p", O_RDWBefore audio init
R|O_NONBLOCKomap850_audio_init start
eac->base = c4954000
CSMI: csmi_ctl_snd_res failed
CSMI: csmi_ctl_snd failed
eac_enable_clocks start
Clocks are already enabled
omap850_audio_init end
omap850_audio_init failed
after audio init
snd_card_omap_alsa_open end
) = 4
close(3)                                = 0
ioctl(4, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbe863778) = 0
fcntl64(4, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
ioctl(4, AGPIOC_INFO, 0xbe8636f0)       = 0
ioctl(4, AGPIOC_RELEASE or APM_IOC_SUSPEND, 0xbe8636ec) = 0
mmap2(NULL, 4096, PROT_READ, MAP_SHARED, 4, 0x80000) = -1 ENXIO (No
such device or address)
ioctl(4, 0xc0844123, 0xbe8636f4)        = 0
fcntl64(4, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl64(4, F_SETFL, O_RDWR)             = 0
ioctl(4, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbe863ccc) = 0
rt_sigaction(SIGINT, {0x401a28ac, [INT], SA_RESTART|0x4000000},
{SIG_DFL}, 8) = 0
rt_sigaction(SIGTERM, {0x401a28ac, [TERM], SA_RESTART|0x4000000},
{SIG_DFL}, 8) = 0
rt_sigaction(SIGABRT, {0x401a28ac, [ABRT], SA_RESTART|0x4000000},
{SIG_DFL}, 8) = 0
open("startup.wav", O_RDONLY|O_LARGEFILE) = 3
read(3, "RIFF(\310\24\0WAVEfmt \20\0\0\0\1\0\2\0", 24) = 24
read(3, "D\254\0\0", 4)                 = 4
read(3, "\20\261\2\0\4\0\20\0", 8)      = 8
read(3, "data\4\310\24\0", 8)           = 8
write(2, "Playing WAVE \'startup.wav\' : ", 29Playing WAVE
'startup.wav' : ) = 29
write(2, "Signed 16 bit Little Endian, ", 29Signed 16 bit Little Endian, ) = 29
write(2, "Rate 44100 Hz, ", 15Rate 44100 Hz, )         = 15
write(2, "Stereo", 6Stereo)                   = 6
write(2, "\n", 1
)                       = 1
ioctl(4, 0xc25c4110, 0xbe8635f4)        = 0
ioctl(4, 0xc25c4110, 0xbe8632e8)        = 0
ioctl(4, 0xc25c4110, 0xbe8632e8)        = 0
ioctl(4, 0xc25c4110, 0xbe8635f4)        = 0
ioctl(4, 0xc25c4110, 0xbe8632e8)        = 0
ioctl(4, 0xc25c4110, 0xbe8632e8)        = 0
ioctl(4, 0xc25c4110, 0xbe8635f4)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(snd_omap_alsa_hw_params start
4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xcsnd_omap_alsa_prepare start
snd_omap_alsa_prepare end   = 0

ioctl(4, 0xc25c4110, 0xbe86305cSNDRV_PCM_IOCTL1_RESET
)        = 0
ioctl(4, 0xc25c411Inside snd_pcm_lib_ioctl_reset
0, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe86305c)        = 0
ioctl(4, 0xc25c4110, 0xbe863368)        = 0
ioctl(4, 0xc25c4110, 0xbe862e6c)        = 0
ioctl(4, 0xc25c4110, 0xbe862b60)        = 0
ioctl(4, 0xc25c4110, 0xbe862b60)        = 0
ioctl(4, 0xc25c4110, 0xbe862e6c)        = 0
ioctl(4, 0xc25c4110, 0xbe862b60)        = 0
ioctl(4, 0xc25c4110, 0xbe862b60)        = 0
ioctl(4, 0xc25c4110, 0xbe862e6c)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe8630d4)        = 0
ioctl(4, 0xc25c4110, 0xbe863564)        = 0
ioctl(4, 0xc25c4110, 0xbe863564)        = 0
ioctl(4, 0xc25c4110, 0xbe863564)        = 0
ioctl(4, 0xc25c4110, 0xbe863564)        = 0
ioctl(4, 0xc25c4110, 0xbe863564)        = 0
ioctl(4, 0xc25c4110, 0xbe863904)        = 0
ioctl(4, 0xc25c4111, 0xbe863904)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
ioctl(4, 0xc0684113, 0xbe8634c4)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
ioctl(4, 0x4140, 0x400c3ed4)            = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
ioctl(4, 0xc0684113, 0xbe863898)        = 0
read(3, "\377\377\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\1"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\377\377\0\0\1\0\0\0\0\0\0\0\377\377\376\377\0\0\3\0\377"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\374\377\7\0\0\0\0\0\372\377\0\0\376\377\3\0\3\0\373\377"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\373\377\1\0\377\377\5\0\376\377\372\377\377\377\7\0\6"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\212\377{\377\212\377\210\377\220\377\226\377\214\377\213"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, ".\324\326\3438\323Q\343\375\322\34\343\254\323\223\343"...,
8192Inside snd_pcm_do_start
snd_omap_alsa_trigger start
audio_start_dma_chain start
Inside omap_start_dma 1
Inside omap_start_dma 2
Inside omap_start_dma 3
audio_start_dma_chain end
snd_omap_alsa_trigger end
) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           =Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
Count is 34
 Offset is 4294967288 and buffer size is 16384
Inside snd_pcm_update_hw_ptr_pos, pos is 0
 0
read(3, "\2\fK\0x\v\220\375\361\n_\373\246\n\270\371\235\n;\371"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\336\327R\357\277\330\361\357\256\331\211\360d\332(\361"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "H\343#\355\233\342\317\355\377\341\312\356\216\341\250"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbe863bf0)        = -1 EIO (Input/output error)
write(2, "aplay: pcm_write:1268: ", 23aplay: pcm_write:1268: ) = 23
write(2Inside snd_pcm_do_stop
snd_omap_alsa_trigger start
audio_stop_dma start
before writing to EAC_AGCTR = 60
aftere writing to EAC_AGCTR = 60
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end
, "write error: Input/output errsnd_omap_alsa_hw_free start
or", 31write error: Input/outputsnd_omap_alsa_hw_free end
 error) = 31
write(2, "\n", 1
snd_card_omap_alsa_close start
)                       = 1
io_omap850_audio_shutdown start
submit(0x1, 0, 0x4eac_disable_clocks start
eac_disable_clocks end
CSMI: csmi_ctl_snd_res failed
CSMI: csmi_ctl_snd failed
omap850_audio_shutdown end
snd_card_omap_alsa_close end
 <unfinished ... exit status 1>
Process 586 detached

On 6/23/07, Pharaoh . <pharaoh137@gmail.com> wrote:
> Hi
>
> I am testing my audio driver using aplay. I trying to play an audio file
> using:
>
> #aplay -Dplughw:0,0 --rate=44100 --format=S16 --channels=2 test.wav
>  The log is as follows,
>
> snd_card_omap_alsa_open start
> snd_card_omap_alsa_open end
> Playing WAVE 'test.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
> snd_omap_alsa_hw_params start
> snd_omap_alsa_prepare start
> snd_omap_alsa_prepare end
> snd_omap_alsa_trigger start
> audio_start_dma_chain start
> audio_start_dma_chain end
> omap_start_alsa_sound_dma end
> snd_omap_alsa_trigger end
> snd_omap_alsa_pointer start
> audio_get_dma_pos start
> audio_get_dma_pos end
>
> It waits here for sometime and then I get
> snd_omap_alsa_trigger starte error: Input/output error
>
> Then the things are wound up as:
>
> audio_stop_dma start
> omap_stop_alsa_sound_dma start
> omap_stop_alsa_sound_dma end
> omap_clear_alsa_sound_dma start
> omap_clear_alsa_sound_dma end
> snd_omap_alsa_trigger end
>
> snd_omap_alsa_hw_free start
> snd_omap_alsa_hw_free end
> snd_card_omap_alsa_close start
> snd_card_omap_alsa_close end
>
>
> So basically the problem is in trigger where it waits for something
> and then winds up things. Any idea, what could be the reason. I am
> thinking it has to do something with
> DMA interrupts etc.
>

Re: Input/output error while playing a file using aplay

[Clemens Ladisch]

Pharaoh . wrote:
> ...
> It waits here for sometime and then I get
> snd_omap_alsa_trigger starte error: Input/output error

The ALSA framework will stop the stream and return the error code EIO
when there was no interrupt for ten seconds, i.e., when
snd_pcm_period_elapsed() was not called.

Either s->active got corrupted, or your interrupt handler never got
called.

BTW: snd_pcm_period_elapsed() can stop the stream in some situations,
so you should move this call to the end of the interrupt handler, or
check s->active again after calling it.


HTH
Clemens

Re: Input/output error while playing a file using aplay

[Pharaoh .]

>The ALSA framework will stop the stream and return the error code EIO
>when there was no interrupt for ten seconds, i.e., when
>snd_pcm_period_elapsed() was not called.

I am getting the interrupts, but why there wont be any interrupt for
10 seconds?
I am setting the periods in prepare as periods = runtime->period, so
interrupts should
at period boundaries.

May be s->active got corrupted.


On 6/25/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> Pharaoh . wrote:
> > ...
> > It waits here for sometime and then I get
> > snd_omap_alsa_trigger starte error: Input/output error
>
> The ALSA framework will stop the stream and return the error code EIO
> when there was no interrupt for ten seconds, i.e., when
> snd_pcm_period_elapsed() was not called.
>
> Either s->active got corrupted, or your interrupt handler never got
> called.
>
> BTW: snd_pcm_period_elapsed() can stop the stream in some situations,
> so you should move this call to the end of the interrupt handler, or
> check s->active again after calling it.
>
>
> HTH
> Clemens
>

Re: Input/output error while playing a file using aplay

[Clemens Ladisch]

Pharaoh . wrote:
> >The ALSA framework will stop the stream and return the error code EIO
> >when there was no interrupt for ten seconds, i.e., when
> >snd_pcm_period_elapsed() was not called.
> 
> I am getting the interrupts, but why there wont be any interrupt for
> 10 seconds?

I don't quite understand this sentence.  You do get interrupts?
And snd_pcm_period_elapsed() is not called?

> I am setting the periods in prepare as periods = runtime->period, so
> interrupts should at period boundaries.

runtime->periods is the number of periods.  I don't know how your
hardware works, but I guess it wants to know the period size, i.e.,
runtime->period_size converted to bytes.


Regards,
Clemens

Re: Input/output error while playing a file using aplay

[Pharaoh .]

On 6/25/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> Pharaoh . wrote:
> > >The ALSA framework will stop the stream and return the error code EIO
> > >when there was no interrupt for ten seconds, i.e., when
> > >snd_pcm_period_elapsed() was not called.
> >
> > I am getting the interrupts, but why there wont be any interrupt for
> > 10 seconds?
>
> I don't quite understand this sentence.  You do get interrupts?
> And snd_pcm_period_elapsed() is not called?
>
> > I am setting the periods in prepare as periods = runtime->period, so
> > interrupts should at period boundaries.
>
> runtime->periods is the number of periods.  I don't know how your
> hardware works, but I guess it wants to know the period size, i.e.,
> runtime->period_size converted to bytes.
>
>
> Regards,
> Clemens
>


Apologie for being ambiguous...

1. When I posted the question, I was not even getting the DMA
interrupts. The input/output error was present.

2. After modifying the code a little I started getting the DMA
interrupts, but the input/output error still persists. So I am
doubting I might have messed up with the
period size etc.

3. I am assigning s->periods = runtime->period i.e. without converting
them in bytes, in prepare (I have seen some standard omap drivers
doing the same, so I am not converting it to bytes, frames should be
okay, but I will check this in h/w manual) and I take care in trigger
too by updating the s->periods field.

4. Also, s->period is locked appropriately so dont think it is corrupted.

I am attaching the source file, I have attached only 1 file since I
think it is relevant. Will send the log once I get chance to test it
again.

Re: Input/output error while playing a file using aplay

[Pharaoh .]

Here is the log, it seems that the pointer function is not working. I
am not supposed to use printks in many automic functions but I dont
have any other debugging option.


snd_card_omap_alsa_open start

omap850_audio_init start

eac_enable_clocks start
Clocks are already enabled
eac_set_samplerate start

eac_set_samplerate end

audio_dma_request start
omap_request_alsa_sound_dma start
omap_request_alsa_sound_dma end
snd_card_omap_alsa_open end
Playing WAVE 'startup.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
snd_omap_alsa_hw_params start
data format is 2 -- Channel 0 rate =2 and buffer size is ac44
snd_omap_alsa_hw_params end
snd_omap_alsa_prepare start
audio_configure_dma_channel start
dma_size is 2000
dma_ptr is c3fa0000
snd_omap_alsa_prepare end
SNDRV_PCM_IOCTL1_RESET
Inside snd_pcm_lib_ioctl_reset
Inside snd_pcm_do_start
snd_omap_alsa_trigger start
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
Inside omap_start_dma 1
Inside omap_start_dma 2
Inside omap_start_dma 3
audio_start_dma_chain end
Reading from c4954180
snd_omap_alsa_trigger end
sound_dma_irq_handler start
!!! In DMA IRQ handler
lch=0,status=0x20, dma_status=32, data=c3cb5104
callback_omap_alsa_sound_dma start
Inside /snd_pcm_period_elapsed
Inside snd_pcm_update_hw_ptr_interrupt
Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
 audio stream->offset is 1000000
 runtime->framebits is 20
Count is 8192
 Offset is 4192256 and buffer size is 16384
Inside snd_pcm_update_hw_ptr_pos, pos is 0
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
audio_start_dma_chain end
Reading from c4954180
sound_dma_irq_handler end

Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
 audio stream->offset is 2000
 runtime->framebits is 20
Count is 8192
 Offset is 0 and buffer size is 16384
Inside snd_pcm_update_hw_ptr_pos, pos is 0
/*Is waits here for sometime and then following error*/

Inside snd_pcm_do_stop write error: Input/output error


snd_omap_alsa_trigger start
audio_stop_dma start
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end

snd_omap_alsa_hw_free start
snd_omap_alsa_hw_free end
snd_card_omap_alsa_close start
omap850_audio_shutdown start

eac_disable_clocks start
eac_disable_clocks end
omap850_audio_shutdown end
audio_dma_free start
omap_free_alsa_sound_dma start
omap_sound_dma_unlink_lch start
omap_sound_dma_unlink_lch end
omap_free_alsa_sound_dma end
snd_card_omap_alsa_close end


And detailed log using strace


# strace aplay -Dplughw:0,0 --rate=44100 --format=S16 --channels=2 startup.wav
execve("/usr/local/bin/aplay", ["aplay", "-Dplughw:0,0",
"--rate=44100", "--format=S16", "--channels=2", "startup.wav"], [/* 7
vars */]) = 0
uname({sys="Linux", node="192.168.200.217", ...}) = 0
brk(0)                                  = 0x20000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0777, st_size=12436, ...}) = 0
mmap2(NULL, 12436, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40015000
close(3)                                = 0
open("/usr/local/lib/libasound.so.2", O_RDONLY) = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\314\353\1"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0777, st_size=2164893, ...}) = 0
mmap2(NULL, 777620, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x4001e000
mprotect(0x400d0000, 48532, PROT_NONE)  = 0
mmap2(0x400d8000, 16384, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xb2) = 0x400d8000
close(3)                                = 0
open("/lib/libm.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\00003\0\000"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0777, st_size=778699, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40019000
mmap2(NULL, 713068, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x400dc000
mprotect(0x40182000, 33132, PROT_NONE)  = 0
mmap2(0x40189000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa5) = 0x40189000
close(3)                                = 0
open("/lib/libdl.so.2", O_RDONLY)       = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\344\v\0\000"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0777, st_size=16868, ...}) = 0
mmap2(NULL, 41152, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x4018b000
mprotect(0x4018d000, 32960, PROT_NONE)  = 0
mmap2(0x40194000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1) = 0x40194000
close(3)                                = 0
open("/lib/libpthread.so.0", O_RDONLY)  = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0p?\0\0004"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0777, st_size=99172, ...}) = 0
mmap2(NULL, 367928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x40196000
mprotect(0x401a5000, 306488, PROT_NONE) = 0
mmap2(0x401ac000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xe) = 0x401ac000
mmap2(0x401ae000, 269624, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x401ae000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1a\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0HM\1\0004"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0777, st_size=1424946, ...}) = 0
mmap2(NULL, 1132932, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE,
3, 0) = 0x401f0000
mprotect(0x402f7000, 55684, PROT_NONE)  = 0
mmap2(0x402ff000, 16384, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x107) = 0x402ff000
mmap2(0x40303000, 6532, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40303000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x4001a000
mprotect(0x402ff000, 8192, PROT_READ)   = 0
mprotect(0x401ac000, 4096, PROT_READ)   = 0
mprotect(0x40194000, 4096, PROT_READ)   = 0
mprotect(0x40189000, 4096, PROT_READ)   = 0
mprotect(0x4001c000, 4096, PROT_READ)   = 0
munmap(0x40015000, 12436)               = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
setrlimit(RLIMIT_STACK, {rlim_cur=2044*1024, rlim_max=RLIM_INFINITY}) = 0
getpid()                                = 613
rt_sigaction(SIGRTMIN, {0x4019e980, [], 0x4000000 /* SA_??? */}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x4019ea3c, [RTMIN], 0x4000000 /* SA_??? */},
NULL, 8) = 0
rt_sigaction(SIGRT_2, {0x4019eba8, [], 0x4000000 /* SA_??? */}, NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RTMIN], NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RT_1], NULL, 8) = 0
_sysctl({{CTL_KERN, KERN_VERSION}, 2, 0xbed04ad8, 40, (nil), 0}) = 0
brk(0)                                  = 0x20000
brk(0x41000)                            = 0x41000
stat64("/usr/local/share/alsa/alsa.conf", {st_mode=S_IFREG|0777,
st_size=7764, ...}) = 0
open("/usr/local/share/alsa/alsa.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0777, st_size=7764, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40015000
read(3, "#\n#  ALSA library configuration "..., 4096) = 4096
read(3, "cards.pcm.surround40\npcm.surroun"..., 4096) = 3668
read(3, "", 4096)                       = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x40015000, 4096)                = 0
access("/etc/asound.conf", R_OK)        = 0
open("/etc/asound.conf", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0777, st_size=690, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40015000
read(3, "pcm.headset {\n\t@args [BDADDR TIM"..., 4096) = 690
read(3, "", 4096)                       = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x40015000, 4096)                = 0
access("//.asoundrc", R_OK)             = -1 ENOENT (No such file or directory)
open("/dev/snd/controlC0", O_RDONLY)    = 3
close(3)                                = 0
open("/dev/snd/controlC0", O_RDWR)      = 3
ioctl(3, USBDEVFS_CONTROL, 0xbed04874)  = 0
ioctl(3, 0x4snd_card_omap_alsa_open start
eac->base = c4954000        = 0

open("/dev/snd/pcmC0D0p", O_RDWBefore audio init
R|O_NONBLOCKomap850_audio_init start
eac_enable_clocks start
Clocks are already enabled
eac_set_samplerate start
Reading from c4954178
eac_set_samplerate end
after audio init
audio_dma_request start
omap_request_alsa_sound_dma start
omap_request_alsa_sound_dma end
snd_card_omap_alsa_open end
) = 4
close(3)                                = 0
ioctl(4, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbed04778) = 0
fcntl64(4, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
ioctl(4, AGPIOC_INFO, 0xbed046f0)       = 0
ioctl(4, AGPIOC_RELEASE or APM_IOC_SUSPEND, 0xbed046ec) = 0
mmap2(NULL, 4096, PROT_READ, MAP_SHARED, 4, 0x80000) = -1 ENXIO (No
such device or address)
ioctl(4, 0xc0844123, 0xbed046f4)        = 0
fcntl64(4, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl64(4, F_SETFL, O_RDWR)             = 0
ioctl(4, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbed04ccc) = 0
rt_sigaction(SIGINT, {0x401a28ac, [INT], SA_RESTART|0x4000000},
{SIG_DFL}, 8) = 0
rt_sigaction(SIGTERM, {0x401a28ac, [TERM], SA_RESTART|0x4000000},
{SIG_DFL}, 8) = 0
rt_sigaction(SIGABRT, {0x401a28ac, [ABRT], SA_RESTART|0x4000000},
{SIG_DFL}, 8) = 0
open("startup.wav", O_RDONLY|O_LARGEFILE) = 3
read(3, "RIFF(\310\24\0WAVEfmt \20\0\0\0\1\0\2\0", 24) = 24
read(3, "D\254\0\0", 4)                 = 4
read(3, "\20\261\2\0\4\0\20\0", 8)      = 8
read(3, "data\4\310\24\0", 8)           = 8
write(2, "Playing WAVE \'startup.wav\' : ", 29Playing WAVE
'startup.wav' : ) = 29
write(2, "Signed 16 bit Little Endian, ", 29Signed 16 bit Little Endian, ) = 29
write(2, "Rate 44100 Hz, ", 15Rate 44100 Hz, )         = 15
write(2, "Stereo", 6Stereo)                   = 6
write(2, "\n", 1
)                       = 1
ioctl(4, 0xc25c4110, 0xbed045f4)        = 0
ioctl(4, 0xc25c4110, 0xbed042e8)        = 0
ioctl(4, 0xc25c4110, 0xbed042e8)        = 0
ioctl(4, 0xc25c4110, 0xbed045f4)        = 0
ioctl(4, 0xc25c4110, 0xbed042e8)        = 0
ioctl(4, 0xc25c4110, 0xbed042e8)        = 0
ioctl(4, 0xc25c4110, 0xbed045f4)        = 0
ioctl(4, 0xc25c4110, 0xbed04368)        = 0
ioctl(4, 0xc25c4110, 0xbed0405c)        = 0
ioctl(4, 0xc25c4110, 0xbed0405c)        = 0
ioctl(4, 0xc25c4110, 0xbed04368)        = 0
ioctl(4, 0xc25c4110, 0xbed04368)        = 0
ioctl(4, 0xc25c4110, 0xbed0405c)        = 0
ioctl(4, 0xc25c4110, 0xbed0405c)        = 0
ioctl(4, 0xc25c4110, 0xbed04368)        = 0
ioctl(4, 0xc25c4110snd_omap_alsa_hw_params start
, 0xbed0405c)        = 0
ioctl(data format is 2 -- Channel 0 rate =2 and buffer size is ac44
4, 0xc25c4110, 0xbed0405c)      snd_omap_alsa_hw_params end
  = 0
ioctl(4, 0xc25c4110, 0xbed04368)        = 0
snd_omap_alsa_prepare start4368)        = 0

ioctl(4, 0xc25c4110, 0xbed0405caudio_configure_dma_channel start
)        = 0
ioctl(4, 0xc25c411dma_size is 2000
0, 0xbed0405c)        = 0
ioctldma_ptr is c3f20000
(4, 0xc25c4110, 0xbed04368)     snd_omap_alsa_prepare end
   = 0
ioctl(4, 0xc25c4110, 0xbSNDRV_PCM_IOCTL1_RESET
ed0405c)        = 0
ioctl(4, 0xInside snd_pcm_lib_ioctl_reset
c25c4110, 0xbed0405c)        = 0
ioctl(4, 0xc25c4110, 0xbed04368)        = 0
ioctl(4, 0xc25c4110, 0xbed03e6c)        = 0
ioctl(4, 0xc25c4110, 0xbed03b60)        = 0
ioctl(4, 0xc25c4110, 0xbed03b60)        = 0
ioctl(4, 0xc25c4110, 0xbed03e6c)        = 0
ioctl(4, 0xc25c4110, 0xbed03b60)        = 0
ioctl(4, 0xc25c4110, 0xbed03b60)        = 0
ioctl(4, 0xc25c4110, 0xbed03e6c)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed040d4)        = 0
ioctl(4, 0xc25c4110, 0xbed04564)        = 0
ioctl(4, 0xc25c4110, 0xbed04564)        = 0
ioctl(4, 0xc25c4110, 0xbed04564)        = 0
ioctl(4, 0xc25c4110, 0xbed04564)        = 0
ioctl(4, 0xc25c4110, 0xbed04564)        = 0
ioctl(4, 0xc25c4110, 0xbed04904)        = 0
ioctl(4, 0xc25c4111, 0xbed04904)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
ioctl(4, 0xc0684113, 0xbed044c4)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
ioctl(4, 0x4140, 0x400c3ed4)            = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
ioctl(4, 0xc0684113, 0xbed04898)        = 0
read(3, "\377\377\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\1"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\377\377\0\0\1\0\0\0\0\0\0\0\377\377\376\377\0\0\3\0\377"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\374\377\7\0\0\0\0\0\372\377\0\0\376\377\3\0\3\0\373\377"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\373\377\1\0\377\377\5\0\376\377\372\377\377\377\7\0\6"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\212\377{\377\212\377\210\377\220\377\226\377\214\377\213"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, ".\324\326\3438\323Q\343\375\322\34\343\254\323\223\343"...,
8192) = 8192
ioctl(4, 0x400c4150, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "\2\fK\0x\v\220\375\361\n_\373\246\n\270\371\235\n;\Inside
snd_pcm_do_start
snd_omap_alsa_trigger start
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
Inside omap_start_dma 1
Inside omap_start_dma 2
Inside omap_start_dma 3
audio_start_dma_chain end
Reading from c4954180
snd_omap_alsa_trigger end
371"..., 8192) = 8192
ioctl(4, sound_dma_irq_handler start
0x400c4150, 0xbed04bf0)        =!!! In DMA IRQ handler
lch=0,status=0x20, dma_status=32, data=c3cb9884
 0
ioctl(4, 0xc0844123, 0x27e10callback_omap_alsa_sound_dma start
)           = 0
read(3, "\336\3Inside /snd_pcm_period_elapsed
27R\357\277\330\361\357\256\331\Inside snd_pcm_update_hw_ptr_interrupt
Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
 audio stream->offset is 1000000
 runtime->framebits is 20
Count is 8192
 Offset is 4192256 and buffer size is 16384
Inside snd_pcm_update_hw_ptr_pos, pos is 0
211\360d\332(\361"..., 8192) = 8audio_set_dma_params_play start
192
ioctl(4, 0x400c4150audio_set_dma_params_play end
audio_start_dma_chain start
audio_start_dma_chain end
Reading from c4954180
sound_dma_irq_handler end
, 0xbed04bf0)        = 0
ioctl(4, 0xc0844123, 0x27e10)           = 0
read(3, "H\343#\3Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
 audio stream->offset is 2000
 runtime->framebits is 20
Count is 8192
 Offset is 0 and buffer size is 16384
Inside snd_pcm_update_hw_ptr_pos, pos is 0
55\233\342\317\355\377\341\312\356\216\341\250"..., 8192) = 8192
ioctl(4, 0x400c4150


/**********waits here **************/
0xbed04bf0)        = -1 EIO (Input/output error)
write(2, "aplay: pcm_write:1268: ", 23aplay: pcm_write:1268: ) = 23
write(2Inside snd_pcm_do_stop
snd_omap_alsa_trigger start
audio_stop_dma start
Reading from c4954180
before writing to EAC_AGCTR = 60
aftere writing to EAC_AGCTR = 60
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end
, "write error: Input/output errsnd_omap_alsa_hw_free start
or", 31write error: Input/outputsnd_omap_alsa_hw_free end
 error) = 31
write(2, "\n", 1
snd_card_omap_alsa_close start
)                       = 1
io_omap850_audio_shutdown start
submit(0x1, 0, 0x4Reading from c4954180
eac_disable_clocks start
eac_disable_clocks end

omap850_audio_shutdown end
audio_dma_free start
omap_free_alsa_sound_dma start
omap_sound_dma_unlink_lch start
omap_sound_dma_unlink_lch end
omap_free_alsa_sound_dma end
snd_card_omap_alsa_close end
 <unfinished ... exit status 1>
Process 613 detached




On 6/25/07, Pharaoh . <pharaoh137@gmail.com> wrote:
> On 6/25/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> > Pharaoh . wrote:
> > > >The ALSA framework will stop the stream and return the error code EIO
> > > >when there was no interrupt for ten seconds, i.e., when
> > > >snd_pcm_period_elapsed() was not called.
> > >
> > > I am getting the interrupts, but why there wont be any interrupt for
> > > 10 seconds?
> >
> > I don't quite understand this sentence.  You do get interrupts?
> > And snd_pcm_period_elapsed() is not called?
> >
> > > I am setting the periods in prepare as periods = runtime->period, so
> > > interrupts should at period boundaries.
> >
> > runtime->periods is the number of periods.  I don't know how your
> > hardware works, but I guess it wants to know the period size, i.e.,
> > runtime->period_size converted to bytes.
> >
> >
> > Regards,
> > Clemens
> >
>
>
> Apologie for being ambiguous...
>
> 1. When I posted the question, I was not even getting the DMA
> interrupts. The input/output error was present.
>
> 2. After modifying the code a little I started getting the DMA
> interrupts, but the input/output error still persists. So I am
> doubting I might have messed up with the
> period size etc.
>
> 3. I am assigning s->periods = runtime->period i.e. without converting
> them in bytes, in prepare (I have seen some standard omap drivers
> doing the same, so I am not converting it to bytes, frames should be
> okay, but I will check this in h/w manual) and I take care in trigger
> too by updating the s->periods field.
>
> 4. Also, s->period is locked appropriately so dont think it is corrupted.
>
> I am attaching the source file, I have attached only 1 file since I
> think it is relevant. Will send the log once I get chance to test it
> again.
>

Re: Input/output error while playing a file using aplay

[Pharaoh .]

I am pruning the logs in previous e-mails here since its becoming too
lengthy to read. After rewriting the pointer function I am not getting
the input/output error but I am getting underruns. I think I am little
closer to the
working driver now, am I?

here is the log, after getting couple of underrun error messages the
dma just gets halted.

Log:

snd_card_omap_alsa_open start

eac_enable_clocks start
Clocks are already enabled
eac_set_samplerate start

eac_set_samplerate end
after audio init
audio_dma_request start
omap_request_alsa_sound_dma start
omap_request_alsa_sound_dma end
snd_card_omap_alsa_open end
Playing WAVE 'startup.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
snd_omap_alsa_hw_params start
data format is 2 -- Channel 0 rate =2 and buffer size is ac44
snd_omap_alsa_hw_params end
snd_omap_alsa_prepare start
audio_configure_dma_channel start
dma_size is 2000
dma_ptr is c3540000
snd_omap_alsa_prepare end
SNDRV_PCM_IOCTL1_RESET
Inside snd_pcm_lib_ioctl_reset
Inside snd_pcm_do_start
snd_omap_alsa_trigger start
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
/*These are the platform specific dma setup routines*/
Inside omap_start_dma 1
Inside omap_start_dma 2
Inside omap_start_dma 3
audio_start_dma_chain end
snd_omap_alsa_trigger end
sound_dma_irq_handler start
!!! In DMA IRQ handler
lch=0,status=0x20, dma_status=32, data=c3cb5704
callback_omap_alsa_sound_dma start
Inside /snd_pcm_period_elapsed
Inside snd_pcm_update_hw_ptr_interrupt
Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
Inside snd_pcm_update_hw_ptr_pos, pos is 18153472
/**Here is a BUG**/
ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000,
buffer size = 0x4000, period size = 0x800
Inside snd_pcm_do_stop
snd_omap_alsa_trigger start
audio_stop_dma start
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end
Not active
sound_dma_irq_handler end
Inside snd_pcm_status
/***Under run here ****/
underrun!!! (at least -33.431 mssnd_omap_alsa_prepare start
 long)
audio_configure_dma_channel start
dma_size is 2000
dma_ptr is c3540000
snd_omap_alsa_prepare end
SNDRV_PCM_IOCTL1_RESET
Inside snd_pcm_lib_ioctl_reset
Inside snd_pcm_do_start
snd_omap_alsa_trigger start
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
Inside omap_start_dma 1
Inside omap_start_dma 2
Inside omap_start_dma 3
audio_start_dma_chain end
snd_omap_alsa_trigger end
sound_dma_irq_handler start
!!! In DMA IRQ handler
lch=0,status=0x20, dma_status=32, data=c3cb5704
callback_omap_alsa_sound_dma start
Inside /snd_pcm_period_elapsed
Inside snd_pcm_update_hw_ptr_interrupt
Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
Inside snd_pcm_update_hw_ptr_pos, pos is 18153472

/***Bug ***/
ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000,
buffer size = 0x4000, period size = 0x800
Inside snd_pcm_do_stop
snd_omap_alsa_trigger start
audio_stop_dma start
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end
Not active
sound_dma_irq_handler end
Inside snd_pcm_status
/***underrun***/
underrun!!! (at least -33.633 mssnd_omap_alsa_prepare start
 long)
audio_configure_dma_channel start
dma_size is 2000
dma_ptr is c3540000
snd_omap_alsa_prepare end
SNDRV_PCM_IOCTL1_RESET
Inside snd_pcm_lib_ioctl_reset
Inside snd_pcm_do_start
snd_omap_alsa_trigger start
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
Inside omap_start_dma 1
Inside omap_start_dma 2
Inside omap_start_dma 3
audio_start_dma_chain end
snd_omap_alsa_trigger end
sound_dma_irq_handler start
!!! In DMA IRQ handler
lch=0,status=0x20, dma_status=32, data=c3cb5704
callback_omap_alsa_sound_dma start
Inside /snd_pcm_period_elapsed
Inside snd_pcm_update_hw_ptr_interrupt
Inside snd_pcm_update_hw_ptr_pos
snd_omap_alsa_pointer start
Inside snd_pcm_update_hw_ptr_pos, pos is 18153472
/***BUG**/
ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000,
buffer size = 0x4000, period size = 0x800
Inside snd_pcm_do_stop
snd_omap_alsa_trigger start
audio_stop_dma start
omap_stop_alsa_sound_dma end
omap_clear_alsa_sound_dma start
omap_clear_alsa_sound_dma end
snd_omap_alsa_trigger end
Not active
sound_dma_irq_handler end
Inside snd_pcm_status
/***Underrun**/
underrun!!! (at least -33.759 mssnd_omap_alsa_prepare start
 long)
audio_configure_dma_channel start
dma_size is 2000
dma_ptr is c3540000
snd_omap_alsa_prepare end
SNDRV_PCM_IOCTL1_RESET
Inside snd_pcm_lib_ioctl_reset
Inside snd_pcm_do_start
snd_omap_alsa_trigger start
audio_set_dma_params_play start
audio_set_dma_params_play end
audio_start_dma_chain start
Inside omap_start_dma 1
Inside omap_start_dma 2

/******It hangs here, the dma halts here and no further messages are
shown*******/

Re: Input/output error while playing a file using aplay

[Clemens Ladisch]

Pharaoh . wrote:
> After rewriting the pointer function

It would really help if you'd show us the code of the version of the
driver that you're currently talking about.

> I am not getting the input/output error but I am getting underruns.
> ...
> ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000, buffer size = 0x4000, period size = 0x800

Here, "pos" is the value returned by your pointer callback.  This value
should have been a frame number somewhere in the buffer, i.e., in the
range 0..0x3fff.  Apparently, the pointer callback doesn't correctly
calculate this value.

Please remove most printk()s, and add some in the pointer callback to
show both the value that you get from the DMA controller, and the value
that this function returns.


Regards,
Clemens

Re: Input/output error while playing a file using aplay

[Pharaoh .]

>It would really help if you'd show us the code of the version of the
>driver that you're currently talking about.

Hi Clemens...

I had sent you the source file having pcm callbacks yesterday, now I
have modified the pointer function as follows, I am just giving the
pointer function here to avoid duplication, but please let me know in
case you want to have look at the entire file.


static snd_pcm_uframes_t snd_omap_alsa_pointer(snd_pcm_substream_t *substream)
{

        struct omap_eac *chip = snd_pcm_substream_chip(substream);
        snd_pcm_uframes_t pos = 0;

        FN_ENTER;
        pos = audio_get_dma_pos(&chip->s[substream->pstr->stream]);
        printk("Returning pos = %d\n", pos);
        return pos;
        FN_EXIT;
}

static snd_pcm_uframes_t audio_get_dma_pos(struct audio_stream *s)
{
        snd_pcm_substream_t *substream = s->stream;
        snd_pcm_runtime_t *runtime = substream->runtime;
        unsigned long flags;
        dma_addr_t count;
        unsigned long offset;
        dma_addr_t src,dest;

         if (substream->stream == SNDRV_PCM_STREAM_CAPTURE) {
                dest = omap_get_dma_dst_pos(s->lch[s->dma_q_head]);
                offset = dest - runtime->dma_addr;
                printk("dest is %u and offset is %u\n",dest,offset);
         } else {
                src = omap_get_dma_src_pos(s->lch[s->dma_q_head]);
                offset = src - runtime->dma_addr;
                printk("src is %u and offset is %u\n",dest,offset);
         }

        return bytes_to_frames(substream->runtime, offset);
}


And the log is as follows.

For the first time.


snd_omap_alsa_pointer start
src is 3246792928 and offset is 3304194048
Returning pos = 20742144
Inside snd_pcm_update_hw_ptr_pos, pos is 20742144
ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x13c8000,
buffer size = 0x4000, period size = 0x800
returning pos 20742144

I can see things are horribaly wrong here....


On 6/26/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> Pharaoh . wrote:
> > After rewriting the pointer function
>
> It would really help if you'd show us the code of the version of the
> driver that you're currently talking about.
>
> > I am not getting the input/output error but I am getting underruns.
> > ...
> > ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000, buffer
> size = 0x4000, period size = 0x800
>
> Here, "pos" is the value returned by your pointer callback.  This value
> should have been a frame number somewhere in the buffer, i.e., in the
> range 0..0x3fff.  Apparently, the pointer callback doesn't correctly
> calculate this value.
>
> Please remove most printk()s, and add some in the pointer callback to
> show both the value that you get from the DMA controller, and the value
> that this function returns.
>
>
> Regards,
> Clemens
>

Re: Input/output error while playing a file using aplay

[Pharaoh .]

wait..wait.....I need to use locking here...let me send you log after
doing locking appropriately .....

On 6/26/07, Pharaoh . <pharaoh137@gmail.com> wrote:
> >It would really help if you'd show us the code of the version of the
> >driver that you're currently talking about.
>
> Hi Clemens...
>
> I had sent you the source file having pcm callbacks yesterday, now I
> have modified the pointer function as follows, I am just giving the
> pointer function here to avoid duplication, but please let me know in
> case you want to have look at the entire file.
>
>
> static snd_pcm_uframes_t snd_omap_alsa_pointer(snd_pcm_substream_t
> *substream)
> {
>
>         struct omap_eac *chip = snd_pcm_substream_chip(substream);
>         snd_pcm_uframes_t pos = 0;
>
>         FN_ENTER;
>         pos = audio_get_dma_pos(&chip->s[substream->pstr->stream]);
>         printk("Returning pos = %d\n", pos);
>         return pos;
>         FN_EXIT;
> }
>
> static snd_pcm_uframes_t audio_get_dma_pos(struct audio_stream *s)
> {
>         snd_pcm_substream_t *substream = s->stream;
>         snd_pcm_runtime_t *runtime = substream->runtime;
>         unsigned long flags;
>         dma_addr_t count;
>         unsigned long offset;
>         dma_addr_t src,dest;
>
>          if (substream->stream == SNDRV_PCM_STREAM_CAPTURE) {
>                 dest = omap_get_dma_dst_pos(s->lch[s->dma_q_head]);
>                 offset = dest - runtime->dma_addr;
>                 printk("dest is %u and offset is %u\n",dest,offset);
>          } else {
>                 src = omap_get_dma_src_pos(s->lch[s->dma_q_head]);
>                 offset = src - runtime->dma_addr;
>                 printk("src is %u and offset is %u\n",dest,offset);
>          }
>
>         return bytes_to_frames(substream->runtime, offset);
> }
>
>
> And the log is as follows.
>
> For the first time.
>
>
> snd_omap_alsa_pointer start
> src is 3246792928 and offset is 3304194048
> Returning pos = 20742144
> Inside snd_pcm_update_hw_ptr_pos, pos is 20742144
> ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x13c8000,
> buffer size = 0x4000, period size = 0x800
> returning pos 20742144
>
> I can see things are horribaly wrong here....
>
>
> On 6/26/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> > Pharaoh . wrote:
> > > After rewriting the pointer function
> >
> > It would really help if you'd show us the code of the version of the
> > driver that you're currently talking about.
> >
> > > I am not getting the input/output error but I am getting underruns.
> > > ...
> > > ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000, buffer
> > size = 0x4000, period size = 0x800
> >
> > Here, "pos" is the value returned by your pointer callback.  This value
> > should have been a frame number somewhere in the buffer, i.e., in the
> > range 0..0x3fff.  Apparently, the pointer callback doesn't correctly
> > calculate this value.
> >
> > Please remove most printk()s, and add some in the pointer callback to
> > show both the value that you get from the DMA controller, and the value
> > that this function returns.
> >
> >
> > Regards,
> > Clemens
> >
>

Re: Input/output error while playing a file using aplay

[Pharaoh .]

static snd_pcm_uframes_t audio_get_dma_pos(struct audio_stream *s)
{
        snd_pcm_substream_t *substream = s->stream;
        snd_pcm_runtime_t *runtime = substream->runtime;
        unsigned long flags;
        dma_addr_t count;
        unsigned long offset;
        dma_addr_t src,dest;

         if (substream->stream == SNDRV_PCM_STREAM_CAPTURE) {
                spin_lock_irqsave(&s->dma_lock, flags);
                dest = omap_get_dma_dst_pos(s->lch[s->dma_q_head]);
                offset = dest - runtime->dma_addr;
                spin_unlock_irqrestore(&s->dma_lock, flags);
                printk("dest is %u and offset is %u\n",dest,offset);
         } else {
                spin_lock_irqsave(&s->dma_lock, flags);
                src = omap_get_dma_src_pos(s->lch[s->dma_q_head]);
                offset = src - runtime->dma_addr;
                spin_unlock_irqrestore(&s->dma_lock, flags);
                printk("src is %u and offset is %u\n",dest,offset);
         }

        return bytes_to_frames(substream->runtime, offset);
}

and the log is as same....still no joy..

First time

snd_omap_alsa_pointer start
src is 3246792928 and offset is 3296722944
Returning pos = 18874368
Inside snd_pcm_update_hw_ptr_pos, pos is 18874368
ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1200000,
buffer size = 0x4000, period size = 0x800
returning pos 18874368

.......
.......
Second time

snd_omap_alsa_pointer start
src is 3246792928 and offset is 3296722944
Returning pos = 18874368
Inside snd_pcm_update_hw_ptr_pos, pos is 18874368
ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1200000,
buffer size = 0x4000, period size = 0x800
returning pos 18874368

......

then it hangs in the omap_request_dma function.

On 6/26/07, Pharaoh . <pharaoh137@gmail.com> wrote:
> wait..wait.....I need to use locking here...let me send you log after
> doing locking appropriately .....
>
> On 6/26/07, Pharaoh . <pharaoh137@gmail.com> wrote:
> > >It would really help if you'd show us the code of the version of the
> > >driver that you're currently talking about.
> >
> > Hi Clemens...
> >
> > I had sent you the source file having pcm callbacks yesterday, now I
> > have modified the pointer function as follows, I am just giving the
> > pointer function here to avoid duplication, but please let me know in
> > case you want to have look at the entire file.
> >
> >
> > static snd_pcm_uframes_t snd_omap_alsa_pointer(snd_pcm_substream_t
> > *substream)
> > {
> >
> >         struct omap_eac *chip = snd_pcm_substream_chip(substream);
> >         snd_pcm_uframes_t pos = 0;
> >
> >         FN_ENTER;
> >         pos = audio_get_dma_pos(&chip->s[substream->pstr->stream]);
> >         printk("Returning pos = %d\n", pos);
> >         return pos;
> >         FN_EXIT;
> > }
> >
> > static snd_pcm_uframes_t audio_get_dma_pos(struct audio_stream *s)
> > {
> >         snd_pcm_substream_t *substream = s->stream;
> >         snd_pcm_runtime_t *runtime = substream->runtime;
> >         unsigned long flags;
> >         dma_addr_t count;
> >         unsigned long offset;
> >         dma_addr_t src,dest;
> >
> >          if (substream->stream == SNDRV_PCM_STREAM_CAPTURE) {
> >                 dest = omap_get_dma_dst_pos(s->lch[s->dma_q_head]);
> >                 offset = dest - runtime->dma_addr;
> >                 printk("dest is %u and offset is %u\n",dest,offset);
> >          } else {
> >                 src = omap_get_dma_src_pos(s->lch[s->dma_q_head]);
> >                 offset = src - runtime->dma_addr;
> >                 printk("src is %u and offset is %u\n",dest,offset);
> >          }
> >
> >         return bytes_to_frames(substream->runtime, offset);
> > }
> >
> >
> > And the log is as follows.
> >
> > For the first time.
> >
> >
> > snd_omap_alsa_pointer start
> > src is 3246792928 and offset is 3304194048
> > Returning pos = 20742144
> > Inside snd_pcm_update_hw_ptr_pos, pos is 20742144
> > ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x13c8000,
> > buffer size = 0x4000, period size = 0x800
> > returning pos 20742144
> >
> > I can see things are horribaly wrong here....
> >
> >
> > On 6/26/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> > > Pharaoh . wrote:
> > > > After rewriting the pointer function
> > >
> > > It would really help if you'd show us the code of the version of the
> > > driver that you're currently talking about.
> > >
> > > > I am not getting the input/output error but I am getting underruns.
> > > > ...
> > > > ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x1150000,
> buffer
> > > size = 0x4000, period size = 0x800
> > >
> > > Here, "pos" is the value returned by your pointer callback.  This value
> > > should have been a frame number somewhere in the buffer, i.e., in the
> > > range 0..0x3fff.  Apparently, the pointer callback doesn't correctly
> > > calculate this value.
> > >
> > > Please remove most printk()s, and add some in the pointer callback to
> > > show both the value that you get from the DMA controller, and the value
> > > that this function returns.
> > >
> > >
> > > Regards,
> > > Clemens
> > >
> >
>

Re: Input/output error while playing a file using aplay

[Clemens Ladisch]

Pharaoh . wrote:
>                 src = omap_get_dma_src_pos(s->lch[s->dma_q_head]);
>                 offset = src - runtime->dma_addr;
>                 printk("src is %u and offset is %u\n",dest,offset);
> 
> src is 3246792928 and offset is 3304194048
> Returning pos = 20742144
> ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x13c8000, buffer size = 0x4000, period size = 0x800

dma_addr = 0xFC9420E0 (is this correct?)
src      = 0xC18620E0
offset   = 0xC4F20000

Apparently, the return value of omap_get_dma_src_pos() is wrong.
Should this value be 16 bits?


Regards,
Clemens

Re: Input/output error while playing a file using aplay

[Pharaoh .]

As per the plat-omap/dma.c the function is like this:

/*
  * Returns current physical source address for the given DMA channel.
  * If the channel is running the caller must disable interrupts prior calling
  * this function and process the returned value before re-enabling interrupt to
  * prevent races with the interrupt handler. Note that in continuous mode there
  * is a chance for CSSA_L register overflow inbetween the two reads resulting
  * in incorrect return value.
  */
 dma_addr_t omap_get_dma_src_pos(int lch)
 {
         dma_addr_t offset;

         if (cpu_class_is_omap1())
                 offset = (dma_addr_t) (OMAP1_DMA_CSSA_L_REG(lch) |
                                        (OMAP1_DMA_CSSA_U_REG(lch) << 16));

         if (cpu_is_omap24xx())
                 offset = OMAP_DMA_CSAC_REG(lch);

         return offset;
}

I have one doubt here, I am referring Writing ALSA driver by Takashi
it says following about the dma_addr_t.

If you use a standard ALSA function, snd_pcm_lib_malloc_pages(), for
allocating the buffer, these fields are set by the ALSA middle layer,
and you should not change them by yourself.

I am using the standard helper function to allocate the DMA buffer in
my hw_params, so I am not setting the runtime->dma_addr field, pcm
layer must be setting it, right?

But in my pointer function I am accessing runtime->dma_addr where as
the guide says it is i.e the physical bus address is not accessible
from the main CPU. I am doing wrong accessing it?

After allocating the buffer in hw_params i am  trying to check the
physical and virtual addr of the DMA buffer, I get

Physical DMA addr is 00000000 and virtual addr is c3540000

does it mean that dma_addr is really not accessible from main CPU?

In pointer when I check the dma addr I get

runtime->dma_addr is 00000000 !!

How come??

-pharaoh.

On 6/26/07, Clemens Ladisch <cladisch@fastmail.net> wrote:
> Pharaoh . wrote:
> >                 src = omap_get_dma_src_pos(s->lch[s->dma_q_head]);
> >                 offset = src - runtime->dma_addr;
> >                 printk("src is %u and offset is %u\n",dest,offset);
> >
> > src is 3246792928 and offset is 3304194048
> > Returning pos = 20742144
> > ALSA sound/core/pcm_lib.c:167: BUG: stream = 0, pos = 0x13c8000, buffer
> size = 0x4000, period size = 0x800
>
> dma_addr = 0xFC9420E0 (is this correct?)
> src      = 0xC18620E0
> offset   = 0xC4F20000
>
> Apparently, the return value of omap_get_dma_src_pos() is wrong.
> Should this value be 16 bits?
>
>
> Regards,
> Clemens
>
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: Input/output error while playing a file using aplay

[Pharaoh .]

>In pointer when I check the dma addr I get
>runtime->dma_addr is 00000000 !!

I think runtime->dma_addr is set to 0 when the dma buffer is
physically non-contiguous.