Skip to content

Latest stable version 1.5, random TXDelay timing problem #170

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
meinja opened this issue Sep 24, 2018 · 18 comments
Closed

Latest stable version 1.5, random TXDelay timing problem #170

meinja opened this issue Sep 24, 2018 · 18 comments

Comments

@meinja
Copy link

meinja commented Sep 24, 2018 •
edited
Loading

I have Direwolf 1.5 installed on a Raspberry Pi3 ( with freshly installed Raspian Stretch). The setup uses linBPQ and Direwolf KISS mode 127.0.0.1:8001. I am able to make connections with no problem on 1200 and 300 baud, but I notice random delays between the PTT activation and actual transmitted audio. I have TXDelay set at 30ms, but I'm seeing delays up to 2 seconds (maybe even more at times) between PTT keydown and transmitted audio. Seems purely random; I would say 50% of the transmissions have this large delay, and the rest are normal. The long delays themselves are random in length also, and occur on any transmit, whether an ack or a command sent to the other station. The Pi3's CPU is generally around only 3% use when I'm using packet; no spikes during the delays or anything. This same problem was in the 1.5-beta4 version as well.

PTT is activated by the Pi3's GPIO pin 26.

USB audio is the Syba SD-CM-UAUD.

Timings in bpq32.cfg are at the suggested settings in the Direwolf user guide.

The BPQ config file is very basic; no other timing settings other than the following:

PORT
PORTNUM=1 ; Port number
ID=VHF Packet 1200-baud ; PORTS command text
TYPE=ASYNC :RS232 connection
IPADDR=127.0.0.1 ; DIREWOLF
TCPPORT=8001 ; DIREWOLF
SPEED=19200
CHANNEL=A ; TNC channel
MAXFRAME=1 ;Max outstanding frames
FRACK=4000 ; Level 2 timeout (ms)
RESPTIME=40 ; Level 2 delayed ACK (ms)
RETRIES=10 ; Level 2 max retries
PACLEN=128 ; Max packet length (bytes)
TXDELAY=100 ; Transmit keyup delay (ms)
SLOTTIME=100 ; CMSA interval timer (ms)
TXTAIL=100
PERSIST=63 ; Persistence (256/(# transmissions-1)
DIGIFLAG=1 ; Allow Digipeat on this port
ENDPORT

Direwolf config settings that are enabled are:

ADEVICE plughw:1,0
ACHANNELS 1
MODEM 1200 1200:2200
PTT GPIO 26
KISSPORT 8001

I also tried different ARATE settings at 11025 and 48000, but no change was seen.

Output when I run it is:

Dire Wolf version 1.5 (Sep 22 2018) Beta Test 4
Includes optional support for: cm108-ptt

Reading config file direwolf.conf
Audio device for both receive and transmit: plughw:1,0 (channel 0)
Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, E+, 44100 sample rate / 3.
Ready to accept AGW client application 0 on port 8000 ...
Ready to accept KISS TCP client application 0 on port 8001 ...

Attached to KISS TCP client application 0...

Ready to accept KISS TCP client application 1 on port 8001 ...
KISS protocol set TXDELAY = 10 (*10mS units = 100 mS), port 0
KISS protocol set Persistence = 63, port 0
KISS protocol set SlotTime = 10 (*10mS units = 100 mS), port 0
KISS protocol set TXtail = 10 (*10mS units = 100 mS), port 0
KISS protocol set FullDuplex = 0, port 0
@meinja meinja changed the title random TXDelay timing, Direwolf 1.5-beta4 Latest stable version 1.5 has random TXDelay timing Oct 9, 2018
@meinja meinja changed the title Latest stable version 1.5 has random TXDelay timing Latest stable version 1.5, random TXDelay timing problem Oct 9, 2018
@SmithChart
Copy link

I can reproduce this issue with the current master c0abb4b on my raspberryPi zero W. I am using direwolf in beacon-mode and let it transmit my current system uptime as a dummy value.

I am using a GPIO to toggle the PPT.
My CPU-load is a bit higher (around 20%). But that does not justify a few seconds between assertion of the PPT-GPIO and the actual audio playing.

I have tried to narrow the delay down by looking at the log output:

pi@raspberrypi:~ $ direwolf -c direwolf.conf -d o | ts '[%Y-%m-%d %H:%M:%S]'
[2018-10-31 21:29:55] Dire Wolf version 1.5
[2018-10-31 21:29:55] 
[2018-10-31 21:29:55] Reading config file direwolf.conf
[2018-10-31 21:29:55] Audio device for both receive and transmit: plughw:1,0  (channel 0)
[2018-10-31 21:29:55] Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, E+, 44100 sample rate / 3.
[2018-10-31 21:29:55] Ready to accept KISS TCP client application 0 on port 8001 ...
[2018-10-31 21:29:55] Ready to accept AGW client application 0 on port 8000 ...
(...)

But observing roughly 20 TX-Packets they had no delay. The following log shows such a sample:

[2018-10-31 21:33:10] PTT 0 = 1
[2018-10-31 21:33:10] [0L] DB1FI>APDW15,WIDE2-1:T#59,4412.56
[2018-10-31 21:33:11] PTT 0 = 0

I have used an USB-Serial-Adapter to cross-check the problem: With a USB-Serial-Adapter (and a new config-file reflecting the change) the delay seems to be gone, too.

Once I've got the time I'll try to reproduce the issue again.

@meinja
Copy link
Author

meinja commented Nov 2, 2018

Thank you very much for that information. I will try that here tonight and see if it clears up the delay.

@meinja
Copy link
Author

meinja commented Nov 3, 2018

Unfortunately, I still have the delay, after running Direwolf with "direwolf -c direwolf.conf -d o".

@meinja
Copy link
Author

meinja commented Nov 4, 2018

I can reproduce this issue with the current master c0abb4b on my raspberryPi zero W. I am using direwolf in beacon-mode and let it transmit my current system uptime as a dummy value.

I am using a GPIO to toggle the PPT.
My CPU-load is a bit higher (around 20%). But that does not justify a few seconds between assertion of the PPT-GPIO and the actual audio playing.

I have tried to narrow the delay down by looking at the log output:

pi@raspberrypi:~ $ direwolf -c direwolf.conf -d o | ts '[%Y-%m-%d %H:%M:%S]'
[2018-10-31 21:29:55] Dire Wolf version 1.5
[2018-10-31 21:29:55] 
[2018-10-31 21:29:55] Reading config file direwolf.conf
[2018-10-31 21:29:55] Audio device for both receive and transmit: plughw:1,0  (channel 0)
[2018-10-31 21:29:55] Channel 0: 1200 baud, AFSK 1200 & 2200 Hz, E+, 44100 sample rate / 3.
[2018-10-31 21:29:55] Ready to accept KISS TCP client application 0 on port 8001 ...
[2018-10-31 21:29:55] Ready to accept AGW client application 0 on port 8000 ...
(...)

But observing roughly 20 TX-Packets they had no delay. The following log shows such a sample:

[2018-10-31 21:33:10] PTT 0 = 1
[2018-10-31 21:33:10] [0L] DB1FI>APDW15,WIDE2-1:T#59,4412.56
[2018-10-31 21:33:11] PTT 0 = 0

I have used an USB-Serial-Adapter to cross-check the problem: With a USB-Serial-Adapter (and a new config-file reflecting the change) the delay seems to be gone, too.

Once I've got the time I'll try to reproduce the issue again.

If I'm understanding this right, when you run Direwolf without the "-d o" output switch, the TX delay issue is reproduced? And if you run it with the "-d o" output switch, the TX delay issue is gone? I tried it both ways here, but still have the TX delay problem.

@SmithChart
Copy link

SmithChart commented Nov 5, 2018 •
edited
Loading

Sorry, that is a misunderstanding.
direwolf -d o just activates debug output for the PPT and carrier-detect signals. Thus I just get more output from direwolf and get some information about internal states.

I am not really sure what caused the delay or what made it disappear when I started with debug output. @meinja could you run direwolf with the command I used ( direwolf -c direwolf.conf -d o | ts '[%Y-%m-%d %H:%M:%S]' ) and paste the output of a TX with a delay here? I am curious if we can reassemble the delay in the timestamps.

@meinja
Copy link
Author

meinja commented Nov 6, 2018

OK, I'll post the output later today. What Linux distro are you using on the Pi Zero? The "direwolf -c direwolf.conf -d o | ts '[%Y-%m-%d %H:%M:%S]'" command doesn't work on my Raspian Stretch, I get an error saying "no command found" for "ts". I ran "direwolf -c direwolf.conf -d o -T %H:%M:%S" which did work on mine. Very curious what you did to eliminate the delay. I did notice there is no apparent delay when using 300-baud, which I thought was odd. I'll have to test that some more to verify though.

@SmithChart
Copy link

I am using a Raspbian Strech Lite.

You need to install the ts-command first. It is not part of the Debian standard installation

sudo apt-get update
sudo apt-get install moreutils

Afterwards you can use the ts-command. ts will add a timestamp to every line of output direwolf writes to your terminal.
As far as I know the -T option only adds a timestmap to frames.

@meinja
Copy link
Author

meinja commented Nov 6, 2018

Nice! Thanks. Here's the output. I made three transmissions to my other setup across the house by just sending the letter "a". The lines in bold are the transmits. First transmit was noticeably much longer with the delay. Second and third were normal:

[2018-11-06 17:27:23] PTT 0 = 1
[2018-11-06 17:27:23] [0L] KP3FT-2>KB2QXA:(I cmd, n(s)=3, n(r)=6, p=1, pid=0xf0)a<0x0d>
[2018-11-06 17:27:24] PTT 0 = 0
[2018-11-06 17:27:24] DCD 0 = 1
[2018-11-06 17:27:24] DCD 0 = 0
[2018-11-06 17:27:24] DCD 0 = 1
[2018-11-06 17:27:24]
[2018-11-06 17:27:24] KB2QXA audio level = 70(31/16) [NONE] |||||||
[2018-11-06 17:27:24] [0.4] KB2QXA>KP3FT-2:(RR res, n(r)=4, f=1)
[2018-11-06 17:27:25] DCD 0 = 0
[2018-11-06 17:27:27] PTT 0 = 1
[2018-11-06 17:27:27] [0L] KP3FT-2>KB2QXA:(I cmd, n(s)=4, n(r)=6, p=1, pid=0xf0)a<0x0d>
[2018-11-06 17:27:27] PTT 0 = 0
[2018-11-06 17:27:28] DCD 0 = 1
[2018-11-06 17:27:28]
[2018-11-06 17:27:28] KB2QXA audio level = 68(31/16) [NONE] _||||||||
[2018-11-06 17:27:28] [0.4] KB2QXA>KP3FT-2:(RR res, n(r)=5, f=1)
[2018-11-06 17:27:28] DCD 0 = 0
[2018-11-06 17:27:29] PTT 0 = 1
[2018-11-06 17:27:29] [0L] KP3FT-2>KB2QXA:(I cmd, n(s)=5, n(r)=6, p=1, pid=0xf0)a<0x0d>
[2018-11-06 17:27:30] PTT 0 = 0
[2018-11-06 17:27:30] DCD 0 = 1

@SmithChart
Copy link

Can you estimate how long noticeably much longer is? In the log the TX have the following duration:

  1. <2s
  2. <1s
  3. <2s

I will try to reproduce this with my setup today.

@SmithChart
Copy link

I found the time to power up my rig and give it a try.

I tried two setups. First: With USB-Hub between RaspberryPi Zero W and Soundcard:

Normal length:

[2018-11-08 20:13:49.685394] PTT 0 = 1
[2018-11-08 20:13:49.699158] [0L] DB1FI>APDW15,WIDE2-1:T#7,439.77
[2018-11-08 20:13:49.730839] DCD 0 = 1
[2018-11-08 20:13:49.835763] DCD 0 = 0
[2018-11-08 20:13:50.335977] PTT 0 = 0
[2018-11-08 20:13:51.450438] DCD 0 = 1
[2018-11-08 20:13:51.975422] 
[2018-11-08 20:13:51.976381] Digipeater WIDE2 (probably DB0OI) audio level = 56(12/7)   [NONE]   __:||||||
[2018-11-08 20:13:51.977084] [0.5] DB1FI>APDW15,DB0OI,WIDE2*:T#7,439.77
[2018-11-08 20:13:51.977916] Found fewer than expected number of telemetry data values.
[2018-11-08 20:13:51.978667] Telemetry, DireWolf, WB2OSZ
[2018-11-08 20:13:51.979463] Seq=7, A1=439.77
[2018-11-08 20:13:52.052885] DCD 0 = 0

Too long:

[2018-11-08 20:15:19.358910] PTT 0 = 1
[2018-11-08 20:15:19.369091] [0L] DB1FI>APDW15,WIDE2-1:T#10,530.27
[2018-11-08 20:15:21.066526] PTT 0 = 0
[2018-11-08 20:15:22.211019] DCD 0 = 1
[2018-11-08 20:15:22.693578] 
[2018-11-08 20:15:22.694531] Digipeater WIDE2 (probably DB0OI) audio level = 60(13/7)   [NONE]   ___|||||:
[2018-11-08 20:15:22.695500] [0.5] DB1FI>APDW15,DB0OI,WIDE2*:T#10,530.27
[2018-11-08 20:15:22.696291] Found fewer than expected number of telemetry data values.
[2018-11-08 20:15:22.697130] Telemetry, DireWolf, WB2OSZ
[2018-11-08 20:15:22.697942] Seq=10, A1=530.27
[2018-11-08 20:15:22.757243] DCD 0 = 0

And 2nd setup without USB-hub:
Normal:

[2018-11-08 20:22:54.916310] PTT 0 = 1
[2018-11-08 20:22:54.926541] [0L] DB1FI>APDW15,WIDE2-1:T#1,148.00
[2018-11-08 20:22:54.968339] DCD 0 = 1
[2018-11-08 20:22:55.074135] DCD 0 = 0
[2018-11-08 20:22:55.565462] PTT 0 = 0
[2018-11-08 20:22:56.687340] DCD 0 = 1
[2018-11-08 20:22:57.212819] 
[2018-11-08 20:22:57.213539] Digipeater WIDE2 (probably DB0OI) audio level = 56(13/7)   [NONE]   __:||||||
[2018-11-08 20:22:57.214298] [0.5] DB1FI>APDW15,DB0OI,WIDE2*:T#1,148.00
[2018-11-08 20:22:57.215030] Found fewer than expected number of telemetry data values.
[2018-11-08 20:22:57.215747] Telemetry, DireWolf, WB2OSZ
[2018-11-08 20:22:57.216353] Seq=1, A1=148.00 s
[2018-11-08 20:22:57.255572] DCD 0 = 0

Really long one:

[2018-11-08 20:23:24.656948] PTT 0 = 1
[2018-11-08 20:23:24.670532] [0L] DB1FI>APDW15,WIDE2-1:T#2,178.16
[2018-11-08 20:23:29.001275] PTT 0 = 0
[2018-11-08 20:23:30.170497] DCD 0 = 1
[2018-11-08 20:23:30.654468] 
[2018-11-08 20:23:30.655212] Digipeater WIDE2 (probably DB0OI) audio level = 59(10/6)   [NONE]   ___|||||:
[2018-11-08 20:23:30.655984] [0.5] DB1FI>APDW15,DB0OI,WIDE2*:T#2,178.16
[2018-11-08 20:23:30.656724] Found fewer than expected number of telemetry data values.
[2018-11-08 20:23:30.657444] Telemetry, DireWolf, WB2OSZ
[2018-11-08 20:23:30.658048] Seq=2, A1=178.16 s
[2018-11-08 20:23:30.726149] DCD 0 = 0

Another long one:

[2018-11-08 20:25:10.413523] PTT 0 = 1
[2018-11-08 20:25:10.423769] [0L] DB1FI>APDW15,WIDE2-1:T#4,283.92
[2018-11-08 20:25:15.338093] PTT 0 = 0
[2018-11-08 20:25:16.766062] DCD 0 = 1
[2018-11-08 20:25:17.679966] 
[2018-11-08 20:25:17.680959] Digipeater WIDE2 (probably DB0OI) audio level = 26(8/5)   [NONE]   __:|||||_
[2018-11-08 20:25:17.681753] [0.4] DB1FI>APDW15,DB0OI,WIDE2*:T#4,283.92
[2018-11-08 20:25:17.682484] Found fewer than expected number of telemetry data values.
[2018-11-08 20:25:17.683094] Telemetry, DireWolf, WB2OSZ
[2018-11-08 20:25:17.683838] Seq=4, Uptime=283.92 s
[2018-11-08 20:25:17.752022] DCD 0 = 0

(I've done a few more samples but they are not all worth mentioning here.)
It feels like using direwolf without the hub increases the delay.
Good thing is: we can see the delay in the debug output. Thus I hope I can track down the part of the code that produces the delay.

@meinja
Copy link
Author

meinja commented Nov 8, 2018 •
edited
Loading

That's very interesting. I wonder if it's related to amperage somehow. Is your USB hub an externally-powered hub, or "passive" using the Pi Zero's power?

On mine, the noticeable delays were around 2 seconds, and seems like 3 seconds at times. Some are around 1 second. On the transmissions with normal delay, it sounds like just a quick chirp on the back-and-forth acks and short one-letter commands.

@meinja
Copy link
Author

meinja commented Nov 12, 2018

I found this in the "xmit.c" file in the Direwolf directory around line# 882:

  • See how long it has been since PTT was turned on.

  • Wait additional time if necessary.
    */

    time_now = dtime_now();
    already = (int) ((time_now - time_ptt) * 100.);
    wait_more = duration - already;

@SmithChart
Copy link

It seems we are hunting a "heisenbug" here: I tried to have a closer look at the xmit.c toady. But I can not reproduce the issue anymore. Today everything works totally fine. :/

A litte further down in xmit.x wb2osz has already brought some debug infrastructure in place:
https://github.com/wb2osz/direwolf/blob/master/xmit.c#L908

I have enabled some of the debugging messages in my build:

From: Chris Fiege <chris@tinyhost.de>
Date: Mon, 24 Dec 2018 13:53:44 +0100
Subject: [PATCH] xmit.c: Enable Debug output

Signed-off-by: Chris Fiege <chris@tinyhost.de>
---
 xmit.c | 10 +---------
 1 file changed, 1 insertion(+), 9 deletions(-)

diff --git a/xmit.c b/xmit.c
index 19a9ad0d87cb..cbd3df030a4b 100644
--- a/xmit.c
+++ b/xmit.c
@@ -749,10 +749,8 @@ static void xmit_ax25_frames (int chan, int prio, packet_t pp, int max_bundle)
 // TODO: This was written assuming bits/sec = baud.
 // Does it is need to be scaled differently for PSK?
 
-#if DEBUG
 	text_color_set(DW_COLOR_DEBUG);
 	dw_printf ("xmit_thread: Turn on PTT now for channel %d. speed = %d\n", chan, xmit_bits_per_sec[chan]);
-#endif
 	ptt_set (OCTYPE_PTT, chan, 1);
 
 
@@ -887,10 +885,8 @@ static void xmit_ax25_frames (int chan, int prio, packet_t pp, int max_bundle)
 	already = (int) ((time_now - time_ptt) * 1000.);
 	wait_more = duration - already;
 
-#if DEBUG
 	text_color_set(DW_COLOR_DEBUG);
 	dw_printf ("xmit_thread: xmit duration=%d, %d already elapsed since PTT, wait %d more\n", duration, already, wait_more );
-#endif
 
 	if (wait_more > 0) {
 	  SLEEP_MS(wait_more);
@@ -903,21 +899,17 @@ static void xmit_ax25_frames (int chan, int prio, packet_t pp, int max_bundle)
 
 	  /* Looks like a bug with the RPi audio system. Never an issue with Ubuntu.  */
 	  /* This runs over randomly sometimes. TODO:  investigate more fully sometime. */
-#ifndef __arm__
 	  text_color_set(DW_COLOR_ERROR);
 	  dw_printf ("Transmit timing error: PTT is on %d mSec too long.\n", -wait_more);
-#endif
 	}
 
 /*
  * Turn off transmitter.
  */
-#if DEBUG
 	text_color_set(DW_COLOR_DEBUG);
 	time_now = dtime_now();
 	dw_printf ("xmit_thread: Turn off PTT now. Actual time on was %d mS, vs. %d desired\n", (int) ((time_now - time_ptt) * 1000.), duration);
-#endif
-		
+
 	ptt_set (OCTYPE_PTT, chan, 0);
 
 } /* end xmit_ax25_frames */

Maybe you can give this a try on your setup?

@SmithChart SmithChart mentioned this issue Feb 10, 2019
Closed
@wb2osz
Copy link
Owner

wb2osz commented Feb 16, 2019

This has been isolated to a small test case.
https://github.com/wb2osz/rpi-usb-audio-bug

@meinja
Copy link
Author

meinja commented Feb 26, 2019

Has anyone tried an older version Raspian distro to see if that makes a difference? I'll try it here on my RPi3b, but it won't be for some time yet.

@wb2osz
Copy link
Owner

wb2osz commented Nov 24, 2019

The problem was reported here but no one seems interested.
https://bugs.launchpad.net/bugs/1819560
It was confirmed as being a problem but it hasn't been assigned to anyone.
Maybe if more people piled on to the comment section it would get some attention.

@wb2osz
Copy link
Owner

wb2osz commented Nov 24, 2019

Same as #194

@wb2osz
Copy link
Owner

wb2osz commented Oct 20, 2023

Duplicate. See #194

@wb2osz wb2osz closed this as completed Oct 20, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@wb2osz @SmithChart @meinja