From: Daniel W. <wa...@mo...> - 2007-12-18 15:06:18
|
This is just to let you know what I found out so far. As reported shortly after starting up I see following: wagi@newton:~/src/libffado$ jackd -R -d firewire no message buffer overruns jackd 0.107.2 Copyright 2001-2005 Paul Davis and others. jackd 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 JACK compiled with System V SHM support. loading driver .. 3057156402: Warning (bebob_mixer.cpp)[ 163] addElementForAllFunctionBlocks: No BeBoB audio subunit found libiec61883 warning: Established connection on channel 0. You may need to manually set the channel on the receiving node. libiec61883 warning: Established connection on channel 1. You may need to manually set the channel on the transmitting node. jackd watchdog: timeout - killing jackd Segmentation fault The debug version times out faster than the non debug version. This might indicate indeed that there is too much debugging code. The good news is that for a short time a valid stream is on the bus. The device is happy with it. I have to reread Pieter's mail about this debugging effort with the old firewire stack. I have the feeling it might be the same problem. I'm not sure where to start digging first. Maybe I have to play a bit more to get a better understanding what's really happing. daniel |
From: Daniel W. <wa...@mo...> - 2007-12-20 16:41:06
|
> The good news is that for a short time a valid stream is on the bus. The > device is happy with it. I guess I was too fast with this statement. I have recorded with dumpiso the activities on the bus. It is a modified version which also records the cycle when the packet was received. To be sure I got the correct results I have first tried it out with freebob. startup: cycle 7098 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 7099 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 7100 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 7101 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7102 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7103 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7104 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7107 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 7108 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7109 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7110 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7111 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 7112 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7113 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7114 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7115 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 7116 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 7117 dropped 0 channel 0 tag 1 sy 0 length 232 [...] As one can note it isn't really what it should be. The expected pattern is 1 empty, 3 data packets for 48 kHz. After a while it looks as expected though: cycle 4511 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 4512 dropped 0 channel 1 tag 1 sy 0 length 8 cycle 4512 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 4513 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 4513 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 4514 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 4514 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 4515 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 4515 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 4516 dropped 0 channel 1 tag 1 sy 0 length 8 cycle 4516 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 4517 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 4517 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 4518 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 4518 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 4519 dropped 0 channel 1 tag 1 sy 0 length 232 Stream 0 and 1 are off by one in the sense of the pattern but that isn't a problem. That is completely ok. So now let's have a look at ffado: starting stream: cycle 1265 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1270 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1271 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1272 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1275 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1276 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1277 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1278 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1279 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1280 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1281 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 1282 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1283 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1284 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1286 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1287 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 1288 dropped 0 channel 0 tag 1 sy 0 length 232 [...] There are more and larger gaps (1272-1275) compared to freebob which has only 1 gap at startup. I don't think it is necessary to have from the first cycle a valid stream though the ffado case looks more 'distorted'. The main problem it seems is that there is never a valid stream on the bus: cycle 2156 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2157 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 2158 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2159 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2160 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2161 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 2162 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2163 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2164 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2165 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 2166 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2167 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2170 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2171 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2172 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2173 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 2174 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2175 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2176 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2177 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 2178 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2179 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2180 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 2182 dropped 0 channel 0 tag 1 sy 0 length 232 Right after this block the device starts to stream (channel 1). The device also needs some time until the stream is stabilized. cycle 6113 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 6114 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6114 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6115 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6115 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6116 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6116 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6117 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6117 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 6118 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6118 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6119 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6119 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6120 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6120 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6121 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6121 dropped 0 channel 0 tag 1 sy 0 length 8 cycle 6122 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6123 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6124 dropped 0 channel 1 tag 1 sy 0 length 232 cycle 6124 dropped 0 channel 0 tag 1 sy 0 length 232 cycle 6125 dropped 0 channel 1 tag 1 sy 0 length 232 Channel 0 still has drop outs, it might be the reason why channel 1 lacks a regular pattern. The device tries to keep in sync with channel 0. |
From: Daniel W. <wa...@mo...> - 2007-12-21 15:58:29
|
some more debugging output (channel 0 is from the pc to the device): 1286 ch 0 len 232 cip1 010700b0 [dbc b0] cip2 900265a2 [syt a265] 1287 ch 0 len 232 cip1 010700b8 [dbc b8] cip2 900279a2 [syt a279] 1288 ch 0 len 232 cip1 010700c0 [dbc c0] cip2 900291a3 [syt a391] 1289 ch 0 len 8 cip1 010700c8 [dbc c8] cip2 9002a5a2 [syt a2a5] 1290 ch 0 len 232 cip1 010700d0 [dbc d0] cip2 9002ffff [syt ffff] 1291 ch 0 len 232 cip1 010700d0 [dbc d0] cip2 9002b9a3 [syt a3b9] 1292 ch 0 len 232 cip1 010700d8 [dbc d8] cip2 9002d1a3 [syt a3d1] 1293 ch 0 len 8 cip1 010700e0 [dbc e0] cip2 9002e5a4 [syt a4e5] 1294 ch 0 len 232 cip1 010700e8 [dbc e8] cip2 9002ffff [syt ffff] 1295 ch 0 len 232 cip1 010700e8 [dbc e8] cip2 9002f9a3 [syt a3f9] 1296 ch 0 len 232 cip1 010700f0 [dbc f0] cip2 900211a4 [syt a411] 1297 ch 0 len 8 cip1 010700f8 [dbc f8] cip2 900225a5 [syt a525] 1298 ch 0 len 232 cip1 01070000 [dbc 0] cip2 9002ffff [syt ffff] 1299 ch 0 len 232 cip1 01070000 [dbc 0] cip2 900239a4 [syt a439] 1300 ch 0 len 232 cip1 01070008 [dbc 8] cip2 900251a5 [syt a551] 1301 ch 0 len 8 cip1 01070010 [dbc 10] cip2 900265a5 [syt a565] I think there are three things wrong: - cycle 1294: fmt == 0x10 and syt == 0xffff for a data packet - cycle 1293: syt != 0xffff for a empty packet - cycle 1298 and 1299 have the same dbc "If FMT is 0b111111 (no data), the fields for DBS, FN, QPC, SPH and DBC are ignored and no data data blocks shall be transmitted. For other values of FMT, data is presented and the most significat bit of the FMT field indicates whether or not a time stamp in SYT format is present. When the most significatn bit of FMT is zero, the FMT-dependent field contains a time stamp in the format specified by SYT." -- iec61883 "In order to indicate 'no data', the transmitter may transmit an empty packet or a special non-empty packet which ahs the 'NO-DATA' code in its FDF and has the same size of dummy data as a non-empty packet. Ther transmitter must set the time stamp of the first data block in a packet" -- AM 2.1 From those two paragraphs I deduce that cycle 1294 is not correct. One could argue that cycle 1293 is still correct because it is not explicitly forbidden, though I don't think it matters. It just doesn't make much sense for me. What time do you play nothing? The dbc thing is also doesn't make much sense. Could it be that the CIP headers are just off by one? Then it would make much more sense. daniel |
From: Daniel W. <wa...@mo...> - 2007-12-23 11:02:36
|
> From those two paragraphs I deduce that cycle 1294 is not correct. One > could argue that cycle 1293 is still correct because it is not > explicitly forbidden, though I don't think it matters. It just doesn't > make much sense for me. What time do you play nothing? > > The dbc thing is also doesn't make much sense. Could it be that the CIP > headers are just off by one? Then it would make much more sense. Stupid me. I got my analyzing tool wrong. Anyway, the I have intercepted following from the PC: 2493 ch 1 len 8 cip1 01070000 [dbc 0] cip2 90ffffff [syt ffff] 2494 ch 1 len 8 cip1 01070000 [dbc 0] cip2 90ffffff [syt ffff] 2495 ch 1 len 8 cip1 01070000 [dbc 0] cip2 90ffffff [syt ffff] [...] 4798 ch 1 len 8 cip1 01070000 [dbc 0] cip2 90ffffff [syt ffff] 4799 ch 1 len 8 cip1 01070000 [dbc 0] cip2 90ffffff [syt ffff] 4800 ch 1 len 8 cip1 01070000 [dbc 0] cip2 90ffffff [syt ffff] 4801 ch 1 len 232 cip1 01070000 [dbc 0] cip2 9002734d [syt 734d] syt-diff: 574d payload: 40000000 40000000 40000000 00000000 40000000 4802 ch 1 len 232 cip1 01070008 [dbc 8] cip2 9002874d [syt 874d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4803 ch 1 len 8 cip1 01070010 [dbc 10] cip2 90ffffff [syt ffff] 4804 ch 1 len 232 cip1 01070010 [dbc 10] cip2 90029b4d [syt 9b4d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4805 ch 1 len 232 cip1 01070018 [dbc 18] cip2 9002b34d [syt b34d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4806 ch 1 len 232 cip1 01070020 [dbc 20] cip2 9002c74d [syt c74d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4807 ch 1 len 8 cip1 01070028 [dbc 28] cip2 90ffffff [syt ffff] 4808 ch 1 len 232 cip1 01070028 [dbc 28] cip2 9002db4d [syt db4d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4809 ch 1 len 232 cip1 01070030 [dbc 30] cip2 9002f34d [syt f34d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4810 ch 1 len 232 cip1 01070038 [dbc 38] cip2 9002074d [syt 74d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4811 ch 1 len 8 cip1 01070040 [dbc 40] cip2 90ffffff [syt ffff] 4812 ch 1 len 232 cip1 01070040 [dbc 40] cip2 90021b4d [syt 1b4d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4813 ch 1 len 232 cip1 01070048 [dbc 48] cip2 9002334d [syt 334d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 4814 ch 1 len 232 cip1 01070050 [dbc 50] cip2 9002474d [syt 474d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 [...] 5120 ch 1 len 232 cip1 01070078 [dbc 78] cip2 90025b4d [syt 5b4d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 5121 ch 1 len 232 cip1 01070080 [dbc 80] cip2 9002734d [syt 734d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 5122 ch 1 len 232 cip1 01070088 [dbc 88] cip2 9002874d [syt 874d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 5123 ch 1 len 8 cip1 01070090 [dbc 90] cip2 90ffffff [syt ffff] 5124 ch 1 len 232 cip1 01070090 [dbc 90] cip2 90029b4d [syt 9b4d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 5125 ch 1 len 232 cip1 01070098 [dbc 98] cip2 9002b34d [syt b34d] syt-diff: 1000 payload: 40000000 40000000 40000000 00000000 40000000 5126 ch 1 len 8 cip1 010700a0 [dbc a0] cip2 90ffffff [syt ffff] 5127 ch 1 len 8 cip1 010700a0 [dbc a0] cip2 90ffffff [syt ffff] 5128 ch 1 len 8 cip1 010700a0 [dbc a0] cip2 90ffffff [syt ffff] 5129 ch 1 len 8 cip1 010700a0 [dbc a0] cip2 90ffffff [syt ffff] [...] So this look very good now. Ah yes, I have changed the line bool send_payload=true; to bool send_payload=false; in src/libstreaming/amdtp/AmdtpTransmitStreamProcessor.cpp I just liked to have the empty packets instead of the no-data ones for debugging. In order to check if the data ffado puts into the kernel is also the data which is afterwards on the bus, I have tapped the raw1394 callback. It looks ok. So now difference between what we write into the kernel and on the bus differ. Well, that is what I expected. The only thing which could be a problem is the short amount of time where data is send (cycle 4801 to cycle 5124 (diff 323)). Though the device starts streaming on cycle 1181, 3620 cycle before the PC. 1178 ch 0 len 8 cip1 02070008 [dbc 8] cip2 9002ffff [syt ffff] 1179 ch 0 len 8 cip1 02070008 [dbc 8] cip2 9002ffff [syt ffff] 1180 ch 0 len 8 cip1 02070008 [dbc 8] cip2 9002ffff [syt ffff] 1181 ch 0 len 232 cip1 02070078 [dbc 78] cip2 9002d94f [syt d94f] syt-diff: a54f payload: 40000000 40000000 40000000 80000000 40000000 1182 ch 0 len 232 cip1 02070080 [dbc 80] cip2 9002f14f [syt f14f] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1183 ch 0 len 232 cip1 02070088 [dbc 88] cip2 90020550 [syt 550] syt-diff: 1001 payload: 40000000 40000000 40000000 80000000 40000000 1184 ch 0 len 8 cip1 02070090 [dbc 90] cip2 9002ffff [syt ffff] 1185 ch 0 len 8 cip1 02070090 [dbc 90] cip2 9002ffff [syt ffff] 1186 ch 0 len 232 cip1 02070090 [dbc 90] cip2 90023351 [syt 3351] syt-diff: 2201 payload: 40000000 40000000 40000000 80000000 40000000 1187 ch 0 len 8 cip1 02070098 [dbc 98] cip2 9002ffff [syt ffff] 1188 ch 0 len 232 cip1 02070098 [dbc 98] cip2 90024751 [syt 4751] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1189 ch 0 len 232 cip1 020700a0 [dbc a0] cip2 90025b51 [syt 5b51] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1190 ch 0 len 232 cip1 020700a8 [dbc a8] cip2 90027352 [syt 7352] syt-diff: 1001 payload: 40000000 40000000 40000000 80000000 40000000 1191 ch 0 len 8 cip1 020700b0 [dbc b0] cip2 9002ffff [syt ffff] 1192 ch 0 len 232 cip1 020700b0 [dbc b0] cip2 90028752 [syt 8752] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1193 ch 0 len 232 cip1 020700b8 [dbc b8] cip2 90029b52 [syt 9b52] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1194 ch 0 len 232 cip1 020700c0 [dbc c0] cip2 9002b353 [syt b353] syt-diff: 1001 payload: 40000000 40000000 40000000 80000000 40000000 1195 ch 0 len 8 cip1 020700c8 [dbc c8] cip2 9002ffff [syt ffff] 1196 ch 0 len 232 cip1 020700c8 [dbc c8] cip2 9002c753 [syt c753] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1197 ch 0 len 232 cip1 020700d0 [dbc d0] cip2 9002db53 [syt db53] syt-diff: 1000 payload: 40000000 40000000 40000000 80000000 40000000 1198 ch 0 len 232 cip1 020700d8 [dbc d8] cip2 9002f354 [syt f354] syt-diff: 1001 payload: 40000000 40000000 40000000 80000000 40000000 [...] As you can see there is a small hickup during startup phase but then the stream gets stable and stays that way. The above record is from the wire. Next step is to intercept the data in the raw1394 rx callback. |
From: Daniel W. <wa...@mo...> - 2007-12-23 14:08:25
|
ok, after some help from Pieter it works for the ref board but not for the fa-66. see checkin r764. After startup I see now following: [...] libiec61883 warning: Established connection on channel 0. You may need to manually set the channel on the receiving node. libiec61883 warning: Established connection on channel 1. You may need to manually set the channel on the transmitting node. jackd watchdog: timeout - killing jackd Aborted Previously to the Abort message there is a bus reset. I don't know where it is coming from but it seems to be the source of the problem. |
From: Daniel W. <wa...@mo...> - 2007-12-23 14:43:56
|
And the last problem is also fixed. During my hacking I changed the FMT for empty packets to a wrong format. Now ffado works for me(TM). |