Now it is time for new year fairy tales.
Chapter II - Realtime audio driver
Well, that was hell long and bumpy road to go, cause…
Default ALSA SOC driver is good enough for ordinary sound task like playing you favorite music or record something… But truly incapable to do realtime work, as there is no synchronization between capturing audio and playing it back…
So after long study of SOC datasheet a decision was made how things should be organized.
At first, I need to make input and output synchronous - that means that clocks, frequencies and bit depths should be equal for both input and output TDM. No resample engine allowed and by this time, no support for EQDRC or Sharebuffer (for parallel SPDIF output interface) will be implemented.
At second point - SOC itself allows circular 2 buffers scheme (not implemented In Amlogic ALSA drivers) - so I’ll implement this. What is more important - an SOC raises an interrupt when switching buffers - good point to sync kernel task with user space - saying - Hey, I have a new buffer for DSP to handle!!!
Need to say that without oscilloscope - there are no chances to debug things like audio driver…. I spent a lot of hours dealing with a stupid mistake … For some reasons I was getting data from ADC via TDM DATA IN slot … but sometimes it was purely wrong… At the end I’ve found that pinctrl was not applying right amperage to the clock pins (my mistake - as in mainline DTS pin amperage is now described as drive-strength-microamp = directive instead one used in 4.9 kernerls)
However it was still not enough to get a realtime driver. Through several test - it was unexpected floats of times when interrupts happens - even up to 300 microseconds… Many days were spent trying to figure out a root cause and finally SOC internal fifo’s were found culprit… So I had to make extreme changes to fifos config - and yes - finally I got my realtime driver working as expected…
root@Khadas:~# modinfo evl_audio_rt
filename: /lib/modules/5.15.0/kernel/drivers/evl/sound/evl-amlogic/evl-audio-rt.ko
license: GPL
description: Realtime Amlogic SOC AUGE direct sound driver
author: Old Navi (old.navi@bk.ru)
alias: of:N*T*Camlogic,axg-sound-realtimeC*
alias: of:N*T*Camlogic,axg-sound-realtime
alias: of:N*T*Camlogic,_sm1-audio-ddr-managerC*
alias: of:N*T*Camlogic,_sm1-audio-ddr-manager
alias: of:N*T*Camlogic,_tl1-audio-ddr-managerC*
alias: of:N*T*Camlogic,_tl1-audio-ddr-manager
alias: of:N*T*Camlogic,_g12a-audio-ddr-managerC*
alias: of:N*T*Camlogic,_g12a-audio-ddr-manager
alias: of:N*T*Camlogic,_axg-audio-ddr-managerC*
alias: of:N*T*Camlogic,_axg-audio-ddr-manager
alias: of:N*T*Camlogic,_tm2-audio-clocksC*
alias: of:N*T*Camlogic,_tm2-audio-clocks
alias: of:N*T*Camlogic,_sm1-audio-clocksC*
alias: of:N*T*Camlogic,_sm1-audio-clocks
alias: of:N*T*Camlogic,_tl1-audio-clocksC*
alias: of:N*T*Camlogic,_tl1-audio-clocks
alias: of:N*T*Camlogic,_g12a-audio-clocksC*
alias: of:N*T*Camlogic,_g12a-audio-clocks
alias: of:N*T*Camlogic,_axg-audio-clocksC*
alias: of:N*T*Camlogic,_axg-audio-clocks
alias: of:N*T*Camlogic,_tm2-snd-tdmlbC*
alias: of:N*T*Camlogic,_tm2-snd-tdmlb
alias: of:N*T*Camlogic,_tm2-snd-tdmcC*
alias: of:N*T*Camlogic,_tm2-snd-tdmc
alias: of:N*T*Camlogic,_tm2-snd-tdmbC*
alias: of:N*T*Camlogic,_tm2-snd-tdmb
alias: of:N*T*Camlogic,_tm2-snd-tdmaC*
alias: of:N*T*Camlogic,_tm2-snd-tdma
alias: of:N*T*Camlogic,_sm1-snd-tdmlbC*
alias: of:N*T*Camlogic,_sm1-snd-tdmlb
alias: of:N*T*Camlogic,_sm1-snd-tdmcC*
alias: of:N*T*Camlogic,_sm1-snd-tdmc
alias: of:N*T*Camlogic,_sm1-snd-tdmbC*
alias: of:N*T*Camlogic,_sm1-snd-tdmb
alias: of:N*T*Camlogic,_sm1-snd-tdmaC*
alias: of:N*T*Camlogic,_sm1-snd-tdma
alias: of:N*T*Camlogic,_tl1-snd-tdmlbC*
alias: of:N*T*Camlogic,_tl1-snd-tdmlb
alias: of:N*T*Camlogic,_tl1-snd-tdmcC*
alias: of:N*T*Camlogic,_tl1-snd-tdmc
alias: of:N*T*Camlogic,_tl1-snd-tdmbC*
alias: of:N*T*Camlogic,_tl1-snd-tdmb
alias: of:N*T*Camlogic,_tl1-snd-tdmaC*
alias: of:N*T*Camlogic,_tl1-snd-tdma
alias: of:N*T*Camlogic,_g12a-snd-tdmlbC*
alias: of:N*T*Camlogic,_g12a-snd-tdmlb
alias: of:N*T*Camlogic,_g12a-snd-tdmcC*
alias: of:N*T*Camlogic,_g12a-snd-tdmc
alias: of:N*T*Camlogic,_g12a-snd-tdmbC*
alias: of:N*T*Camlogic,_g12a-snd-tdmb
alias: of:N*T*Camlogic,_g12a-snd-tdmaC*
alias: of:N*T*Camlogic,_g12a-snd-tdma
alias: of:N*T*Camlogic,_axg-snd-tdmlbC*
alias: of:N*T*Camlogic,_axg-snd-tdmlb
alias: of:N*T*Camlogic,_axg-snd-tdmcC*
alias: of:N*T*Camlogic,_axg-snd-tdmc
alias: of:N*T*Camlogic,_axg-snd-tdmbC*
alias: of:N*T*Camlogic,_axg-snd-tdmb
alias: of:N*T*Camlogic,_axg-snd-tdmaC*
alias: of:N*T*Camlogic,_axg-snd-tdma
depends:
intree: Y
name: evl_audio_rt
vermagic: 5.15.0 SMP mod_unload aarch64
parm: audio_buffer_size:uint
parm: audio_hat:charp
parm: audio_enable_low_latency:uint
root@Khadas:~#
(As side effect - I’m not longer limited to standard I2S frequencies - now I can have any - like 33333Hz - and everything works)
So I’ve added some extra code for measurement into the driver (I’m measuring a nanoseconds timestamps when interrupt arrives) and wrote a simple userpace test program - which receives an event when driver switches to the new buffer and print some information
It is also required some kernel and driver tuning… for kernel config it was require to isolate some CPUs from Realtime Kernel and virse-versa using isolcpus and oobcpus arguments
[ 0.000000] Kernel command line: root=UUID=641c1c63-3430-4636-9ab3-0002f130cd43 rootfstype=ext4 rootflags=data=writeback rw ubootpart=357d90c6-01 console=ttyAML0,115200n8 no_console_suspend consoleblank=0 loglevel=0 osd12 fbcon=rotate:90 fsck.repair=yes net.ifnames=0 jtag=disable mac=c8:63:14:71:2b:98 fan=auto khadas_board=VIM3L hwver=VIM3.V12 coherent_pool=2M pci=pcie_bus_perf imagetype=EMMC_MBR uboottype=mainline splash quiet plymouth.ignore-serial-consoles vt.handoff=7 isolcpus=1,2,3 evl.oobcpus=1,2,3
Also realtime driver code required to use interrupt affinity to OOB cpus - just to avoid interfere of interrupts (by default Linux kernel pins most of interrupt to CPU0)
root@Khadas:/opt/evl/bin# cat /proc/interrupts
CPU0 CPU1 CPU2 CPU3
9: 0 0 0 0 GICv2 25 Level vgic
10: 0 128451273 6961558 6622463 SIRQC 10 Edge in-band work
12: 0 0 0 0 GICv2 30 Level kvm guest ptimer
13: 0 0 0 0 GICv2 27 Level kvm guest vtimer
14: 693238 273781873 828541 647049 GICv2 26 Level oob arch_timer
16: 217688 0 0 0 GICv2 40 Level eth0
20: 4 0 0 0 GICv2 225 Edge ttyAML0
21: 97 0 0 0 GICv2 227 Edge ff805000.i2c
22: 0 0 0 0 GICv2 228 Edge ff808000.ir
23: 2 0 0 0 GICv2 232 Edge ff809000.adc
24: 0 0 0 0 GICv2 76 Edge vdec
25: 0 0 0 0 GICv2 64 Edge esparserirq
27: 0 0 0 0 GICv2 71 Edge ffd1c000.i2c
28: 4199 0 0 0 GICv2 58 Edge ttyAML6
29: 223581 0 0 0 GICv2 221 Edge ffe03000.sd
30: 0 0 0 0 GICv2 222 Edge ffe05000.sd
31: 6603 0 0 0 GICv2 223 Edge ffe07000.mmc
33: 0 0 0 0 GICv2 194 Level panfrost-job
34: 0 0 0 0 GICv2 193 Level panfrost-mmu
35: 3 0 0 0 GICv2 192 Level panfrost-gpu
36: 0 0 0 0 GICv2 218 Level galcore:0
37: 693182 831246 828514 647021 SIRQC 37 Edge proxy tick
38: 0 0 0 0 GICv2 63 Level ff400000.usb, ff400000.usb
39: 33 0 0 0 GICv2 62 Level xhci-hcd:usb1
41: 0 0 0 0 PCI-MSI 0 Edge PCIe PME, aerdrv
42: 11 0 0 0 PCI-MSI 524288 Edge nvme0q0
43: 1 0 0 0 meson-gpio-irqchip 26 Level 0.0:00
45: 10240 0 0 0 PCI-MSI 524289 Edge nvme0q1
46: 0 0 0 0 PCI-MSI 524290 Edge nvme0q2
47: 0 0 0 0 PCI-MSI 524291 Edge nvme0q3
48: 0 0 0 0 PCI-MSI 524292 Edge nvme0q4
49: 0 202121 0 0 GICv2 180 Edge oob sound@0xFF660000
52: 0 202157 0 0 GICv2 184 Edge oob sound@0xFF660000
IPI0: 209671 703 43306187 41385913 Rescheduling interrupts
IPI1: 118 210 856 640 Function call interrupts
IPI2: 0 0 0 0 CPU stop interrupts
IPI3: 0 0 0 0 CPU stop (for crash dump) interrupts
IPI4: 0 0 0 0 Timer broadcast interrupts
IPI5: 0 0 0 0 IRQ work interrupts
IPI6: 0 0 0 0 CPU wake-up interrupts
So my driver is smart enough to set affinity to OOB cpus, notice OOB flags set for interrupt lines 49 and 52
So now it is time for measurements… I will make a test with smallest sample buffer possible - just 16 samples… bigger buffers shows the same picture
Testcase 1 - IDLE load
Idle scenario - no load at system - sampling frequency 96Khz, 24 bit, buffer size 16 samples
root@Khadas:~# ./test 96000 16
.....
nsec: 4637152559669 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637152726336 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637152893002 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637153059669 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637153226336 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637153393002 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637153559669 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637153726336 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637153893002 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637154059669 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637154226336 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637154393002 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637154559711 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637154726336 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637154893002 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637155059669 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637155226336 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637155393002 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4637155559669 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
User process minumum wait time = 163µs, maximum wait time = 170µs, average = 166µs
IRQ minumum wait time = 166µs, maximum wait time = 166µs, average = 166µs
Wow!!! Drift of times is not bigger than 4 microseconds… Audio in latency is just 0.166 milliseconds … no interrupt or buffer overrun loss…
Tescase 2: Light load on the system with several realtime threads running
root@Khadas:/opt/evl/bin# ./hectic
== Testing FPU check routines...
== FPU check routines: OK.
== Threads: sleeper_ufps1-0 rtk1-1 rtk1-2 rtup1-3 rtup1-4 rtup_ufpp1-5 rtup_ufpp1-6 rtus1-7 rtus1-8 rtus_ufps1-9 rtus_ufps1-10 rtuo1-11 rtuo1-12 rtuo_ufpp1-13 rtuo_ufpp1-14 rtuo_ufps1-15 rtuo_ufps1-16 rtuo_ufpp_ufps1-17 rtuo_ufpp_ufps1-18 sleeper_ufps2-0 rtk2-1 rtk2-2 rtup2-3 rtup2-4 rtup_ufpp2-5 rtup_ufpp2-6 rtus2-7 rtus2-8 rtus_ufps2-9 rtus_ufps2-10 rtuo2-11 rtuo2-12 rtuo_ufpp2-13 rtuo_ufpp2-14 rtuo_ufps2-15 rtuo_ufps2-16 rtuo_ufpp_ufps2-17 rtuo_ufpp_ufps2-18 sleeper_ufps3-0 rtk3-1 rtk3-2 rtup3-3 rtup3-4 rtup_ufpp3-5 rtup_ufpp3-6 rtus3-7 rtus3-8 rtus_ufps3-9 rtus_ufps3-10 rtuo3-11 rtuo3-12 rtuo_ufpp3-13 rtuo_ufpp3-14 rtuo_ufps3-15 rtuo_ufps3-16 rtuo_ufpp_ufps3-17 rtuo_ufpp_ufps3-18
RTT| 00:00:01
RTH|---------cpu|ctx switches|-------total
RTD| 3| 16359| 16359
RTD| 2| 16414| 16414
RTD| 1| 16361| 16361
RTD| 3| 16414| 32773
RTD| 1| 16416| 32777
RTD| 2| 16416| 32830
RTD| 3| 16363| 49136
RTD| 2| 16416| 49246
RTD| 1| 16416| 49193
RTD| 3| 16414| 65550
RTD| 1| 16414| 65607
RTD| 2| 16416| 65662
And results are
root@Khadas:~# ./test 96000 16
.....
nsec: 4883259795328 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883259962786 - Waited for IRQ for 169µs, IRQ time = 167µs, retcode = 0
nsec: 4883260129453 - Waited for IRQ for 165µs, IRQ time = 166µs, retcode = 0
nsec: 4883260296203 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883260462036 - Waited for IRQ for 165µs, IRQ time = 165µs, retcode = 0
nsec: 4883260628661 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883260795370 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883260962036 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883261128661 - Waited for IRQ for 167µs, IRQ time = 166µs, retcode = 0
nsec: 4883261295328 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883261462536 - Waited for IRQ for 167µs, IRQ time = 167µs, retcode = 0
nsec: 4883261628703 - Waited for IRQ for 165µs, IRQ time = 166µs, retcode = 0
nsec: 4883261795328 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883261961995 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 4883262128661 - Waited for IRQ for 167µs, IRQ time = 166µs, retcode = 0
User process minumum wait time = 161µs, maximum wait time = 171µs, average = 166µs
IRQ minumum wait time = 163µs, maximum wait time = 169µs, average = 166µs
Drift is ±5 microseconds - notice that interrupt time started to float, but that is still damn good values
Testcase 3: High load with process contact switch at maximum rate (every 3 microsecond)
root@Khadas:/opt/evl/bin# ./hectic -s 3
== Testing FPU check routines...
== FPU check routines: OK.
== Threads: switcher_ufps1-0 rtk1-1 rtk1-2 rtup1-3 rtup1-4 rtup_ufpp1-5 rtup_ufpp1-6 rtus1-7 rtus1-8 rtus_ufps1-9 rtus_ufps1-10 rtuo1-11 rtuo1-12 rtuo_ufpp1-13 rtuo_ufpp1-14 rtuo_ufps1-15 rtuo_ufps1-16 rtuo_ufpp_ufps1-17 rtuo_ufpp_ufps1-18 fpu_stress_ufps1-19 switcher_ufps2-0 rtk2-1 rtk2-2 rtup2-3 rtup2-4 rtup_ufpp2-5 rtup_ufpp2-6 rtus2-7 rtus2-8 rtus_ufps2-9 rtus_ufps2-10 rtuo2-11 rtuo2-12 rtuo_ufpp2-13 rtuo_ufpp2-14 rtuo_ufps2-15 rtuo_ufps2-16 rtuo_ufpp_ufps2-17 rtuo_ufpp_ufps2-18 fpu_stress_ufps2-19 switcher_ufps3-0 rtk3-1 rtk3-2 rtup3-3 rtup3-4 rtup_ufpp3-5 rtup_ufpp3-6 rtus3-7 rtus3-8 rtus_ufps3-9 rtus_ufps3-10 rtuo3-11 rtuo3-12 rtuo_ufpp3-13 rtuo_ufpp3-14 rtuo_ufps3-15 rtuo_ufps3-16 rtuo_ufpp_ufps3-17 rtuo_ufpp_ufps3-18 fpu_stress_ufps3-19
RTT| 00:00:01
RTH|---------cpu|ctx switches|-------total
RTD| 2| 57454| 57454
RTD| 1| 45484| 45484
RTD| 3| 54946| 54946
RTD| 2| 57114| 114568
RTD| 1| 45771| 91255
RTD| 3| 57000| 111946
RTD| 2| 57114| 171682
RTD| 1| 45771| 137026
RTD| 3| 57057| 169003
RTD| 2| 57114| 228796
RTD| 1| 45657| 182683
RTD| 3| 56886| 225889
RTD| 2| 57342| 286138
RTD| 1| 45602| 228285
RTD| 3| 57000| 282889
RTD| 2| 57228| 343366
And test results are:
./test 96000 16
.....
nsec: 5159810749877 - Waited for IRQ for 166µs, IRQ time = 167µs, retcode = 0
nsec: 5159810915752 - Waited for IRQ for 167µs, IRQ time = 165µs, retcode = 0
nsec: 5159811082377 - Waited for IRQ for 164µs, IRQ time = 166µs, retcode = 0
nsec: 5159811249085 - Waited for IRQ for 168µs, IRQ time = 166µs, retcode = 0
nsec: 5159811417252 - Waited for IRQ for 168µs, IRQ time = 168µs, retcode = 0
nsec: 5159811582627 - Waited for IRQ for 165µs, IRQ time = 165µs, retcode = 0
nsec: 5159811749377 - Waited for IRQ for 165µs, IRQ time = 166µs, retcode = 0
nsec: 5159811915960 - Waited for IRQ for 167µs, IRQ time = 166µs, retcode = 0
nsec: 5159812082793 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 5159812250293 - Waited for IRQ for 167µs, IRQ time = 167µs, retcode = 0
nsec: 5159812416043 - Waited for IRQ for 163µs, IRQ time = 165µs, retcode = 0
nsec: 5159812582502 - Waited for IRQ for 167µs, IRQ time = 166µs, retcode = 0
nsec: 5159812748877 - Waited for IRQ for 166µs, IRQ time = 166µs, retcode = 0
nsec: 5159812916877 - Waited for IRQ for 169µs, IRQ time = 168µs, retcode = 0
nsec: 5159813082502 - Waited for IRQ for 163µs, IRQ time = 165µs, retcode = 0
nsec: 5159813250918 - Waited for IRQ for 169µs, IRQ time = 168µs, retcode = 0
nsec: 5159813415877 - Waited for IRQ for 164µs, IRQ time = 164µs, retcode = 0
User process minumum wait time = 156µs, maximum wait time = 175µs, average = 166µs
IRQ minumum wait time = 158µs, maximum wait time = 173µs, average = 166µs
Delta microseconds went to ± 10 microseconds and it is still excellent !!!
Testcase 4: Highest load plus CPU cache wiping out
Same as previous but I’m adding CPU cache line wiping using dd if=/dev/zero of=/dev/null command. It will run only on inband kernel CPUS
And results are:
root@Khadas:~# ./test 96000 16
......
sec: 5383588888358 - Waited for IRQ for 163µs, IRQ time = 166µs, retcode = 0
nsec: 5383589055150 - Waited for IRQ for 171µs, IRQ time = 166µs, retcode = 0
nsec: 5383589221025 - Waited for IRQ for 164µs, IRQ time = 165µs, retcode = 0
nsec: 5383589390567 - Waited for IRQ for 169µs, IRQ time = 169µs, retcode = 0
nsec: 5383589556025 - Waited for IRQ for 161µs, IRQ time = 165µs, retcode = 0
nsec: 5383589722233 - Waited for IRQ for 165µs, IRQ time = 166µs, retcode = 0
nsec: 5383589888067 - Waited for IRQ for 166µs, IRQ time = 165µs, retcode = 0
nsec: 5383590054775 - Waited for IRQ for 168µs, IRQ time = 166µs, retcode = 0
nsec: 5383590221317 - Waited for IRQ for 164µs, IRQ time = 166µs, retcode = 0
nsec: 5383590388150 - Waited for IRQ for 167µs, IRQ time = 166µs, retcode = 0
nsec: 5383590554858 - Waited for IRQ for 172µs, IRQ time = 166µs, retcode = 0
nsec: 5383590720942 - Waited for IRQ for 160µs, IRQ time = 166µs, retcode = 0
nsec: 5383590888817 - Waited for IRQ for 167µs, IRQ time = 167µs, retcode = 0
nsec: 5383591054567 - Waited for IRQ for 167µs, IRQ time = 165µs, retcode = 0
nsec: 5383591221858 - Waited for IRQ for 165µs, IRQ time = 167µs, retcode = 0
nsec: 5383591388567 - Waited for IRQ for 165µs, IRQ time = 166µs, retcode = 0
User process minumum wait time = 146µs, maximum wait time = 186µs, average = 166µs
IRQ minumum wait time = 149µs, maximum wait time = 183µs, average = 166µs
Delta of changes became bigger but doesn’t exceeds ±20 microseconds… Hell yeah!!! Excelent
Summing up - yes it works… even in rough conditions with 16 sample size buffer, no loss of interrupts, and timing are great. In reality nobody is using such small sample buffer… just for understanding - 10 milliseconds audio delay isn’t hearable at all…
So running that test with full load with realistic buffer size of 256 samples and 48Khz sampling frequency (giving 5,3ms input latency and 10,6ms round trip latency)
root@Khadas:~# ./test 48000 256
.......
nsec: 5680108422583 - Waited for IRQ for 5338µs, IRQ time = 5331µs, retcode = 0
nsec: 5680113756708 - Waited for IRQ for 5332µs, IRQ time = 5334µs, retcode = 0
nsec: 5680119088750 - Waited for IRQ for 5331µs, IRQ time = 5332µs, retcode = 0
nsec: 5680124423333 - Waited for IRQ for 5335µs, IRQ time = 5334µs, retcode = 0
nsec: 5680129756750 - Waited for IRQ for 5335µs, IRQ time = 5333µs, retcode = 0
nsec: 5680135090000 - Waited for IRQ for 5327µs, IRQ time = 5333µs, retcode = 0
nsec: 5680140423791 - Waited for IRQ for 5336µs, IRQ time = 5333µs, retcode = 0
nsec: 5680145754875 - Waited for IRQ for 5325µs, IRQ time = 5331µs, retcode = 0
nsec: 5680151091000 - Waited for IRQ for 5338µs, IRQ time = 5336µs, retcode = 0
nsec: 5680156424041 - Waited for IRQ for 5338µs, IRQ time = 5333µs, retcode = 0
nsec: 5680161757166 - Waited for IRQ for 5329µs, IRQ time = 5333µs, retcode = 0
nsec: 5680167087958 - Waited for IRQ for 5334µs, IRQ time = 5330µs, retcode = 0
nsec: 5680172422000 - Waited for IRQ for 5331µs, IRQ time = 5334µs, retcode = 0
nsec: 5680177760750 - Waited for IRQ for 5338µs, IRQ time = 5338µs, retcode = 0
nsec: 5680183089791 - Waited for IRQ for 5331µs, IRQ time = 5329µs, retcode = 0
User process minumum wait time = 5313µs, maximum wait time = 5353µs, average = 5333µs
IRQ minumum wait time = 5319µs, maximum wait time = 5345µs, average = 5333µs
±20 microseconds latency drifting play zero role when we are dealing with milliseconds
That is unreachable with stock Linux kernel… and light years unreachable on Windows
Next step is to polish driver code… and start porting DAW software