Mackie Onyx 1640i: Kernel module snd-oxfw plays audio in slow motion.

[AreYouLoco]

As I already wrote an email to you @takaswie maybe some other developers might want to take a look so I re-post a bit reformatted report here:

So I confirm my Mackie Onyx 1640i is using snd_oxfw driver.

I have two items to request you:

• retrieve packet dump from ALSA oxfw driver
• test with the latest driver

1. Here is dump [1] (file:trace.dat_stock) with the old (stock) driver for my custom kernel (5.12.2-rt3-fw) and the [1] (file:trace.dat_new) from your new driver (master branch) that you asked to test out. Everything at 512 buffer size and 3 periods @ 48kHz and JACK2 with ALSA backend (44,1kHz test described below) :

The problem is when I play music from pulseaudio sink (from Firefox; Soundcloud and YouTube) the audio plays in slow motion on both sites mentioned. Even the video on YouTube is in slow motion. With VLC and local mp3 file there is slow motion effect and interrupt/break in audio output every 1 second. In Ardour (Linux DAW) the same problem appears. Audio is slowed or just really pitched down. I used command sleep 5 to be more on less precise on the time sudo trace-cmd record -e snd_firewire_lib:amdtp_packet runs.

Also from my experience; I played audio only for short time on YT (pulseaudio_sink to ALSA backend on JACK as I dont have 44.1kHz sessions in Ardour. But at 44.1kHz the same slow motion effect appears on YT and Soundcloud as well as files played locally via VLC. (file:trace.dat_441)

The only messages from dmesg are:

[  531.209832] snd_oxfw fw1.0: Detect discontinuity of CIP: 68 00
[ 5041.841125] snd_oxfw fw1.0: Detect discontinuity of CIP: 58 00

But I am not sure when they appeared. With old or the new master kernel module. Maybe I will try to figure it out. Also I will try with non-RT kernel.

LINK TO THE DUMPS [1] https://mega.nz/folder/76hCBRTK#muOYoyghB8fbva4alQDZnQ

I've verified I run your new driver with this:

areyouloco@studio:~/code/snd-firewire-improve$ sudo modinfo snd-oxfw
filename:       /lib/modules/5.12.2-rt3-fw/updates/dkms/snd-oxfw.ko
areyouloco@studio:~/code/snd-firewire-improve$ sudo dkms install alsa-firewire/4.17
Module alsa-firewire/4.17 already installed on kernel 5.12.2-rt3-fw/x86_64

(sudo modprobe -r before and loaded the module again after DKMS build to be sure)

2. So when I uninstall your driver and run it from kernel directory:

   
   areyouloco@studio:~/code/snd-firewire-improve$ sudo dkms remove alsa-firewire/4.17 --all
   areyouloco@studio:~/code/snd-firewire-improve$ sudo modinfo snd-oxfw
   filename: /lib/modules/5.12.2-rt3-fw/kernel/sound/firewire/oxfw/snd-oxfw.ko

(again sudo modprobe -r before and loaded the module again after DKMS uninstall)

After restoring to kernel's stock module it plays at normal speed/pitch.

So there is for sure some bug introduced to be rechecked.

Thank you for your amazing work! Up to some further tests,
AreYouLoco? 

[AreYouLoco]

I've rechecked my dmesg output and found some related lines:

[    6.962065] firewire_ohci 0000:0d:00.3: added OHCI v1.10 device as card 0, 4 IR + 4 IT contexts, quirks 0x50
[    6.962190] firewire_ohci 0000:0d:00.3: isochronous cycle inconsistent
[    6.962313] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.962437] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.962560] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.962685] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.962813] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.962936] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.963060] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.963185] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    6.963313] firewire_ohci 0000:0d:00.3: isochronous cycle too long
[    7.466963] firewire_core 0000:0d:00.3: created device fw0: GUID 0021cc20090c29ce, S400
[    7.474158] firewire_core 0000:0d:00.3: created device fw1: GUID 000ff2050000145b, S400
[    7.474162] firewire_core 0000:0d:00.3: phy config: new root=ffc0, gap_count=5
[ 6759.166861] firewire_core 0000:0d:00.3: rediscovered device fw0

Not sure using which driver. Will try to establish which driver correlates to that messages.

EDIT:

[ 7403.839511] firewire_ohci 0000:0d:00.3: isochronous cycle inconsistent
[ 7404.243910] firewire_core 0000:0d:00.3: created device fw1: GUID 000ff2050000145b, S400
[ 7404.243916] firewire_core 0000:0d:00.3: phy config: new root=ffc0, gap_count=5

This appeared when starting JACK on your snd-oxfw kernel module.

I am going to check with non-RT kernel. EDIT: With 5.10.0-8-amd64 stock Debian kernel and your code the audio is definitely playing in slow motion not pitched down.

I am switching back to stock kernel driver and waiting your response.

[takaswie]

Thanks for the report! As a quick glance of the packet dump, it comes from the quirk specific to your model or mackie models. I'd like you to wait a bit till I finish further analysis.

Cheers.

[takaswie]

@AreYouLoco Would I request you to ssend additional information below?

• dump of/proc/asound/cards includes values ofsome registers.

Thanks

[AreYouLoco]

@AreYouLoco Would I request you to send additional information below?

• dump of /proc/asound/cards includes values of some registers. Thanks

areyouloco@studio:~$ cat /proc/asound/cards
 0 [PCH            ]: HDA-Intel - HDA Intel PCH
                      HDA Intel PCH at 0xf3820000 irq 34
 1 [NVidia         ]: HDA-Intel - HDA NVidia
                      HDA NVidia at 0xf1000000 irq 17
 2 [O1640i         ]: OXFW - Onyx 1640i
                      Loud Technologies Inc. Onyx 1640i (OXFW971 0105), GUID 000ff2050000145b at fw1.

it comes from the quirk specific to your model or mackie models

I am using custom patch for my kernel that gives another option in firewire_ohci quirks.

To activate this patch you will have to create a file /etc/modprobe.d/ricoh-firewire.conf with the following content: options firewire_ohci ricoh_audio=on quirks=0xd0 and reload the firewire_ohci module or simply reboot. //Debian default quirks are 0x50 we need to add “Ricoh FIFO configurable = 0x80”, so in hexadecimal 0x50 + 0x80 gives us quirks=0xd0

But with stock Debian kernel without that quirk the result is the same. So I tried with quirks hexadecimal values 0x50, and on custom kernel 0xd0 and 0x80.

parm: quirks:Chip quirks (default = 0, nonatomic cycle timer = 0x1, reset packet generation = 0x2, AR/selfID endianness = 0x4, no 1394a enhancements = 0x8, disable MSI = 0x10, TI SLLZ059 erratum = 0x20, IR wake unreliable = 0x40, Ricoh FIFO configurable = 0x80) (int) parm: ricoh_audio:Prioritize audio over disk traffic on Ricoh controllers (bool) parm: debug:Verbose logging (default = 0, AT/AR events = 1, self-IDs = 2, IRQs = 4, busReset events = 8, or a combination, or all = -1) (int) parm: remote_dma:Enable unfiltered remote DMA (default = N) (bool)

[takaswie]

I hastily wrote Python 3 script to parse the packet dumps.

#!/usr/bin/env python3

from sys import argv
from pathlib import Path

def build_quadlet(elems):
    return (int(elems[0]) << 24) | \
           (int(elems[1]) << 16) | \
           (int(elems[2]) << 8) | \
           (int(elems[3]) << 0)

if len(argv) < 2:
    print('At least one argument is required for path of file')
    sys.exit(1)
filepath = argv[1]

path = Path(filepath)
if not path.exists():
    print('File not found')
    sys.exit(1)

seq = {}

with path.open('r') as f:
    for line in f:
        line = line.strip();
        pos = line.find('amdtp_packet')
        if pos < 0:
            continue
        elems = line[(pos + 22):].split(' ')

        sec = int(elems[0])
        cycle = int(elems[1])
        src_node = elems[2]
        dst_node = elems[3]
        isoc_ch = int(elems[4])
        quadlet_count = int(elems[5])
        data_blocks = int(elems[6])
        data_block_count = int(elems[7])
        packet_index = int(elems[8])
        is_irq = int(elems[9]) > 0
        index = int(elems[10])

        cip0 = build_quadlet(elems[-8:-4])
        cip1 = build_quadlet(elems[-4:])

        if isoc_ch not in seq:
            seq[isoc_ch] = []
        seq[isoc_ch].append([sec, cycle, quadlet_count, data_blocks, data_block_count, packet_index, is_irq, index, cip0, cip1])

def compute_cycle_count(sec, cycle):
    return (sec * 8000) + cycle

def increment_cycle_count(cycle_count):
    cycle_count += 1
    return cycle_count % (8 * 8000)

for isoc_ch, cycles in seq.items():
    next_cycle_count = compute_cycle_count(cycles[0][0], cycles[0][1])
    count = 0
    events = 0;

    print('ch {}:'.format(isoc_ch))
    for cycle in cycles:
        cycle_count = compute_cycle_count(cycle[0], cycle[1])
        if cycle_count != next_cycle_count:
            print('  discontinue')
        next_cycle_count = increment_cycle_count(cycle_count)

        events += cycle[3]

        count += 1
        if count == 8000:
            print('  {} sec, {} cycle: {} events'.format(cycle[0], cycle[1], events))
            count = 0
            events = 0

When parsing, the packet dump should be converted for text format by trace-cmd report. As results:

$ ./parse stock.log
ch 0:
  1 sec, 5594 cycle: 48000 events
  2 sec, 5594 cycle: 48000 events
  3 sec, 5594 cycle: 48000 events
  4 sec, 5594 cycle: 48000 events
  5 sec, 5594 cycle: 48000 events
  6 sec, 5594 cycle: 48000 events
  7 sec, 5594 cycle: 48000 events
  0 sec, 5594 cycle: 48000 events
  1 sec, 5594 cycle: 48000 events
  2 sec, 5594 cycle: 48000 events
  3 sec, 5594 cycle: 48000 events
  4 sec, 5594 cycle: 48000 events
ch 1:
  1 sec, 5336 cycle: 48000 events
  2 sec, 5336 cycle: 48000 events
  3 sec, 5336 cycle: 48000 events
  4 sec, 5336 cycle: 48000 events
  5 sec, 5336 cycle: 48000 events
  6 sec, 5336 cycle: 48000 events
  7 sec, 5336 cycle: 48000 events
  0 sec, 5336 cycle: 48000 events
  1 sec, 5336 cycle: 48000 events
  2 sec, 5336 cycle: 48000 events
  3 sec, 5336 cycle: 48000 events
  4 sec, 5336 cycle: 48000 events

$ ./parse new.log
ch 0:
  5 sec, 4318 cycle: 26392 events
  6 sec, 4318 cycle: 26400 events
  7 sec, 4318 cycle: 26392 events
  0 sec, 4318 cycle: 26392 events
  1 sec, 4318 cycle: 26400 events
  2 sec, 4318 cycle: 26392 events
  3 sec, 4318 cycle: 26392 events
  4 sec, 4318 cycle: 26400 events
  5 sec, 4318 cycle: 26392 events
ch 1:
  5 sec, 4037 cycle: 26400 events
  6 sec, 4037 cycle: 26392 events
  7 sec, 4037 cycle: 26400 events
  0 sec, 4037 cycle: 26392 events
  1 sec, 4037 cycle: 26392 events
  2 sec, 4037 cycle: 26400 events
  3 sec, 4037 cycle: 26392 events
  4 sec, 4037 cycle: 26392 events
  5 sec, 4037 cycle: 26400 events

$ ./parse 441.log
ch 0:
  0 sec, 3825 cycle: 26336 events
  1 sec, 3825 cycle: 26336 events
  2 sec, 3825 cycle: 26336 events
  3 sec, 3825 cycle: 26336 events
  4 sec, 3825 cycle: 26336 events
  5 sec, 3825 cycle: 26336 events
  6 sec, 3825 cycle: 26336 events
  7 sec, 3825 cycle: 26336 events
  0 sec, 3825 cycle: 26336 events
  1 sec, 3825 cycle: 26336 events
  2 sec, 3825 cycle: 26344 events
  3 sec, 3825 cycle: 26336 events
  4 sec, 3825 cycle: 26336 events
  5 sec, 3825 cycle: 26336 events
ch 1:
  0 sec, 3567 cycle: 26336 events
  1 sec, 3567 cycle: 26336 events
  2 sec, 3567 cycle: 26336 events
  3 sec, 3567 cycle: 26336 events
  4 sec, 3567 cycle: 26336 events
  5 sec, 3567 cycle: 26336 events
  6 sec, 3567 cycle: 26336 events
  7 sec, 3567 cycle: 26336 events
  0 sec, 3567 cycle: 26336 events
  1 sec, 3567 cycle: 26336 events
  2 sec, 3567 cycle: 26344 events
  3 sec, 3567 cycle: 26336 events
  4 sec, 3567 cycle: 26336 events
  5 sec, 3567 cycle: 26336 events

In all cases, the device uses isochronous channel number 1. We can see apparent regression between v5.14 kernel and v5.13 kernel or before. 55 % of packets than media clock frequency are actually transferred. It is the cause of slow playback.

Fortunately, at least, we know the way to handle the device correctly ;) I prepare a patch and push it into topic/fix-oxfw-mackie-regression remote branch. Would I ask you to test it in your system? Regardless of success or failure, It's preferable to save packet dump and share it to me.

Thanks

[AreYouLoco]

areyouloco@studio:~/code/snd-firewire-improve$ git status
HEAD detached at origin/topic/fix-oxfw-mackie-regression
nothing to commit, working tree clean

Audio and video is still in slow motion. Same result in VLC. I can see no real difference with this fix. Packet dump: https://mega.nz/file/figBmCga#NXsEfFFprKNt552jEbjtMrlFXsbrJn-abLE9l6dYiGU

EDIT: I've made some .bash_aliases to be able to quickly build and restore snd-oxfw. I used timeout 15s command to precisely capture dump for some seconds. So testing is just a matter of minute or so.

[takaswie]

Audio and video is still in slow motion. Same result in VLC. I can see no real difference with this fix.
Packet dump: https://mega.nz/file/figBmCga#NXsEfFFprKNt552jEbjtMrlFXsbrJn-abLE9l6dYiGU

Thanks for the test. According to the log, we can see the media clock frequency is still invalid.

$ ./parse fix1.log
ch 0:
  2 sec, 6543 cycle: 26648 events
  3 sec, 6543 cycle: 26656 events
  4 sec, 6543 cycle: 26648 events
  5 sec, 6543 cycle: 26656 events
  6 sec, 6543 cycle: 26640 events
  7 sec, 6543 cycle: 26656 events
  0 sec, 6543 cycle: 26648 events
  1 sec, 6543 cycle: 26648 events
  2 sec, 6543 cycle: 26648 events
ch 1:
  2 sec, 6285 cycle: 26656 events
  3 sec, 6285 cycle: 26648 events
  4 sec, 6285 cycle: 26648 events
  5 sec, 6285 cycle: 26656 events
  6 sec, 6285 cycle: 26648 events
  7 sec, 6285 cycle: 26648 events
  0 sec, 6285 cycle: 26648 events
  1 sec, 6285 cycle: 26656 events
  2 sec, 6285 cycle: 26640 events

Hm, I pile another patch into the previous one:

oxfw: postpone the cycle to start processing tx packets

The media clock frequency is not stable until enough amount of received
packets are processed. This commit postpones the cycle to start processing
tx packets until 1000 isochronous cycles are past.

Would i ask you additional test?

[AreYouLoco]

HEAD is now at 51018bd oxfw: postpone the cycle to start processing tx packets No real difference.

Dump FIXv2: https://mega.nz/file/n3REgBYY#YLA35hobLZnepi3LcErE5df3KWu5lKrePyNmbSIyh5Q

[takaswie]

@AreYouLoco I'm sorry to be late for reply, but I write additional patch to test. Would you please try with current HEAD (709535a2879d) of topic/fix-oxfw-mackie-regression branch?

[AreYouLoco]

I tested I while ago and there seems do be problem since audio is more audible but til not normally to listed. I Experience XRUNS while its playing and on VLC one seconds breaks i guess separate issue there. And dump as always: https://mega.nz/file/2roXGY7T#jiwOv0msawAzLzO-C9zoLyggxb5aeqIwJsLwDsC9AMQ

[takaswie]

I tested I while ago and there seems do be problem since audio is more audible but til not normally to listed. I Experience XRUNS while its playing and on VLC one seconds breaks i guess separate issue there. And dump as always: https://mega.nz/file/2roXGY7T#jiwOv0msawAzLzO-C9zoLyggxb5aeqIwJsLwDsC9AMQ

Thanks for testing. Hm. I attempted to analyze packet dump but the data (trace_.dat_quiet) includes no events... Would I ask you to get the data again?

[takaswie]

And today I got similar model, Mackie Onyx 820i (OXFW971) in used market, and tested current code. As a result, current ALSA OXFW driver can successfully handle the model, unlike your Onyx 1640i.

As long as I know, below models have the similar identification information in their configuration ROM:

• Onyx 820i
• Onyx 1220i
• Onyx 1620i

They commonly have two analog output ports and the driver works with two channels of playback.

On the other hand, Onyx 1640i has 16 analog output ports. I think that OXFW 971 has some kind of quirk when configured to operate for many channels in the point of media clock recovery.

Anyway, I'm waiting for the dump data, thanks.

[AreYouLoco]

Indeed I thought its switched of speakers but there is just no sound. I am using FW channels 1-2 to out. Should try on all 16?! DUMP: https://mega.nz/file/ijB3VCya#gYkSY0RJSOVkpAXmWTf7QY6v88L7kozcW3MoO8mEgiQ

EDIT: I restarted JACK and it seems to produce some sound but still in slow motion.

[AreYouLoco]

OFTOPPIC:

When you are done with this one I am interested in buying Onyx 820i from you. I hope the sending from wherewere you are is not too expencive.

On September 21, 2021 1:31:54 PM UTC, "坂本 貴史" @.***> wrote:

And today I got similar model, Mackie Onyx 820i (OXFW971) in used market, and tested current code. As a result, current ALSA OXFW driver can successfully handle the model, unlike your Onyx 1640i.

As long as I know, below models have the similar identification information in their configuration ROM:

• Onyx 820i
• Onyx 1220i
• Onyx 1640i

They commonly have two analog output ports and the driver works with two channels of playback.

On the other hand, Onyx 1640i has 16 analog output ports. I think that OXFW 971 has some kind of quirk when configured to operate for many channels.

Anyway, I'm waiting for the dump data, thanks.

[takaswie]

Indeed I thought its switched of speakers but there is just no sound. I am using FW channels 1-2 to out. Should try on all 16?! DUMP: https://mega.nz/file/ijB3VCya#gYkSY0RJSOVkpAXmWTf7QY6v88L7kozcW3MoO8mEgiQ

EDIT: I restarted JACK and it seems to produce some sound but still in slow motion.

Thanks, however the content of packet dump indicates that it is retrieved by driver version as of https://github.com/takaswie/snd-firewire-improve/issues/38#issuecomment-917625293.

Would I ask you to reinstall the driver built at current HEAD of topic/fix-oxfw-mackie-regression branch? It's now 709535a2879d.

Regards

[AreYouLoco]

It works. But audio is distorted. Heavily. DUMP: https://mega.nz/file/L3RQQbTJ#zgMZ4ARryG0-5J9o4ZWE_l864JzMZqIRt7OV7bK-JpU

[takaswie]

It works. But audio is distorted. Heavily. DUMP: https://mega.nz/file/L3RQQbTJ#zgMZ4ARryG0-5J9o4ZWE_l864JzMZqIRt7OV7bK-JpU

Thanks. We can see apparent improvement in analysis of packet dump:

$ trace-cmd report trace.dat_distrorted > list
$ ./parse list 
ch 0:
  5 sec, 513 cycle: 44424 events
  6 sec, 513 cycle: 44048 events
  7 sec, 513 cycle: 43912 events
  0 sec, 513 cycle: 43776 events
  1 sec, 513 cycle: 43608 events
  2 sec, 513 cycle: 43864 events
  3 sec, 513 cycle: 42928 events
  4 sec, 513 cycle: 44352 events
  5 sec, 513 cycle: 43872 events
  6 sec, 513 cycle: 43200 events
  7 sec, 513 cycle: 43424 events
  0 sec, 513 cycle: 43864 events
  1 sec, 513 cycle: 44376 events
  2 sec, 513 cycle: 43520 events
  3 sec, 513 cycle: 41912 events
  4 sec, 513 cycle: 43536 events
  5 sec, 513 cycle: 42760 events
  6 sec, 513 cycle: 43736 events
ch 1:
  5 sec, 255 cycle: 44464 events
  6 sec, 255 cycle: 44032 events
  7 sec, 255 cycle: 43776 events
  0 sec, 255 cycle: 43840 events
  1 sec, 255 cycle: 43608 events
  2 sec, 255 cycle: 43896 events
  3 sec, 255 cycle: 42976 events
  4 sec, 255 cycle: 44288 events
  5 sec, 255 cycle: 43888 events
  6 sec, 255 cycle: 43152 events
  7 sec, 255 cycle: 43520 events
  0 sec, 255 cycle: 43800 events
  1 sec, 255 cycle: 44408 events
  2 sec, 255 cycle: 43480 events
  3 sec, 255 cycle: 41872 events
  4 sec, 255 cycle: 43552 events
  5 sec, 255 cycle: 42752 events
  6 sec, 255 cycle: 43744 events

However, we can also see that the media clock frequency is not stable yet. It should be near 48,000 according to current sampling transfer frequency.

Hm. In the attempt, we use 125 msec to start media clock recovery. In next attempt, let us use double duration, 250 msec. Would I request you for another test with current HEAD of the remote branch? It's now moved to 544858a14ee0.

[takaswie]

@AreYouLoco I'm sorry if you are still busy but I'd like you to test the additional patch for the issue.

Thanks.

[AreYouLoco]

@takaswie I will be on it in two weeks of time. I am sorry I cannot test it earlier. Will get to you as soon as possible after testing.

[AreYouLoco]

@takaswie I am going to test it tomorrow.

[AreYouLoco]

Yup! It seems that timing was the issue. Audio is no longer in slo-mo. Here is the dump: https://mega.nz/file/SjxUhZBQ#EV0BWx3PHKv2EFjVCQwBucpLS17jYkiIhQugBYlSyFs

Edit: I managed to happilly test it between two power shortages at my house due to the weather. Still no power at home.

EDIT 2: I was too fast to say it works. Sometimes the JACK2 daemon crashes and I am unable to restart it:

Fri Oct 22 18:09:39 2021: ------------------
Fri Oct 22 18:09:39 2021: Controller activated. Version 1.9.17 (unknown) built on Thu Jan 21 21:52:23 2021
Fri Oct 22 18:09:39 2021: Loading settings from "/home/areyouloco/.config/jack/conf.xml" using expat_2.2.10 ...
Fri Oct 22 18:09:39 2021: setting parameter 'engine':'driver':'(null)' to value "alsa"
Fri Oct 22 18:09:39 2021: setting parameter 'engine':'realtime-priority':'(null)' to value "25"
Fri Oct 22 18:09:39 2021: setting parameter 'engine':'verbose':'(null)' to value "true"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'capture' to value "hw:O1640i,0"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'playback' to value "hw:O1640i,0"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'period' to value "512"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'nperiods' to value "3"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'hwmon' to value "false"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'hwmeter' to value "false"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'inchannels' to value "16"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'outchannels' to value "16"
Fri Oct 22 18:09:39 2021: setting parameter 'drivers':'alsa':'midi-driver' to value "raw"
Fri Oct 22 18:09:39 2021: Listening for D-Bus messages
Fri Oct 22 18:09:42 2021: Starting jack server...
Fri Oct 22 18:09:42 2021: JACK server starting in realtime mode with priority 25
Fri Oct 22 18:09:42 2021: self-connect-mode is "Don't restrict self connect requests"
Fri Oct 22 18:09:42 2021: Jack: JackPosixThread::StartImp : create non RT thread
Fri Oct 22 18:09:42 2021: Jack: JackPosixThread::ThreadHandler : start
Fri Oct 22 18:09:42 2021: Jack: capture device hw:O1640i,0
Fri Oct 22 18:09:42 2021: Jack: playback device hw:O1640i,0
Fri Oct 22 18:09:42 2021: Jack: frames per period = 512
Fri Oct 22 18:09:42 2021: Jack: JackDriver::Open capture_driver_name = hw:O1640i,0
Fri Oct 22 18:09:42 2021: Jack: JackDriver::Open playback_driver_name = hw:O1640i,0
Fri Oct 22 18:09:42 2021: Jack: Check protocol client = 8 server = 8
Fri Oct 22 18:09:42 2021: Jack: JackEngine::ClientInternalOpen: name = system
Fri Oct 22 18:09:42 2021: Jack: JackEngine::AllocateRefNum ref = 0
Fri Oct 22 18:09:42 2021: Jack: JackLinuxFutex::Allocate name = jack_sem.1000_default_system val = 0
Fri Oct 22 18:09:42 2021: Jack: JackEngine::NotifyAddClient: name = system
Fri Oct 22 18:09:42 2021: Jack: JackGraphManager::SetBufferSize size = 512
Fri Oct 22 18:09:42 2021: Jack: JackConnectionManager::DirectConnect first: ref1 = 0 ref2 = 0
Fri Oct 22 18:09:42 2021: Jack: JackGraphManager::ConnectRefNum cur_index = 0 ref1 = 0 ref2 = 0
Fri Oct 22 18:09:42 2021: Jack: JackDriver::SetupDriverSync driver sem in flush mode
Fri Oct 22 18:09:47 2021: Device reservation request with priority 2147483647 denied for "Audio2": org.freedesktop.DBus.Error.NoReply (Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, 
Fri Oct 22 18:09:47 2021: ERROR: Failed to acquire device name : Audio2 error : Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broke
Fri Oct 22 18:09:47 2021: ERROR: Audio device hw:O1640i,0 cannot be acquired...
Fri Oct 22 18:09:47 2021: Jack: ~JackDriver
Fri Oct 22 18:09:47 2021: ERROR: Cannot initialize driver
Fri Oct 22 18:09:47 2021: Jack: no message buffer overruns
Fri Oct 22 18:09:47 2021: Jack: JackPosixThread::Stop
Fri Oct 22 18:09:47 2021: Jack: JackPosixThread::ThreadHandler : exit
Fri Oct 22 18:09:47 2021: ERROR: JackServer::Open failed with -1
Fri Oct 22 18:09:47 2021: Jack: Succeeded in unlocking 107341338 byte memory area
Fri Oct 22 18:09:47 2021: Jack: JackShmMem::delete size = 0 index = 0
Fri Oct 22 18:09:47 2021: Jack: ~JackDriver
Fri Oct 22 18:09:47 2021: Jack: Succeeded in unlocking 1187 byte memory area
Fri Oct 22 18:09:47 2021: Jack: JackShmMem::delete size = 0 index = 1
Fri Oct 22 18:09:47 2021: Jack: Cleaning up shared memory
Fri Oct 22 18:09:47 2021: Jack: Cleaning up files
Fri Oct 22 18:09:47 2021: Jack: Unregistering server `default'
Fri Oct 22 18:09:47 2021: ERROR: Failed to open server

Dmesg said a couple of times:

firewire_ohci 0000:0d:00.3: DMA context still active (0x00000411)
snd_oxfw fw1.0: transaction failed: bus reset

Switching back to stock kernel drives gets rid of the issue. Again switching to your driver after re-installation I am able to start/stop JACK2 but seems unstable. Will test it further.

[takaswie]

Hi,

Thanks for your test.

Yup! It seems that timing was the issue. Audio is no longer in slo-mo. Here is the dump: https://mega.nz/file/SjxUhZBQ#EV0BWx3PHKv2EFjVCQwBucpLS17jYkiIhQugBYlSyFs

$ trace-cmd report trace.dat_works > /tmp/1640i.log
$ /tmp/parse /tmp/1640i.log 
ch 0:
  6 sec, 2329 cycle: 48000 events
  7 sec, 2329 cycle: 48000 events
  0 sec, 2329 cycle: 48000 events
  1 sec, 2329 cycle: 48000 events
  2 sec, 2329 cycle: 48000 events
  3 sec, 2329 cycle: 48000 events
  4 sec, 2329 cycle: 48000 events
  5 sec, 2329 cycle: 48000 events
  6 sec, 2329 cycle: 48000 events
  7 sec, 2329 cycle: 48000 events
ch 1:
  6 sec, 2071 cycle: 48000 events
  7 sec, 2071 cycle: 48000 events
  0 sec, 2071 cycle: 48000 events
  1 sec, 2071 cycle: 48000 events
  2 sec, 2071 cycle: 48000 events
  3 sec, 2071 cycle: 48000 events
  4 sec, 2071 cycle: 48000 events
  5 sec, 2071 cycle: 48000 events
  6 sec, 2071 cycle: 48000 events
  7 sec, 2071 cycle: 48000 events

Now the device transfers events in the sequence of isochronous packet as we expected.

However we see another quirk that the device voluntarily generate bus reset so often as you report.

firewire_ohci 0000:0d:00.3: DMA context still active (0x00000411)
snd_oxfw fw1.0: transaction failed: bus reset

Hm. The patchset takes ALSA oxfw driver to postpone media clock recovery during receiving 2,000 isochronous packets in the beginning of packet streaming. The driver also transfers isochronous packet with events according to nominal sampling transmission frequency in the beginning of packet streaming, so that the device can adjust its internal state machine to determine expected media clock from the sequence of received isochronous packets.

if we can see the bus reset so often, it would mean that the above estimation and expectation are not adequate to your device. If so, we need to take ALSA oxfw driver back, not to perform media clock recovery in your device. It is the mode of the driver in stock kernel.

Anyway, we need to identify that the bus reset as the cause of disorder in jackd process. As a quick glance, you run jackd process via jackdbus interface. I'd like you to execute jackd command in terminal, then observe its runtime so that we are free from any interaction issue via inter process communication.

Thanks.

[AreYouLoco]

After reboot. I can no longer start your new driver. Weird it worked when I posted the dump (?).

So starting jackdbus with cadence:

Sat Oct 23 18:41:15 2021: Starting jack server...
Sat Oct 23 18:41:15 2021: Jack: Server `default' registered
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::InitConnections size = 19050752 
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::InitClients
Sat Oct 23 18:41:15 2021: JACK server starting in realtime mode with priority 25
Sat Oct 23 18:41:15 2021: self-connect-mode is "Don't restrict self connect requests"
Sat Oct 23 18:41:15 2021: Jack: JackShmMem::new index = 0 attached = 825d9000 size = 107341340 
Sat Oct 23 18:41:15 2021: Jack: JackShmMem::new placement size = 38108700
Sat Oct 23 18:41:15 2021: Jack: Succeeded in locking 107341340 byte memory area
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::InitConnections size = 19050752 
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::InitClients
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::InitConnections size = 19050752 
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::InitClients
Sat Oct 23 18:41:15 2021: Jack: JackShmMem::new index = 1 attached = 8d1f0000 size = 1196 
Sat Oct 23 18:41:15 2021: Jack: Succeeded in locking 1196 byte memory area
Sat Oct 23 18:41:15 2021: Jack: JackPosixThread::StartImp : create non RT thread
Sat Oct 23 18:41:15 2021: Jack: JackPosixThread::ThreadHandler : start
Sat Oct 23 18:41:15 2021: Jack: playback device hw:O1640i,0
Sat Oct 23 18:41:15 2021: Jack: capture device hw:O1640i,0
Sat Oct 23 18:41:15 2021: Jack: capture device hw:O1640i,0
Sat Oct 23 18:41:15 2021: Jack: playback device hw:O1640i,0
Sat Oct 23 18:41:15 2021: Jack: apparent rate = 48000
Sat Oct 23 18:41:15 2021: Jack: frames per period = 512
Sat Oct 23 18:41:15 2021: Jack: JackDriver::Open capture_driver_name = hw:O1640i,0
Sat Oct 23 18:41:15 2021: Jack: JackDriver::Open playback_driver_name = hw:O1640i,0
Sat Oct 23 18:41:15 2021: Jack: Check protocol client = 9 server = 9
Sat Oct 23 18:41:15 2021: Jack: JackEngine::ClientInternalOpen: name = system
Sat Oct 23 18:41:15 2021: Jack: JackEngine::AllocateRefNum ref = 0
Sat Oct 23 18:41:15 2021: Jack: JackLinuxFutex::Allocate name = jack_sem.1000_default_system val = 0
Sat Oct 23 18:41:15 2021: Jack: JackEngine::NotifyAddClient: name = system
Sat Oct 23 18:41:15 2021: Jack: JackGraphManager::SetBufferSize size = 512
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::DirectConnect first: ref1 = 0 ref2 = 0
Sat Oct 23 18:41:15 2021: Jack: JackGraphManager::ConnectRefNum cur_index = 0 ref1 = 0 ref2 = 0
Sat Oct 23 18:41:15 2021: Jack: JackDriver::SetupDriverSync driver sem in flush mode
Sat Oct 23 18:41:15 2021: Acquired audio card Audio2
Sat Oct 23 18:41:15 2021: creating alsa driver ... hw:O1640i,0|hw:O1640i,0|512|3|48000|0|0|nomon|swmeter|-|32bit
Sat Oct 23 18:41:15 2021: configuring for 48000Hz, period = 512 frames (10.7 ms), buffer = 3 periods
Sat Oct 23 18:41:15 2021: ALSA: final selected sample format for capture: 32bit integer little-endian
Sat Oct 23 18:41:15 2021: ALSA: use 3 periods for capture
Sat Oct 23 18:41:15 2021: ERROR: ALSA: cannot set hardware parameters for capture
Sat Oct 23 18:41:15 2021: ERROR: ALSA: cannot configure capture channel
Sat Oct 23 18:41:15 2021: Jack: JackDriver::Close
Sat Oct 23 18:41:15 2021: Jack: JackConnectionManager::DirectDisconnect last: ref1 = 0 ref2 = 0
Sat Oct 23 18:41:15 2021: Jack: JackGraphManager::DisconnectRefNum cur_index = 0 ref1 = 0 ref2 = 0
Sat Oct 23 18:41:15 2021: Jack: JackEngine::ClientInternalClose ref = 0
Sat Oct 23 18:41:15 2021: Jack: JackEngine::ClientCloseAux ref = 0
Sat Oct 23 18:41:15 2021: Jack: JackGraphManager::RemoveAllPorts ref = 0
Sat Oct 23 18:41:15 2021: Released audio card Audio2
Sat Oct 23 18:41:15 2021: Jack: ~JackDriver
Sat Oct 23 18:41:15 2021: ERROR: Cannot initialize driver
Sat Oct 23 18:41:15 2021: Jack: no message buffer overruns
Sat Oct 23 18:41:15 2021: Jack: JackPosixThread::Stop
Sat Oct 23 18:41:15 2021: Jack: JackPosixThread::ThreadHandler : exit
Sat Oct 23 18:41:15 2021: ERROR: JackServer::Open failed with -1
Sat Oct 23 18:41:15 2021: Jack: Succeeded in unlocking 107341340 byte memory area
Sat Oct 23 18:41:15 2021: Jack: JackShmMem::delete size = 0 index = 0
Sat Oct 23 18:41:15 2021: Jack: ~JackDriver
Sat Oct 23 18:41:15 2021: Jack: Succeeded in unlocking 1196 byte memory area
Sat Oct 23 18:41:15 2021: Jack: JackShmMem::delete size = 0 index = 1
Sat Oct 23 18:41:15 2021: Jack: Cleaning up shared memory
Sat Oct 23 18:41:15 2021: Jack: Cleaning up files
Sat Oct 23 18:41:15 2021: Jack: Unregistering server `default'
Sat Oct 23 18:41:15 2021: ERROR: Failed to open server

Starting jackd from console:

areyouloco@studio:~$ jackd -v -P25 -dalsa -r48000 -p512 -n3 -Xraw -D -dhw:O1640i,0 -I127 -O127
jackdmp 1.9.19
Copyright 2001-2005 Paul Davis and others.
Copyright 2004-2016 Grame.
Copyright 2016-2021 Filipe Coelho.
jackdmp comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details
no message buffer overruns
no message buffer overruns
no message buffer overruns
JACK server starting in realtime mode with priority 25
self-connect-mode is "Don't restrict self connect requests"
Jack: JackPosixThread::StartImp : create non RT thread
Jack: JackPosixThread::ThreadHandler : start
Jack: playback device hw:O1640i,0
Jack: capture device hw:O1640i,0
Jack: apparent rate = 48000
Jack: frames per period = 512
Jack: JackDriver::Open capture_driver_name = hw:O1640i,0
Jack: JackDriver::Open playback_driver_name = hw:O1640i,0
Jack: Check protocol client = 9 server = 9
Jack: JackEngine::ClientInternalOpen: name = system
Jack: JackEngine::AllocateRefNum ref = 0
Jack: JackLinuxFutex::Allocate name = jack_sem.1000_default_system val = 0
Jack: JackEngine::NotifyAddClient: name = system
Jack: JackGraphManager::SetBufferSize size = 512
Jack: JackConnectionManager::DirectConnect first: ref1 = 0 ref2 = 0
Jack: JackGraphManager::ConnectRefNum cur_index = 0 ref1 = 0 ref2 = 0
Jack: JackDriver::SetupDriverSync driver sem in flush mode
audio_reservation_init
Acquire audio card Audio2
creating alsa driver ... hw:O1640i,0|hw:O1640i,0|512|3|48000|0|0|nomon|swmeter|-|32bit
configuring for 48000Hz, period = 512 frames (10.7 ms), buffer = 3 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 3 periods for capture
ALSA: cannot set hardware parameters for capture
ALSA: cannot configure capture channel
Jack: JackDriver::Close
Jack: JackConnectionManager::DirectDisconnect last: ref1 = 0 ref2 = 0
Jack: JackGraphManager::DisconnectRefNum cur_index = 0 ref1 = 0 ref2 = 0
Jack: JackEngine::ClientInternalClose ref = 0
Jack: JackEngine::ClientCloseAux ref = 0
Jack: JackGraphManager::RemoveAllPorts ref = 0
Released audio card Audio2
audio_reservation_finish
Jack: ~JackDriver
Cannot initialize driver
Jack: no message buffer overruns
Jack: JackPosixThread::Stop
Jack: JackPosixThread::ThreadHandler : exit
JackServer::Open failed with -1
Jack: Succeeded in unlocking 107341340 byte memory area
Jack: JackShmMem::delete size = 0 index = 0
Jack: ~JackDriver
Jack: Succeeded in unlocking 1196 byte memory area
Jack: JackShmMem::delete size = 0 index = 1
Jack: Cleaning up shared memory
Jack: Cleaning up files
Jack: Unregistering server `default'
Failed to open server

Nothing in the dmesg this time.

[takaswie]

Thanks for the report.

areyouloco@studio:~$ jackd -v -P25 -dalsa -r48000 -p512 -n3 -Xraw -D -dhw:O1640i,0 -I127 -O127
...
creating alsa driver ... hw:O1640i,0|hw:O1640i,0|512|3|48000|0|0|nomon|swmeter|-|32bit
configuring for 48000Hz, period = 512 frames (10.7 ms), buffer = 3 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 3 periods for capture
ALSA: cannot set hardware parameters for capture
...
Failed to open server

I guess the runtime of jackd received failure by call of ioctl with SNDRV_PCM_IOCTL_HW_PARAMS request. Typically, the error code is -ETIMEDOUT.

Would I ask you to test jackd with strace(1) command and gather logs? The command line should be:

$ strace -tt -f jackd -v -P25 -dalsa -r48000 -p512 -n3 -Xraw -D -dhw:O1640i,0 -I127 -O127 2> /tmp/log

When the ioctl call returns -ETIMEDOUT, it means that ALSA oxfw driver doesn't start packet processing within 200 msec after starting packet streaming. It's my shame, but as we applied a patch to expand initial cycles to skip processing isochronous packets transferred by the device during 2000 isochronous cycles (=250msec), the 200 msec timeout can cause the issue.

Would I request you to test jackd runtime with below patch?

diff --git a/sound/firewire/oxfw/oxfw-stream.c b/sound/firewire/oxfw/oxfw-stream.c
index 206684b..9d913e7 100644
--- a/sound/firewire/oxfw/oxfw-stream.c
+++ b/sound/firewire/oxfw/oxfw-stream.c
@@ -9,7 +9,7 @@
 #include <linux/delay.h>

 #define AVC_GENERIC_FRAME_MAXIMUM_BYTES        512
-#define READY_TIMEOUT_MS       200
+#define READY_TIMEOUT_MS       500

 /*
  * According to datasheet of Oxford Semiconductor:

Thanks for your cooperation.

[AreYouLoco]

I am amazed how good you know your code. I've edited the file by hand. It helped because with this patch jack starts/stops just fine with cadence BUT the audio is distorted and playback produces constant xruns. Stock driver works just fine. I also greped /tmp/log there is no ETIMEDOUT there with last patch.

EDIT: I've tried setting bigger buffers/periods still the audio is distorted.

[takaswie]

EDIT: I've tried setting bigger buffers/periods still the audio is distorted.

Hm. As long as I know, jackd runs with asynchronous mode as a default, however it brings issues at thread wakeup timing between audio graph processing and PCM frame processing. Synchronous mode (-S) can suppress the issue. Would you test again with the option? The command line is like:

$ jackd -v -S -P25 -dalsa -r48000 -p512 -n3 -Xraw -D -dhw:O1640i,0

[AreYouLoco]

I've tried with option Server Synchronous Mode ticked in cadence configuration screen.

Still with that option on/off the audio is distorted in the same way. I am switching back to stock driver.

[takaswie]

Still with that option on/off the audio is distorted in the same way.

Hm. Would I ask you to retrieve packet dump when encountering the distorsion?

[AreYouLoco]

Distorted dump: https://mega.nz/file/XnJ3BS6A#YmsYIS8PMswKvwn729N44Qbpj73-6f0mJR9cq5ctHek

Log from parse.py:

ch 0:
  5 sec, 3507 cycle: 43768 events
  6 sec, 3507 cycle: 43496 events
  7 sec, 3507 cycle: 43112 events
  0 sec, 3507 cycle: 43624 events
  1 sec, 3507 cycle: 44368 events
  2 sec, 3507 cycle: 44856 events
  3 sec, 3507 cycle: 43272 events
  4 sec, 3507 cycle: 44480 events
  5 sec, 3507 cycle: 43984 events
ch 1:
  5 sec, 3250 cycle: 43864 events
  6 sec, 3250 cycle: 43440 events
  7 sec, 3250 cycle: 43096 events
  0 sec, 3250 cycle: 43680 events
  1 sec, 3250 cycle: 44312 events
  2 sec, 3250 cycle: 44888 events
  3 sec, 3250 cycle: 43216 events
  4 sec, 3250 cycle: 44504 events
  5 sec, 3250 cycle: 43936 events

[takaswie]

Distorted dump: https://mega.nz/file/XnJ3BS6A#YmsYIS8PMswKvwn729N44Qbpj73-6f0mJR9cq5ctHek

Log from parse.py:

ch 0:
  5 sec, 3507 cycle: 43768 events
  6 sec, 3507 cycle: 43496 events
  7 sec, 3507 cycle: 43112 events
  0 sec, 3507 cycle: 43624 events
  1 sec, 3507 cycle: 44368 events
  2 sec, 3507 cycle: 44856 events
  3 sec, 3507 cycle: 43272 events
  4 sec, 3507 cycle: 44480 events
  5 sec, 3507 cycle: 43984 events
ch 1:
  5 sec, 3250 cycle: 43864 events
  6 sec, 3250 cycle: 43440 events
  7 sec, 3250 cycle: 43096 events
  0 sec, 3250 cycle: 43680 events
  1 sec, 3250 cycle: 44312 events
  2 sec, 3250 cycle: 44888 events
  3 sec, 3250 cycle: 43216 events
  4 sec, 3250 cycle: 44504 events
  5 sec, 3250 cycle: 43936 events

Thanks. I got the same result from the dump data.

Hm. As I noted, media clock recovery in ALSA oxfw driver begin after receiving 2000 isochronous packets from the device so that the state machine of OXFW971 ASIC becomes ready to process events as expected frequency by receiving isochronous packets from the driver.

However, it seems to fail. the state machine is still unstable in regard of generation of event frequency.

Hm. I think it better to give up media clock recovery in the device. Let us back to previous mode in stock kernel.

Fortunately, we are near the last week to official release of Linux kernel v5.15. It's probable to put fix for the issue to v5.15 as long as I promptly write and post patch. I'll test the patch in my Onyx 820i with small customization but it's preferable for you to test it as well.

I'll post new message after preparing for the patch.

Thanks.

[AreYouLoco]

Ok, waiting to pull it from the repo.

[takaswie]

Hi @AreYouLoco ,

Fortunately, we are near the last week to official release of Linux kernel v5.15. It's probable to put fix for the issue to v5.15 as long as I promptly write and post patch. I'll test the patch in my Onyx 820i with small customization but it's preferable for you to test it as well.

I move HEAD of topic/fix-oxfw-mackie-regression into fa7bafa69052 by force-pushing. Would you please test the single patch, and gather/share packet dump as we did?

Thanks

[AreYouLoco]

HEAD is now at fa7bafa oxfw: fix functional regression for Mackie Onyx 1640i in v5.14 or later

areyouloco@studio:~/code/snd-firewire-improve$ ./parse.py ./tmp.log
ch 0:
  6 sec, 7677 cycle: 48000 events
  7 sec, 7677 cycle: 48000 events
  0 sec, 7677 cycle: 48000 events
  1 sec, 7677 cycle: 48000 events
  2 sec, 7677 cycle: 48000 events
  3 sec, 7677 cycle: 48000 events
  4 sec, 7677 cycle: 48000 events
  5 sec, 7677 cycle: 48000 events
  6 sec, 7677 cycle: 48000 events
  7 sec, 7677 cycle: 48000 events
  0 sec, 7677 cycle: 48000 events
  1 sec, 7677 cycle: 48000 events
  2 sec, 7677 cycle: 48000 events
  3 sec, 7677 cycle: 48000 events
  4 sec, 7677 cycle: 48000 events
  5 sec, 7677 cycle: 48000 events
ch 1:
  6 sec, 7547 cycle: 48000 events
  7 sec, 7547 cycle: 48000 events
  0 sec, 7547 cycle: 48000 events
  1 sec, 7547 cycle: 48000 events
  2 sec, 7547 cycle: 48000 events
  3 sec, 7547 cycle: 48000 events
  4 sec, 7547 cycle: 48000 events
  5 sec, 7547 cycle: 48000 events
  6 sec, 7547 cycle: 48000 events
  7 sec, 7547 cycle: 48000 events
  0 sec, 7547 cycle: 48000 events
  1 sec, 7547 cycle: 48000 events
  2 sec, 7547 cycle: 48000 events
  3 sec, 7547 cycle: 48000 events
  4 sec, 7547 cycle: 48000 events
  5 sec, 7547 cycle: 48000 events

It produces some XRUNs at start (around 25 this time with 256 buffer 3 period) the audio sounds good. And the log from parse.py looks good as well.

DUMP: https://mega.nz/file/DrAm3TLT#oXOTiPllBDwlVWnw6H1Ar6soje8YeSxichi02i4zDFI

[takaswie]

areyouloco@studio:~/code/snd-firewire-improve$ ./parse.py ./tmp.log
ch 0:
  6 sec, 7677 cycle: 48000 events
  7 sec, 7677 cycle: 48000 events
  0 sec, 7677 cycle: 48000 events
  1 sec, 7677 cycle: 48000 events
  2 sec, 7677 cycle: 48000 events
  3 sec, 7677 cycle: 48000 events
  4 sec, 7677 cycle: 48000 events
  5 sec, 7677 cycle: 48000 events
  6 sec, 7677 cycle: 48000 events
  7 sec, 7677 cycle: 48000 events
  0 sec, 7677 cycle: 48000 events
  1 sec, 7677 cycle: 48000 events
  2 sec, 7677 cycle: 48000 events
  3 sec, 7677 cycle: 48000 events
  4 sec, 7677 cycle: 48000 events
  5 sec, 7677 cycle: 48000 events
ch 1:
  6 sec, 7547 cycle: 48000 events
  7 sec, 7547 cycle: 48000 events
  0 sec, 7547 cycle: 48000 events
  1 sec, 7547 cycle: 48000 events
  2 sec, 7547 cycle: 48000 events
  3 sec, 7547 cycle: 48000 events
  4 sec, 7547 cycle: 48000 events
  5 sec, 7547 cycle: 48000 events
  6 sec, 7547 cycle: 48000 events
  7 sec, 7547 cycle: 48000 events
  0 sec, 7547 cycle: 48000 events
  1 sec, 7547 cycle: 48000 events
  2 sec, 7547 cycle: 48000 events
  3 sec, 7547 cycle: 48000 events
  4 sec, 7547 cycle: 48000 events
  5 sec, 7547 cycle: 48000 events

It produces some XRUNs at start (around 25 this time with 256 buffer 3 period) the audio sounds good. And the log from parse.py looks good as well.

DUMP: https://mega.nz/file/DrAm3TLT#oXOTiPllBDwlVWnw6H1Ar6soje8YeSxichi02i4zDFI

Thanks for your test. For further investigation about the XRUNs in the beginning of packet streaming, would I ask you to start packet dump process before executing jackd? Like:

(power off the device)
$ sudo modprobe -r snd-oxfw snd-firewire-lib
$ sudo modprobe snd-firewire-lib
$ sudo trace-cmd record -e snd_firewire_lib:amdtp_packet
(open another terminal)
(power on the device)
$ sudo modprobe snd-oxfw
$ jackd -v -S -r -dalsa -dhw:O1640i,0 -r48000 -p512 -n3
(back to the first terminal, then stop trace-cmd process by ctrl + C)

[AreYouLoco]

It was luck again. I cannot start jack without constant XRUNs appearing. I tried to start/stop jack a few times because with stock kernel driver it worked at some point but this time not. I do get XRUNs all the time. I recorded dump and log from parse.py looks like this:

areyouloco@studio:~/code/snd-firewire-improve$ ./parse.py ./tmp.log
ch 0:
  discontinue
  discontinue
  discontinue
  1 sec, 3759 cycle: 44112 events
  discontinue
  discontinue
  2 sec, 4914 cycle: 44104 events
  3 sec, 4914 cycle: 44104 events
  4 sec, 4914 cycle: 44096 events
  5 sec, 4914 cycle: 44104 events
  6 sec, 4914 cycle: 44096 events
  discontinue
  discontinue
  6 sec, 5822 cycle: 45560 events
  7 sec, 5822 cycle: 48000 events
  0 sec, 5822 cycle: 48000 events
  1 sec, 5822 cycle: 48000 events
  2 sec, 5822 cycle: 48000 events
  3 sec, 5822 cycle: 48000 events
  discontinue
  discontinue
  5 sec, 2514 cycle: 48000 events
  6 sec, 2514 cycle: 48000 events
  7 sec, 2514 cycle: 48000 events
  0 sec, 2514 cycle: 48000 events
  1 sec, 2514 cycle: 48000 events
  2 sec, 2514 cycle: 48000 events
  discontinue
  discontinue
  3 sec, 5671 cycle: 48008 events
  4 sec, 5671 cycle: 48000 events
  5 sec, 5671 cycle: 48000 events
  6 sec, 5671 cycle: 48000 events
  7 sec, 5671 cycle: 48000 events
  0 sec, 5671 cycle: 48000 events
  discontinue
  discontinue
  3 sec, 7120 cycle: 48000 events
  4 sec, 7120 cycle: 48000 events
  5 sec, 7120 cycle: 48000 events
  6 sec, 7120 cycle: 48000 events
  discontinue
  discontinue
  0 sec, 3239 cycle: 48008 events
  1 sec, 3239 cycle: 48000 events
  2 sec, 3239 cycle: 48000 events
  3 sec, 3239 cycle: 48000 events
  4 sec, 3239 cycle: 48000 events
  discontinue
  6 sec, 952 cycle: 48000 events
  discontinue
  7 sec, 953 cycle: 48000 events
  0 sec, 953 cycle: 48000 events
  1 sec, 953 cycle: 48000 events
  2 sec, 953 cycle: 48000 events
  3 sec, 953 cycle: 48000 events
  4 sec, 953 cycle: 48000 events
  5 sec, 953 cycle: 48000 events
  6 sec, 953 cycle: 48000 events
  7 sec, 953 cycle: 48000 events
  discontinue
  discontinue
  0 sec, 6244 cycle: 48008 events
  1 sec, 6244 cycle: 48000 events
  2 sec, 6244 cycle: 48000 events
  3 sec, 6244 cycle: 48000 events
  4 sec, 6244 cycle: 48000 events
  5 sec, 6244 cycle: 48000 events
  6 sec, 6244 cycle: 48000 events
  7 sec, 6244 cycle: 48000 events
  0 sec, 6244 cycle: 48000 events
ch 1:
  discontinue
  discontinue
  3 sec, 169 cycle: 27528 events
  4 sec, 169 cycle: 35016 events
  5 sec, 169 cycle: 27904 events
  6 sec, 169 cycle: 27544 events
  7 sec, 169 cycle: 27552 events
  discontinue
  7 sec, 5694 cycle: 29496 events
  0 sec, 5694 cycle: 29440 events
  1 sec, 5694 cycle: 29120 events
  2 sec, 5694 cycle: 29024 events
  3 sec, 5694 cycle: 29584 events
  discontinue
  5 sec, 6387 cycle: 28992 events
  6 sec, 6387 cycle: 29848 events
  7 sec, 6387 cycle: 29320 events
  0 sec, 6387 cycle: 29384 events
  1 sec, 6387 cycle: 29224 events
  discontinue
  3 sec, 5545 cycle: 29376 events
  4 sec, 5545 cycle: 29392 events
  5 sec, 5545 cycle: 29416 events
  6 sec, 5545 cycle: 30104 events
  7 sec, 5545 cycle: 29592 events
  0 sec, 5545 cycle: 29504 events
  discontinue
  4 sec, 2867 cycle: 29696 events
  5 sec, 2867 cycle: 29648 events
  6 sec, 2867 cycle: 29648 events
  discontinue
  0 sec, 2987 cycle: 34576 events
  1 sec, 2987 cycle: 31480 events
  2 sec, 2987 cycle: 29288 events
  3 sec, 2987 cycle: 29680 events
  4 sec, 2987 cycle: 29648 events
  discontinue
  6 sec, 4702 cycle: 29288 events
  7 sec, 4702 cycle: 29168 events
  0 sec, 4702 cycle: 29592 events
  1 sec, 4702 cycle: 29400 events
  2 sec, 4702 cycle: 30440 events
  3 sec, 4702 cycle: 29736 events
  4 sec, 4702 cycle: 29264 events
  5 sec, 4702 cycle: 30088 events
  6 sec, 4702 cycle: 29088 events
  7 sec, 4702 cycle: 29936 events
  discontinue
  1 sec, 5994 cycle: 29088 events
  2 sec, 5994 cycle: 29736 events
  3 sec, 5994 cycle: 29696 events
  4 sec, 5994 cycle: 29608 events
  5 sec, 5994 cycle: 29336 events
  6 sec, 5994 cycle: 29368 events
  7 sec, 5994 cycle: 29648 events
  0 sec, 5994 cycle: 29576 events

I restarted jack a few times so that's why there is discontinue I think. But it seems like packet stream is not so stable 48000 events. I am going to try to start jack until XRUNs won't appear constantly just at start and let you know.

EDIT: I do get constant XRUNs when jack is running. Tries in Synchronous and Asynchronous mode. Around 20 xruns a second. The audio is mostly pops and clicks not an audio output that I would expect. Stock driver works after few times jack is restarted.

[takaswie]

Thanks for the test, however the dump data includes more information than what we can see in output from the parse script. It's the most preferable to share the dump data by any way.

It looks a bug which we encounter long ago. I update HEAD of remote branch to 5ae8bcd3e4a02af6e9735e748cf8d92ab04d071a. Would you please test with it by test procedure to which I address in previous message?

[AreYouLoco]

HEAD is now at 5ae8bcd oxfw: fix functional regression for Mackie Onyx 1640i in v5.14 or later

0 XRUNs at start 0 XRUNs during the playback; audio sounds good. I can go as low as 256 samples 3 periods without XRUNs. I will try to stop/start a few times and try in the long run. Here is the dump so far: https://mega.nz/file/bjQWiTAC#YVXtUJGunTl-CbAOviobHwW9nLRX4VPqUQJ9vRptU8U

EDIT: When I start/stop jack sometimes there are constant XRUNs appearing but one every few tries produces no XRUNs at start and no XRUNs when playing. Most often 0 XRUNs. The driver seems OK now. I think we reached near 0 XRUNs setup.

I even tried with 128 samples 3 periods (even 64 samples 3 periods, that is 1.3ms block latency!) and I do get 0 XRUNs most often. Nice!

[takaswie]

Great.

I still have concern about the state of packets in the beginning of packet streaming. Would you get packet dump by the way in https://github.com/takaswie/snd-firewire-improve/issues/38#issuecomment-953424801?

[AreYouLoco]

I still have concern about the state of packets in the beginning of packet streaming.

Packet dump while doing the sequence from https://github.com/takaswie/snd-firewire-improve/issues/38#issuecomment-953424801 : https://mega.nz/file/uvZUVRDL#fgBXd9srNYtjHsUyiLW5n1uORgBRwdHW6czGHYF6Nqs

Still 0 XRUNs produced at start and when playing when doing your instructions.

[takaswie]

https://mega.nz/file/uvZUVRDL#fgBXd9srNYtjHsUyiLW5n1uORgBRwdHW6czGHYF6Nqs

Thanks. It looks well to me.

I sent the fix to upstream. https://lore.kernel.org/alsa-devel/20211028130325.45772-1-o-takashi@sakamocchi.jp/T/#u

[takaswie]

The patch is merged to Linux sound subsystem and waiting for Linux kernel v5.16 prepatch:

• https://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound.git/commit/?id=cddcd5472abb7b8a9c37ccbcf0908b79740a01b5

[takaswie]

Now the patch is queued for linux-stable v5.14 and v5.15:

• Fixes for 5.14
  • https://git.kernel.org/pub/scm/linux/kernel/git/stable/stable-queue.git/commit/?id=85d6f5e6a4cfcd22a95d46571ea02cf6b67d457d
• Fixes for 5.15
  • https://git.kernel.org/pub/scm/linux/kernel/git/stable/stable-queue.git/commit/?id=179756d16045dc3812227354f3432c061f4403aa

[AreYouLoco]

Nice!

[takaswie]

Linux v5.16-rc1 is out with the patch:

• https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tag/?h=v5.16-rc1

[takaswie]

Below stable kernels are out including the fix.

• Linux 5.14.20

  • https://lore.kernel.org/lkml/1637244207253142@kroah.com/

• Linux 5.15.3

  • https://lore.kernel.org/lkml/163726325011777@kroah.com/

Let me close the issue, thanks.