search

takaswie / linux-firewire-dkms

Currently this repository is maintained for Linux firewire subsystem and unit drivers.
http://ieee1394.docs.kernel.org/
39 stars 8 forks source link

Sample rate problem with Terratec Phase 88 #8

Closed muranyia closed 8 years ago

muranyia commented 9 years ago

I have set the sample rate to 48000 with ffado-mixer and tried to play a 44100 sound file, and got an error. Now no matter if I set the sample rate back to 44100 I get the same error.

aplay -vv -Dplughw:0,0 test.wav 
Playing WAVE 'test' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
aplay: set_params:1297: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 32
CHANNELS: 2
RATE: 44100
PERIOD_TIME: (46439 46440)
PERIOD_SIZE: 2048
PERIOD_BYTES: 8192
PERIODS: 4
BUFFER_TIME: (185759 185760)
BUFFER_SIZE: 8192
BUFFER_BYTES: 32768
TICK_TIME: 0
$ cat /proc/asound/card0/firewire/clock
Sampling rate: 44100
Clock Source: Internal
takaswie commented 9 years ago

Can you see some logs in /var/log/syslog or dmesg?

muranyia commented 9 years ago

Unfortunately there was nothing in syslog or dmesg when aplay failed.

Interestingly, however, my graphical login prompt disappeared (black screen with cursor) at the next restart (tried several times). I restarted without the Phase 88 plugged in and the problem went away. Then I restarted with the Phase 88 plugged in, and when the login prompt disappeared I plugged the Phase 88 out. The login prompt reappeared.

Now I am looking at syslog and when I plug the Phase 88 in, I get this message:

Oct  7 18:56:04 zero kernel: [  181.502167] firewire_ohci 0000:01:0a.2: isochronous cycle inconsistent
Oct  7 18:56:05 zero kernel: [  182.159052] firewire_core 0000:01:0a.2: created device fw3: GUID 000aac0300592827, S400
Oct  7 18:56:05 zero kernel: [  182.159070] firewire_core 0000:01:0a.2: phy config: new root=ffc1, gap_count=5

Furthermore, when I try to play a sound, now I get this message:

$ aplay -vv -Dplughw:0,0 test.wav 
aplay: main:722: audio open error: Device or resource busy

And I get this message repeatedly in syslog:

Oct  7 18:57:01 zero pulseaudio[2536]: [pulseaudio] module-alsa-card.c: Failed to find a working profile.
Oct  7 18:57:01 zero pulseaudio[2536]: [pulseaudio] module.c: Failed to load module "module-alsa-card" (argument: "device_id="0" name="firewire-0x000aac0300592827" card_name="alsa_card.firewire-0x000aac0300592827" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes use_ucm=yes card_properties="module-udev-detect.discovered=1""): initialization failed.

Then I power cycled the Phase 88, syslog said:

Oct  7 19:06:54 zero kernel: [  831.888124] firewire_core 0000:01:0a.2: rediscovered device fw2
Oct  7 19:06:54 zero kernel: [  831.888157] firewire_core 0000:01:0a.2: phy config: new root=ffc1, gap_count=5
Oct  7 19:06:57 zero kernel: [  835.072115] firewire_core 0000:01:0a.2: phy config: new root=ffc1, gap_count=5
Oct  7 19:07:01 zero kernel: [  838.210649] firewire_core 0000:01:0a.2: created device fw3: GUID 000aac0300592827, S400

...and aplay went as far as:

$ aplay -vvvv -Dplughw:0,0 test.wav 
Playing WAVE 'test.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Plug PCM: Route conversion PCM (sformat=S16_LE)
  Transformation table:
    0 <- 0
    1 <- 1
    2 <- none
    3 <- none
    4 <- none
    5 <- none
    6 <- none
    7 <- none
    8 <- none
    9 <- none
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 8192
  period_size  : 2048
  period_time  : 46439
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 2048
  period_event : 0
  start_threshold  : 8192
  stop_threshold   : 8192
  silence_threshold: 0
  silence_size : 0
  boundary     : 4611686018427387904
Slave: Hardware PCM card 0 'PHASE 88 Rack FW' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 10
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 8192
  period_size  : 2048
  period_time  : 46439
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 2048
  period_event : 0
  start_threshold  : 8192
  stop_threshold   : 8192
  silence_threshold: 0
  silence_size : 0
  boundary     : 4611686018427387904
  appl_ptr     : 0
  hw_ptr       : 0

...but apparently not playing.

takaswie commented 9 years ago

Hm.

At first, please kill PulseAudio. Follow to this instruction: https://wiki.ubuntu.com/PulseAudio/Log

This will resolve your issue of login prompt.

Secondly, please confirm whether you can playback with aplay successfully but your device generates no sound, or you always fail to playback with aplay.

muranyia commented 9 years ago

After following the PulseAudio advice I managed to boot with the Phase 88 plugged in. Aplay failed playing with 00%. I noticed however, that the LEDs on the back of the Phase 88 showed Wordclock sync and no Firewire connection. Then I unplugged and replugged the Phase 88, the LEDs changed to show Standalone Mode. Then I powered off and on the Phase 88, which resulted in the LEDs indicating Firewire connection. Now aplay is playing, no sound. (Interestingly, now the Firewire LED is not on any more, but aplay plays.) I had the impression that plugging in produces worse results than powering the Phase 88 off and on, but then I repeated powering on-off and playing a few times, and it seems that it is not consistent. (Honestly, it is a chaos for me at the moment.) One thing seems to be consistent: when isochronous cycle inconsistent appears in syslog upon connection, aplay will fail with 00%. I will be happy to execute a more logical testing workflow if you suggest one.

About no sound: is it normal that ffado-mixer mentions negative values for volume?

11947809599: Debug (bebob_mixer.cpp)[ 215] setValue: Set feature volume 1 to -32622...
muranyia commented 9 years ago

Update: the last connection did not show isochronous cycle inconsistent, aplay played, but a few minutes later it failed with 00%. So it is chaotic indeed.

takaswie commented 9 years ago

After following the PulseAudio advice I managed to boot with the Phase 88 plugged in.

OK. The old release of PulseAudio causes this issue for any of FireWire audio devices with ALSA driver, PulseAudio is basically designed to handle usual surround devices (2.1ch, 5.1ch, 7.1ch and so on). But most of FireWire devices are designed for studio recording, and in most case they don't follow any surround standards.

About no sound: is it normal that ffado-mixer mentions negative values for volume? 11947809599: Debug (bebob_mixer.cpp)[ 215] setValue: Set feature volume 1 to -32622...

For this functionality, ffado-mixer uses Feature Function Block command of AV/C Audio Subunit specification. This specification is not public, but I managed to describe its overview in this page: http://subversion.ffado.org/wiki/BebobAvc

The "-32622" equals 0xFF6E. For Volume control, this means -0.5655dB and valid valie, I think.

Aplay failed playing with 00%.

Hm. We should do further investigation. Would you please do this process?

  1. give debug parameter for 'firewire-ohci' module: $ echo 1 > /sys/module/firewire_ohci/parameters/debug 2.run aplay or arecord (and fail) 3.send syslog message to me

If you want to know the meaning of this parameter, please see: $ modinfo firewire-ohci

Recently, the other user follow this process and give enough information to me. FYI: http://sourceforge.net/p/ffado/mailman/ffado-user/thread/20140918212434.GL668%40incendio.no/#msg32846563

takaswie commented 9 years ago

And please try "jackd with firewire backend" (FFADO is used) and report the result.

If both ALSA and FFADO fail to handle the device, it means the cause is not in drivers, maybe in lower layer. In this case, please tell me what IEEE 1394 interface you use.

muranyia commented 9 years ago

OK. The old release of PulseAudio causes this issue for any of FireWire audio devices with ALSA driver, PulseAudio is basically designed to handle usual surround devices (2.1ch, 5.1ch, 7.1ch and so on). But most of FireWire devices are designed for studio recording, and in most case they don't follow any surround standards.

NB I have applied the changes suggested here

The "-32622" equals 0xFF6E. For Volume control, this means -0.5655dB and valid valie, I think.

Yes. The maximum value in ffado-mixer is -32 767 = -0x7FFF, the document says it is invalid...?

  1. give debug parameter for 'firewire-ohci' module: $ echo 1 > /sys/module/firewire_ohci/parameters/debug 2.run aplay or arecord (and fail) 3.send syslog message to me
Oct  9 13:22:34 zero kernel: [ 5124.343401] firewire_ohci 0000:01:0a.2: AT spd 2 tl 00, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.344081] firewire_ohci 0000:01:0a.2: AR spd 2 tl 00, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.346579] firewire_ohci 0000:01:0a.2: AR spd 2 tl 27, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 9,0
Oct  9 13:22:34 zero kernel: [ 5124.346618] firewire_ohci 0000:01:0a.2: AT spd 2 tl 27, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.346632] firewire_ohci 0000:01:0a.2: AT spd 2 tl 01, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.347534] firewire_ohci 0000:01:0a.2: AR spd 2 tl 01, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.351359] firewire_ohci 0000:01:0a.2: AR spd 2 tl 28, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 9,0
Oct  9 13:22:34 zero kernel: [ 5124.351391] firewire_ohci 0000:01:0a.2: AT spd 2 tl 28, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.351412] firewire_ohci 0000:01:0a.2: AT spd 2 tl 02, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.352408] firewire_ohci 0000:01:0a.2: AR spd 2 tl 02, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.354385] firewire_ohci 0000:01:0a.2: AR spd 2 tl 29, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.354416] firewire_ohci 0000:01:0a.2: AT spd 2 tl 29, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.354431] firewire_ohci 0000:01:0a.2: AT spd 2 tl 03, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.355423] firewire_ohci 0000:01:0a.2: AR spd 2 tl 03, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.357370] firewire_ohci 0000:01:0a.2: AR spd 2 tl 2a, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.357403] firewire_ohci 0000:01:0a.2: AT spd 2 tl 2a, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.370234] firewire_ohci 0000:01:0a.2: AT spd 2 tl 04, ffc1 -> ffc0, ack_pending , QR req, fffff0000904
Oct  9 13:22:34 zero kernel: [ 5124.370400] firewire_ohci 0000:01:0a.2: AR spd 2 tl 04, ffc0 -> ffc1, ack_complete, QR resp = 80009482
Oct  9 13:22:34 zero kernel: [ 5124.370452] firewire_ohci 0000:01:0a.2: AT spd 2 tl 05, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.371083] firewire_ohci 0000:01:0a.2: AR spd 2 tl 05, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.372705] firewire_ohci 0000:01:0a.2: AR spd 2 tl 2b, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.372741] firewire_ohci 0000:01:0a.2: AT spd 2 tl 2b, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.372755] firewire_ohci 0000:01:0a.2: AT spd 2 tl 06, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.373822] firewire_ohci 0000:01:0a.2: AR spd 2 tl 06, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.375527] firewire_ohci 0000:01:0a.2: AR spd 2 tl 2c, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.375558] firewire_ohci 0000:01:0a.2: AT spd 2 tl 2c, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.375574] firewire_ohci 0000:01:0a.2: AT spd 2 tl 07, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.376415] firewire_ohci 0000:01:0a.2: AR spd 2 tl 07, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.393159] firewire_ohci 0000:01:0a.2: AR spd 2 tl 2d, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.393190] firewire_ohci 0000:01:0a.2: AT spd 2 tl 2d, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.393202] firewire_ohci 0000:01:0a.2: AT spd 2 tl 08, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.394243] firewire_ohci 0000:01:0a.2: AR spd 2 tl 08, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.406963] firewire_ohci 0000:01:0a.2: AR spd 2 tl 2e, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 8,0
Oct  9 13:22:34 zero kernel: [ 5124.406997] firewire_ohci 0000:01:0a.2: AT spd 2 tl 2e, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.708103] firewire_ohci 0000:01:0a.2: AT spd 2 tl 0c, ffc1 -> ffc0, ack_pending , Lk req, fffff0000904 8,2
Oct  9 13:22:34 zero kernel: [ 5124.708308] firewire_ohci 0000:01:0a.2: AR spd 2 tl 0c, ffc0 -> ffc1, ack_complete, Lk resp 4,2
Oct  9 13:22:34 zero kernel: [ 5124.708456] firewire_ohci 0000:01:0a.2: AT spd 2 tl 11, ffc1 -> ffc0, ack_pending , Lk req, fffff0000984 8,2
Oct  9 13:22:34 zero kernel: [ 5124.708597] firewire_ohci 0000:01:0a.2: AR spd 2 tl 11, ffc0 -> ffc1, ack_complete, Lk resp 4,2
Oct  9 13:22:34 zero kernel: [ 5124.708699] firewire_ohci 0000:01:0a.2: AT spd 2 tl 12, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.710379] firewire_ohci 0000:01:0a.2: AR spd 2 tl 12, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.715146] firewire_ohci 0000:01:0a.2: AR spd 2 tl 2f, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 29,0
Oct  9 13:22:34 zero kernel: [ 5124.715181] firewire_ohci 0000:01:0a.2: AT spd 2 tl 2f, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.715208] firewire_ohci 0000:01:0a.2: AT spd 2 tl 13, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.716642] firewire_ohci 0000:01:0a.2: AR spd 2 tl 13, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.722225] firewire_ohci 0000:01:0a.2: AR spd 2 tl 30, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 18,0
Oct  9 13:22:34 zero kernel: [ 5124.722267] firewire_ohci 0000:01:0a.2: AT spd 2 tl 30, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.722385] firewire_ohci 0000:01:0a.2: AT spd 2 tl 14, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.723288] firewire_ohci 0000:01:0a.2: AR spd 2 tl 14, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.725681] firewire_ohci 0000:01:0a.2: AR spd 2 tl 31, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 18,0
Oct  9 13:22:34 zero kernel: [ 5124.725720] firewire_ohci 0000:01:0a.2: AT spd 2 tl 31, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.725749] firewire_ohci 0000:01:0a.2: AT spd 2 tl 15, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.726946] firewire_ohci 0000:01:0a.2: AR spd 2 tl 15, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.729513] firewire_ohci 0000:01:0a.2: AR spd 2 tl 32, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 18,0
Oct  9 13:22:34 zero kernel: [ 5124.729548] firewire_ohci 0000:01:0a.2: AT spd 2 tl 32, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.729564] firewire_ohci 0000:01:0a.2: AT spd 2 tl 16, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.730681] firewire_ohci 0000:01:0a.2: AR spd 2 tl 16, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.733094] firewire_ohci 0000:01:0a.2: AR spd 2 tl 33, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 18,0
Oct  9 13:22:34 zero kernel: [ 5124.733127] firewire_ohci 0000:01:0a.2: AT spd 2 tl 33, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.733145] firewire_ohci 0000:01:0a.2: AT spd 2 tl 17, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.734268] firewire_ohci 0000:01:0a.2: AR spd 2 tl 17, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.738145] firewire_ohci 0000:01:0a.2: AR spd 2 tl 34, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 15,0
Oct  9 13:22:34 zero kernel: [ 5124.738186] firewire_ohci 0000:01:0a.2: AT spd 2 tl 34, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.738202] firewire_ohci 0000:01:0a.2: AT spd 2 tl 18, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.739245] firewire_ohci 0000:01:0a.2: AR spd 2 tl 18, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.741633] firewire_ohci 0000:01:0a.2: AR spd 2 tl 35, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 1a,0
Oct  9 13:22:34 zero kernel: [ 5124.741694] firewire_ohci 0000:01:0a.2: AT spd 2 tl 35, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.767403] firewire_ohci 0000:01:0a.2: AT spd 2 tl 19, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.768076] firewire_ohci 0000:01:0a.2: AR spd 2 tl 19, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.770846] firewire_ohci 0000:01:0a.2: AR spd 2 tl 36, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 26,0
Oct  9 13:22:34 zero kernel: [ 5124.770881] firewire_ohci 0000:01:0a.2: AT spd 2 tl 36, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.770901] firewire_ohci 0000:01:0a.2: AT spd 2 tl 1a, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.772054] firewire_ohci 0000:01:0a.2: AR spd 2 tl 1a, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.774586] firewire_ohci 0000:01:0a.2: AR spd 2 tl 37, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 28,0
Oct  9 13:22:34 zero kernel: [ 5124.774616] firewire_ohci 0000:01:0a.2: AT spd 2 tl 37, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.774633] firewire_ohci 0000:01:0a.2: AT spd 2 tl 1b, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.775649] firewire_ohci 0000:01:0a.2: AR spd 2 tl 1b, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.778272] firewire_ohci 0000:01:0a.2: AR spd 2 tl 38, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 1a,0
Oct  9 13:22:34 zero kernel: [ 5124.778304] firewire_ohci 0000:01:0a.2: AT spd 2 tl 38, ffc1 -> ffc0, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.778328] firewire_ohci 0000:01:0a.2: AT spd 2 tl 1c, ffc1 -> ffc0, ack_pending , BW req, fffff0000b00 c,0
Oct  9 13:22:34 zero kernel: [ 5124.780062] firewire_ohci 0000:01:0a.2: AR spd 2 tl 1c, ffc0 -> ffc1, ack_complete, W resp
Oct  9 13:22:34 zero kernel: [ 5124.783832] firewire_ohci 0000:01:0a.2: AR spd 2 tl 39, ffc0 -> ffc1, ack_pending , BW req, fffff0000d00 1a,0
Oct  9 13:22:34 zero kernel: [ 5124.783882] firewire_ohci 0000:01:0a.2: AT spd 2 tl 39, ffc1 -> ffc0, ack_complete, W resp

and on cancelling aplay:

Oct  9 13:34:52 zero kernel: [ 5862.151671] firewire_ohci 0000:01:0a.2: AT spd 2 tl 1d, ffc1 -> ffc0, ack_pending , Lk req, fffff0000984 8,2
Oct  9 13:34:52 zero kernel: [ 5862.151909] firewire_ohci 0000:01:0a.2: AR spd 2 tl 1d, ffc0 -> ffc1, ack_complete, Lk resp 4,2
Oct  9 13:34:52 zero kernel: [ 5862.152439] firewire_ohci 0000:01:0a.2: AT spd 2 tl 22, ffc1 -> ffc0, ack_pending , Lk req, fffff0000904 8,2
Oct  9 13:34:52 zero kernel: [ 5862.152649] firewire_ohci 0000:01:0a.2: AR spd 2 tl 22, ffc0 -> ffc1, ack_complete, Lk resp 4,2

And please try "jackd with firewire backend" (FFADO is used) and report the result.

Please note that I am using libffado from your ppa. Right now jack refuses to start up with the card. (A few days ago, still with libffado from the Ubuntu repo it started up and played thru jack, with no sound.)

13:55:43.314 D-BUS: JACK server could not be started. Sorry
Thu Oct  9 13:55:29 2014: Starting jack server...
Thu Oct  9 13:55:29 2014: JACK server starting in realtime mode with priority 10
Thu Oct  9 13:55:29 2014: self-connect-mode is "Don't restrict self connect requests"
Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started
Thu Oct  9 13:55:43 2014: ERROR: firewire ERR: Could not start streaming threads
Thu Oct  9 13:55:43 2014: ERROR: Cannot start driver
Thu Oct  9 13:55:43 2014: ERROR: JackServer::Start() failed with -1
Thu Oct  9 13:55:43 2014: ERROR: Failed to start server
Thu Oct  9 13:55:43 2014: Saving settings to "/home/muranyia/.config/jack/conf.xml" ...
13:55:45.411 Could not connect to JACK server as client. - Overall operation failed. - Unable to connect to server. Please check the messages window for more info.
Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started

If both ALSA and FFADO fail to handle the device, it means the cause is not in drivers, maybe in lower layer. In this case, please tell me what IEEE 1394 interface you use.

I am using the IEEE1394 port of an Audigy card. I also have a dedicated card (VIA chipset AFAICR), if you want I can try that one.

takaswie commented 9 years ago

Ping https://github.com/takaswie/snd-firewire-improve/issues/7#issuecomment-58451135

takaswie commented 9 years ago

As long as seeing your syslog, the playbacking continued 738 seconds. ALSA BeBoB driver seems to transfer samples to the device successfully. If you want to check this behaviour, please see output from /proc/asound/cardX/pcm0p/sub0/status (here 'X' is ID for your device). I believe you can see 'hw_ptr' and 'hw_ptr' are moving.

So the issue is that the device generates no sound on your favorite output port, I think. How about trials to playback to all of channels which jackd with ALSA backend creates? At first $ jackd -r -d alsa -d hw:X,0 (here X is ID for your device) Then jackd open 10ch playback and 10ch capture for your device. Run some JACK applications and connect their output to the 10ch. Then listen to your device.

And I write a short script. This script executes commands to get status of all Audio Function block in your device. https://gist.github.com/takaswie/8910265fb67f5ef21c29

This script uses 'firewire-request' command in 'jujuutils' to communicate to the device. Please install jujuutils when you try. https://code.google.com/p/jujuutils/

I am using the IEEE1394 port of an Audigy card. I also have a dedicated card (VIA chipset AFAICR), if you want I can try that one.

Let's try it to distinguish this issue...

muranyia commented 9 years ago

As long as seeing your syslog, the playbacking continued 738 seconds. ALSA BeBoB driver seems to transfer samples to the device successfully. If you want to check this behaviour, please see output from /proc/asound/cardX/pcm0p/sub0/status (here 'X' is ID for your device). I believe you can see 'hw_ptr' and 'hw_ptr' are moving.

No, actually 'hw_ptr' and 'hw_ptr' are staying 0 and the scale at the bottom shows 0% too.

$ jackd -r -d alsa -d hw:X,0 (here X is ID for your device)

I added -r44100 because I noticed that otherwise it is initialized for 48000. Either way, jack fails with:

$ jackd -r -d alsa -d hw:0,0 -r44100
jackdmp 1.9.10
Copyright 2001-2005 Paul Davis and others.
Copyright 2004-2014 Grame.
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 non-realtime mode
self-connect-mode is "Don't restrict self connect requests"
audio_reservation_init
Acquire audio card Audio0
creating alsa driver ... hw:0,0|hw:0,0|1024|2|44100|0|0|nomon|swmeter|-|32bit
Using ALSA driver BeBoB running on card 0 - TerraTec Electronic Gmb PHASE 88 Rack FW (id:3, rev:1), GUID 000aac0300592827 a
configuring for 44100Hz, period = 1024 frames (23.2 ms), buffer = 2 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 2 periods for capture
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 2 periods for playback
JackPosixProcessSync::LockedTimedWait error usec = 5000000 err = Connection timed out
Driver is not running
Cannot create new client

And I write a short script. This script executes commands to get status of all Audio Function block in your device.

The script calls ./firewire-request, where can I grab it?

muranyia commented 9 years ago

And I write a short script. This script executes commands to get status of all Audio Function block in your device.

The script calls ./firewire-request, where can I grab it?

Oh I see it is in jujuutils. Changed ./firewire-request to firewire-request.

$ ./phase88-canner.sh /dev/fw2
Selector Function Blocks
response: 000: 0c 08 b8 80 01 10 02 00 01 .........
response: 000: 0c 08 b8 80 02 10 02 00 01 .........
response: 000: 0c 08 b8 80 03 10 02 00 01 .........
response: 000: 0c 08 b8 80 04 10 02 00 01 .........
response: 000: 0c 08 b8 80 05 10 02 00 01 .........
response: 000: 0c 08 b8 80 06 10 02 00 01 .........
response: 000: 0c 08 b8 80 07 10 02 00 01 .........
response: 000: 0c 08 b8 80 08 10 02 01 01 .........
response: 000: 0c 08 b8 80 09 10 02 00 01 .........
response: 000: 0c 08 b8 80 0a 10 02 00 01 .........
Feature Function Blocks (Volume Control Only)
response: 000: 0c 08 b8 81 01 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 02 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 03 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 04 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 05 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 06 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 07 02 02 00 00 ............
response: 000: 0c 08 b8 81 01 10 02 08 02 02 00 00 ............
response: 000: 0c 08 b8 81 02 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 02 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 02 10 02 02 02 02 00 00 ............
response: 000: 0c 08 b8 81 03 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 03 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 03 10 02 02 02 02 00 00 ............
response: 000: 0c 08 b8 81 04 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 04 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 04 10 02 02 02 02 00 00 ............
response: 000: 0c 08 b8 81 05 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 05 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 05 10 02 02 02 02 00 00 ............
response: 000: 0c 08 b8 81 06 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 06 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 06 10 02 02 02 02 00 00 ............
response: 000: 0c 08 b8 81 07 10 02 00 02 02 00 00 ............
response: 000: 0c 08 b8 81 07 10 02 01 02 02 00 00 ............
response: 000: 0c 08 b8 81 07 10 02 02 02 02 00 00 ............
Processing Function Blocks
takaswie commented 9 years ago

No, actually 'hw_ptr' and 'hw_ptr' are staying 0 and the scale at the bottom shows 0% too.

OK, I see. Next, please try with another IEEE1394 interface card (VIA chipset), not Audigy.

$ ./phase88-canner.sh /dev/fw2

OK. We can see no Processing Function Blocks are available (I guess they have fix values), but some Selector/Feature Function Blocks are available.

When changing the state of each Function Block, execute with 0x00 in 1st byte and parameters, like: ./firewire-request /dev/fw1 fcp 0x0008b881011002000202FE82

About the ID and the value of parameters, please refer to: http://subversion.ffado.org/wiki/BebobAvc

muranyia commented 9 years ago

OK, I see. Next, please try with another IEEE1394 interface card (VIA chipset), not Audigy.

I took a closer look and other than the Audigy, my computer has an onboard VIA firewire and a Texas Instruments PCI card. The last test was already done with the Texas Instruments card.

When changing the state of each Function Block, execute with 0x00 in 1st byte and parameters, like: ./firewire-request /dev/fw1 fcp 0x0008b881011002000202FE82

I am trying to understand Function Blocks and Audio Subunits, but unfortunately I am not a proper C/audio programmer so it will take some time for me. If I understand right, ffado-test discover can do the job of mapping the Audio Subunits for me.

takaswie commented 9 years ago

I updated FFADO wiki for Terratec Phase 88 Rack FW, to investigate this issue: http://subversion.ffado.org/wiki/AvcModels/TerratecPhase88

As long as you reported. the version of firmware in your device is the latest one, however FFADO developers have subunit map in the former one.

Would you please get 'Summary' and 'Connections' output by 'ffado-test Discover -v 7' and fill this page? I suspict that Terratec changed subunit formation between the former and the latter.

muranyia commented 9 years ago

I have updated the page (except for the Info Registers which I could not find). For your convenience, the diff between the old and the new discovery is here: http://pastebin.com/DtupcCsE

muranyia commented 9 years ago

BTW the older discovery results contain the typo 'ouput' (instead of 'output') and the latest FFADO has this problem too. I guess someone could just grep -r the whole source for the string 'ouput'...

A normalized version of the diff, without the ouput/output and output/Output differences: http://pastebin.com/3hgsaQMS

takaswie commented 9 years ago

Oops. Your post is trimmed in the end of content. I guess there're some limitation for characters in a page... Please fill it again.

By the way, I guess that the cause of this issue is:

I think this should be connected to ' MSU Synch Internal', not ' MSU Synch External'. Even if you set internal clock source correctly via ffado-mixer and check it via proc ourput which ALSA driver adds, the source of clock is still external in your device. Then your device lost clock source and transfer no packets.

I investigate the command to set this correctly. Please wait a bit.

takaswie commented 9 years ago

Please try these commands for your test.

ASU clocksource -> MSU Sync Internal: ./firewire-request /dev/fw1 fcp 0x00ff1a0f80056008

ASU clocksource -> MSU Sync External: ./firewire-request /dev/fw1 fcp 0x00ff1a0f80056009

I think these commands should be used correspondingly to Selector Function Block settings for clock source. If possible:

1.set clock source by ffado-mixer 2.confirm the setting via proc 3.get subunit topology via ffado-test and confirm which subunit is connected to 'ASU clocksource' 4.execute the command above 5.get subunit topology again and confirm it's changed. 6.aplay 7.confirm hw_ptr is moving via proc

muranyia commented 9 years ago

I see no 13->94 connection... Also in the generated graph 93 and 94 are disconnected. I have uploaded the full dot.

muranyia commented 9 years ago

BTW, somewhere along the lines my Pulseaudio stopped seeing any of the sound card. So now I have no PA sound at all. Is it because of this procedure? https://wiki.ubuntu.com/PulseAudio/Log

takaswie commented 9 years ago

BTW, somewhere along the lines my Pulseaudio stopped seeing any of the sound card. So now I have no PA sound at all. Is it because of this procedure? https://wiki.ubuntu.com/PulseAudio/Log

Exactly. You need to run 'pulseaudio' manually if you want to use it.

muranyia commented 9 years ago

Firstly, to avoid confusion, my comment 58833073 was posted before I saw your comment 58805236.

Then, I have also set a webcam to see what is going on with the backside LEDs of the unit :smiley:

ad 1. I have set every possible clock source. I can confirm that the settings at the top of the ffado-mixer do virtually the same as the ones at the bottom of phase88control (so those can be safely deleted). They both have a bug however, which I describe below. ad 2. Proc reflects Internal and Digital In (S/PDIF) but not Wordclock (proc says '(null)'). Could be also because I have no Wordclock connected. When I choose Internal AFTER Word Clock, however, proc says Wordclock. It says Internal only when chosen after/with S/PDIF.

Sync Source Ext Sync Source WordClk LED Ext Sync LED proc (13) ASU Clocksource input
External S/PDIF off on Digital In (52) Clock
External WordClock on on (null) (52) Clock
Internal S/PDIF off off Internal (52) Clock
Internal WordClock on off Word Clock (52) Clock

ad 3. As you can see it is always (52) Clock feeding the 13) ASU Clocksource. (94) MSU Synch External is always disconnected. Diff confirms that the four topologies are identical, except that only the Internal/SPDIF case shows the Info Registers.

ad 4. Timeout. I have double checked that I am addressing the right controller. ad 5. ...

ad 6-7. I can play ONCE in Internal/SPDIF setting. When stopping it, the Firewire LED goes off, and for the next aplay attempt, the LED goes on but play stops at 00%.

takaswie commented 9 years ago

proc (null)

Fix released for this "null" issue. https://github.com/takaswie/snd-firewire-improve/commit/ad6de4f7518b7d2f5f5f6816f0247783fd969b53

But I think this is not related to the issue in this thread. There seems to be the other causes...

muranyia commented 9 years ago

My impression is that the Phase 88 basically knows what's up, as the LEDs reflect the settings. The graph, however does not change.

Another thing I noticed that the Firewire LED is usually off, sometimes blinking, and on when trying to play. The manual is not very clear on this but the Standalone Mode Manual suggests that it shall be always on when connected.

IEEE-1394:
[on] the device is controlled via 1394 (no standalone mode)
[off] the device has no established connection via 1394
[flashing] “MIDI Remote Mode” is active

I guess this is because of the clock issue.

Today I have managed to run the commands by firewire-request:

$ sudo firewire-request /dev/fw2 fcp 0x00ff1a0f80056008
response: 000: 0a ff 1a ff 80 05 60 08                         ......`.
$ sudo firewire-request /dev/fw2 fcp 0x00ff1a0f80056009
response: 000: 0a ff 1a ff 80 05 60 09                         ......`.

The LEDs did not show any change, aplay does not play, and the graphs are unchanged, as well as proc.

Fix released for this "null" issue. ad6de4f

Module snd-firewire/3.11 already installed on kernel 3.13.0-37-generic/x86_64

How can I update the dkms module? Will dkms autoinstall do it?

takaswie commented 9 years ago

Mode Manual suggests that it shall be always on when connected.

The FireWire LED is corresponding to 'connection'. IEC 61883-1 describe the 'connection'. Windows driver always establishes the connections, however ALSA BeBoB driver establishes/destroys the connections at starting/stopping streams. This is my intension to reduce CPU usage when no ALSA PCM applications are running.

I hope you to read IEC 61883-1 to understand what is the 'connection', but you need to buy it. Here, I introduce you to read page 4 in my snd-firewire-report (https://github.com/takaswie/alsa-firewire-report).

In logs which you reported, these lines are to touch the 'connection':

[ 5124.708103] firewire_ohci 0000:01:0a.2: AT spd 2 tl 0c, ffc1 -> ffc0, ack_pending , Lk req, fffff0000904 8,2 [ 5124.708308] firewire_ohci 0000:01:0a.2: AR spd 2 tl 0c, ffc0 -> ffc1, ack_complete, Lk resp 4,2 [ 5124.708456] firewire_ohci 0000:01:0a.2: AT spd 2 tl 11, ffc1 -> ffc0, ack_pending , Lk req, fffff0000984 8,2 [ 5124.708597] firewire_ohci 0000:01:0a.2: AR spd 2 tl 11, ffc0 -> ffc1, ack_complete, Lk resp 4,2

I believe these are corresponding to FireWire LED.

Today I have managed to run the commands by firewire-request:

0x0a in the first byte means 'rejected'. So these trials have no effects. See: http://subversion.ffado.org/browser/trunk/libffado/src/libavc/general/avc_generic.h#L66

How can I update the dkms module? Will dkms autoinstall do it?

  1. Pull the fixment into your local repository

$ cd git/snd-firewire-improve $ git checkout master $ git remote update $ git pull origin master

  1. Uninstall driver module and reinstall it

$ sudo dkms remove alsa-firewire/3.11 --all $ sudo dkms install alsa-firewire/3.11

takaswie commented 9 years ago

3 unload ALSA BeBoB driver and reload

$ sudo modprobe -r snd-bebob $ sudo modprobe snd-bebob

I forgot it.

muranyia commented 9 years ago

The FireWire LED is corresponding to 'connection'. IEC 61883-1 describe the 'connection'. Windows driver always establishes the connections, however ALSA BeBoB driver establishes/destroys the connections at starting/stopping streams. This is my intension to reduce CPU usage when no ALSA PCM applications are running.

I hope you to read IEC 61883-1 to understand what is the 'connection', but you need to buy it. Here, I introduce you to read page 4 in my snd-firewire-report

I started reading it previously too. Heavy reading for me, as my closest encounter with raw data has been sysex. I was thinking, staring at these LEDs... When powering up the PHASE 88 (or connecting the cable), the Firewire LED switches on meanwhile the sync LED is blinking ('there is a problem with the sync state' according to the manual). Then after a few seconds the Firewire LED goes off. Is it possible, by any chance, that the PHASE 88 would expect that the connection is established and kept, otherwise is disconnects the clock? If so, is it possible that we test with a persistent connection? Of course, this is just a shot in the dark.

3 unload ALSA BeBoB driver and reload

I guessed that. Confirming that the proc anomaly is resolved.

takaswie commented 9 years ago

I guessed that. Confirming that the proc anomaly is resolved.

OK. Thanks for your confirmation. I'll post my patch for the "(null)" label issue to upstream within a few days.

Regards

muranyia commented 9 years ago

Browsing around the ffado sources I have noticed that there is a special way there to detect the clock source of the PHASE 88. Does it make any sense in this case? http://subversion.ffado.org/browser/trunk/libffado/src/bebob/terratec/terratec_device.h#L43

takaswie commented 9 years ago

43 // override these since the phase88 does not support 44 // the usual clock source selection mechanism 45 virtual ClockSourceVector getSupportedClockSources(); 46 virtual bool setActiveClockSource(ClockSource); 47 virtual ClockSource getActiveClockSource();

I guess that Peter Palmer had expected the situation and note it. But there're no implementation for the expectation, therefore I can judge nothing.

But some VENDOR-DEPENDENT commands are in terratec_cmd.cpp. http://subversion.ffado.org/browser/trunk/libffado/src/bebob/terratec/terratec_cmd.cpp

This seems to be for 'Advanced Standalone Mode' in: ftp://ftp.terratec.de/Producer/PHASE/PHASE88RACKFireWire/Manual/PHASE88Rack_FW_AdvancedStandaloneMode_Tutorial.pdf

Try with jujuutils: https://gist.github.com/takaswie/b7409ce0a45daf72b939

muranyia commented 9 years ago

43 // override these since the phase88 does not support 44 // the usual clock source selection mechanism I guess that Peter Palmer had expected the situation and note it. But there're no implementation for the expectation, therefore I can judge nothing.

Ah I see. For the record; I have now confirmed that the PHASE 88 works with FFADO, but notably, only with the lowlatency kernel. I just tried to use snd_firewire with the lowlatency kernel, but I got the following error:

modprobe: ERROR: could not insert 'snd_bebob': Exec format error

Thanks for the pointer to the Vendor Specific Commands for the Advanced Standalone Mode. BTW, it would be cool to have this wrapper in FFADO so I can extend the mixer panel with those settings. Of course not in its current form as the /dev path is hardcoded.

Also a note on Vendor Specific Commands: for 0x24 the comment says Assignment of MIDI channels to control elements when it is actually Assignment of MIDI CC numbers to control elements as stated correctly later. The MIDI Remote Channel, although an important setting, is seemingly missing from the specification (?)

takaswie commented 9 years ago

The MIDI Remote Channel, although an important setting, is seemingly missing from the specification (?)

I cannot understand what you mean...

In my understanding, the 'MIDI Remote Channel' is a functionality to assign a certain MIDI control change number into mixer control element such as fader. To setting this, the vendor-dependent command with 0x24 may be implemented.

takaswie commented 9 years ago

modprobe: ERROR: could not insert 'snd_bebob': Exec format error

When you change kernel, you must rebuild kernel modules. https://github.com/takaswie/snd-firewire-improve/issues/8#issuecomment-59152951

muranyia commented 9 years ago

In my understanding, the 'MIDI Remote Channel' is a functionality to assign a certain MIDI control change number into mixer control element such as fader. To setting this, the vendor-dependent command with 0x24 may be implemented.

'MIDI Remote Channel' is the single MIDI channel (1-16) where the PHASE 88 will listen.

midiremotechannel

I have a clue that 0x23 could be the subfunction where the Channel Number can be specified, as the Advanced Standalone Mode manual does not mention that it could be switched on/off; rather it switches on automatically when you disconnect the device. Perhaps specifying MIDI channel 0 effectively disables it. I will test this later.

When you change kernel, you must rebuild kernel modules.

I did... Shall I delete some things between dkms remove and dkms install?

takaswie commented 9 years ago

Perhaps specifying MIDI channel 0 effectively disables it. I will test this later.

OK. I wait for your report of the test.

I did... Shall I delete some things between dkms remove and dkms install?

Hm. For example, if snd-bebob.ko remains in your system where DKMS doesn't manage, then your linux kernel still use the old one. Please confirm the location of snd-bebob.ko.