Giter Club home page Giter Club logo

Comments (45)

takaswie avatar takaswie commented on September 28, 2024 1

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.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024 1

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

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

Thanks

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

@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)

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024 
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.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024 
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?

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

@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?

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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?

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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 #38 (comment).

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

Regards

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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 544858a.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

Thanks.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

@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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

@takaswie I am going to test it tomorrow.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

Screenshot from 2021-10-24 17-08-38

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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?

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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.

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

Ok, waiting to pull it from the repo.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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 fa7bafa by force-pushing. Would you please test the single patch, and gather/share packet dump as we did?

Thanks

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024 
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)

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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.

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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 5ae8bcd. Would you please test with it by test procedure to which I address in previous message?

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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!

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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 #38 (comment)?

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

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

Packet dump while doing the sequence from #38 (comment) :
https://mega.nz/file/uvZUVRDL#fgBXd9srNYtjHsUyiLW5n1uORgBRwdHW6czGHYF6Nqs

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

Thanks. It looks well to me.

I sent the fix to upstream.
https://lore.kernel.org/alsa-devel/[email protected]/T/#u

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

from linux-firewire-dkms.

AreYouLoco avatar AreYouLoco commented on September 28, 2024

Nice!

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

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

from linux-firewire-dkms.

takaswie avatar takaswie commented on September 28, 2024

Below stable kernels are out including the fix.

Let me close the issue, thanks.

from linux-firewire-dkms.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.