Re: question about alsa tracepoints and alsa debugging

[Takashi Sakamoto <o-takashi@sakamocchi.jp>]

Hi,

> commands used for starting playback / trace capture and for recording -
> ./perf record -F 99 -g -e snd_pcm:* -e sched:sched_switch -e
> sched:sched_wakeup -e irq:* speaker-test -D
> hw:CARD=ak4458ak5558aud,DEV=0 -c8 -r192000 -FS32_LE -tsine &
> arecord -Dhw:CARD=ak4458ak5558aud,DEV=1 -fS32_LE -c16 -r192000
> /mnt/ramdisk/rec.wav
>
> I enabled the kernel options as described at
> https://www.kernel.org/doc/html/v5.9/sound/designs/tracepoints.html
> and have used perf to record a trace, which can be access here -
> https://kernel-debugging.s3-us-west-1.amazonaws.com/perf.data.script.211220202054.txt
> (exported using "perf script")
>
> The trace file shows "lockdep_recursion" at some point so I am
> wondering if my problem has to do with a deadlock somehow being
> caused.

According to the log, speaker-test starts PCM substream for playback
direction with below parameters:

 - bits per sample: 32 bit
 - samples per frame: 8
 - frames per second: 192000
 - frames per period: 4096
 - frames per buffer: 16384
 - ...

By calculation with the above parameters, the hardware of I2S interface
should be configured to generate harware interrupt every 21.3 msec.

I wrote a Python 3 script to check the period of interrupt with a focus
on the record including call of 'snd_pcm_period_elapsed' in its backtrace:
https://gist.github.com/takaswie/af2b93b58a1154903d6fbe1a6bee3c69

```
$ ./parse.py /tmp/perf.data.script.211220202054.txt | \
  grep -B 3 -A 3 unexpected
73.2000 0.02132900 expected
73.2213 0.02133500 expected
73.2426 0.02135300 expected
110.0207 36.77807000 unexpected
110.0420 0.02133000 expected
110.0634 0.02133400 expected
110.0847 0.02132400 expected
```

I can find around 37 second gap in timestamp 110.0207. It means that the
I2S driver failed to control RK3288 I2S interface for periodical hardware
interrupt.

Furthermore, I can see following records after the gap. It means that
speaker-test process successfully detected XRUN of the PCM substream,
then recoverd it to continue processing PCM frames for playback
expectedly. Thus the I2S driver seems to have few problems about
dead-lock issue.

With records of tracepoints events for capture PCM substream
which Bert's SDIO driver handles as well as for the playback PCM
substream which speaker-test starts, we can get more details of
runtimes.

P.S. diagrams for the case:

```
+-----------+       +----+          +------+         +-------+
|AK5558 x 2 |<-(?)->|FPGA|          |RK3288|         | AK4458|
| (ADC)     |<-(?)->|    |<-(SDIO)->|      |<-(I2S)->| (DAC) |
+-----------+       +----+          +------+         +-------+
```


Regards

Takashi Sakamoto