wave_send_repeat() does double the delay time of pulses

[hayguen]

Hello,
i'm recording a bunch of pulses and re-playing them quite similar to the example http://abyz.me.uk/rpi/pigpio/python.html#wave_add_generic

my application records the remote control's signal for a power switch (or any other 433 MHZ OOK device) .. and replays the recorded signal later, e.g. to allow sort of home automization.
see https://github.com/hayguen/rc433_rpi
and https://github.com/hayguen/rc433_rpi/blob/master/tx_csv.py

using python3 and wave_send_repeat() failed to control the power switch at first attempt.
i thought, that the timing is not accurate enough,
that i've written https://github.com/hayguen/rc433_rpi/blob/master/tx_csv_pigpio.c
this worked - even using busy loops.

now, having recorded the transmitted signal of tx_csv.py with an RTLSDR, i realized that all pulse delays were doubled on air!
thus, halving all delay values (see ~line 50 in tx_csv.py) does work and switch the power.

i've tested with Raspberry Pi 3B+ and the latest Raspbian (2020-02-14) with the pigpio package containing version 71 and latest github master with version v74.

later (next days), i could test with a Raspberry Pi 1 and a 4B.

i tried to have a look into the sources .. but i could not understand. i'm missing an explanation how gpioWaveTxSend() works with DMA stuff. Especially how is DMA utilized to produce the delays?

however, if / when there's a bugfix, how can i determine in python if i should halve the delays - or not?

kind regards,
hayati

[joan2937]

Could you please prepare a short Python script which demonstrates this problem?

E.g. a script which is meant to generate pulses of 100 µs but actually results in pulses of 200 µs.

[hayguen]

try following script .. and connect RXPIN with TXPIN:

#!/usr/bin/env python3

import sys
import time
import pigpio
import numpy as np

# connect these two pins for testing
TXPIN = 17
RXPIN = 27
# transmit / expect pin/level change every DELAYUS us
DELAYUS = 200
SLEEP_SECS = 0.2   # wait/sleep while transmitting

bufused = 0
bufmax = 64   # rec max 32 pin changes
bufLevel = np.zeros( bufmax, dtype = np.dtype('uint8') )
bufTime  = np.zeros( bufmax, dtype = np.dtype('uint32') )

def cbf(gpio, level, tick):
	global bufused, bufmax, bufTime, bufLevel
	# just save incoming data, to be as fast as possible
	if RXPIN == gpio and bufused < bufmax:
		bufTime[bufused] = tick
		bufLevel[bufused] = level
		bufused = bufused + 1


p = pigpio.pi()
print("pigpio version: ", p.get_pigpio_version())

p.set_mode(TXPIN, pigpio.OUTPUT)
p.write(TXPIN, 0)
p.set_mode(RXPIN, pigpio.INPUT)
p.set_pull_up_down(RXPIN, pigpio.PUD_DOWN)
cb = p.callback(RXPIN, pigpio.EITHER_EDGE, cbf)

pulseTrain=[]
pinMask = 1 << TXPIN
for k in range(10):
  pulseTrain.append(pigpio.pulse(pinMask, 0, DELAYUS))
  pulseTrain.append(pigpio.pulse(0, pinMask, DELAYUS))

p.wave_clear() # clear any existing waveforms
p.wave_add_generic(pulseTrain)
pT = p.wave_create()
# => same result for wave_send_repeat() or wave_send_once()
print("transmitting ..")
p.wave_send_repeat(pT)
#p.wave_send_once(pT)
time.sleep(0.2)
p.wave_tx_stop() # stop waveform
print(".. stopped")

p.wave_clear()
time.sleep(SLEEP_SECS)
p.write(TXPIN, 0)

for k in range(1, bufused):
  deltaT = 0
  if k > 0:
    deltaT = pigpio.tickDiff(bufTime[k-1], bufTime[k])
  newLevel = bufLevel[k]
  print("{}: measured delta {} us, level {} => delay factor {}".format(k, deltaT, newLevel, deltaT / DELAYUS))

i get following output with 400 us between each pin change,
where it should be DELAYUS = 200 us:

pi@raspberrypi:~/rc433_rpi $ ./testDelay.py
pigpio version:  74
transmitting ..
.. stopped
1: measured delta 400 us, level 0 => delay factor 2.0
2: measured delta 400 us, level 1 => delay factor 2.0
3: measured delta 400 us, level 0 => delay factor 2.0
4: measured delta 400 us, level 1 => delay factor 2.0
5: measured delta 400 us, level 0 => delay factor 2.0
6: measured delta 400 us, level 1 => delay factor 2.0
7: measured delta 400 us, level 0 => delay factor 2.0
8: measured delta 400 us, level 1 => delay factor 2.0
9: measured delta 400 us, level 0 => delay factor 2.0
10: measured delta 400 us, level 1 => delay factor 2.0
11: measured delta 400 us, level 0 => delay factor 2.0

by the way: the receive timings are really accurate, i had not expected.

[hayguen]

above (doubled delay) result was on Raspberry Pi 3B+ with latest Raspbian.

for completeness, here it's pinout chip infos:

Revision           : a020d3
SoC                : BCM2837
RAM                : 1024Mb
Storage            : MicroSD
USB ports          : 4 (excluding power)
Ethernet ports     : 1
Wi-fi              : True
Bluetooth          : True
Camera ports (CSI) : 1
Display ports (DSI): 1

same SD-card on Raspberry Pi 1B (of a friend) produced quite similar results, doubling the delay:

only the measured delay jittered up to 5 us - think, that is quite ok.
here the chip info of pinout:

Revision           : 000f
SoC                : BCM2835
RAM                : 512Mb
Storage            : SD
USB ports          : 2 (excluding power)
Ethernet ports     : 1
Wi-fi              : False
Bluetooth          : False
Camera ports (CSI) : 1
Display ports (DSI): 1

Interestingly on a Raspberry Pi 4B with following pinout infos:

Revision           : b03111
SoC                : BCM2711
RAM                : 2048Mb
Storage            : MicroSD
USB ports          : 4 (excluding power)
Ethernet ports     : 1
Wi-fi              : True
Bluetooth          : True
Camera ports (CSI) : 1
Display ports (DSI): 1

there is NO error:

pigpio version:  74
transmitting ..
.. stopped
1: measured delta 200 us, level 0 => delay factor 1.0
2: measured delta 200 us, level 1 => delay factor 1.0
3: measured delta 200 us, level 0 => delay factor 1.0
4: measured delta 200 us, level 1 => delay factor 1.0
5: measured delta 200 us, level 0 => delay factor 1.0
6: measured delta 200 us, level 1 => delay factor 1.0
7: measured delta 200 us, level 0 => delay factor 1.0
8: measured delta 200 us, level 1 => delay factor 1.0
9: measured delta 200 us, level 0 => delay factor 1.0
10: measured delta 200 us, level 1 => delay factor 1.0
11: measured delta 200 us, level 0 => delay factor 1.0

[joan2937]

Unfortunately it works as expected on my Pi3B+.

./issue.py 
pigpio version:  74
transmitting ..
.. stopped
1: measured delta 200 us, level 0 => delay factor 1.0
2: measured delta 200 us, level 1 => delay factor 1.0
3: measured delta 200 us, level 0 => delay factor 1.0
4: measured delta 200 us, level 1 => delay factor 1.0
5: measured delta 200 us, level 0 => delay factor 1.0
6: measured delta 200 us, level 1 => delay factor 1.0
7: measured delta 200 us, level 0 => delay factor 1.0
8: measured delta 200 us, level 1 => delay factor 1.0
9: measured delta 200 us, level 0 => delay factor 1.0
10: measured delta 200 us, level 1 => delay factor 1.0
11: measured delta 200 us, level 0 => delay factor 1.0
12: measured delta 200 us, level 1 => delay factor 1.0
13: measured delta 200 us, level 0 => delay factor 1.0
14: measured delta 200 us, level 1 => delay factor 1.0
...

Hardware	: BCM2835
Revision	: a020d3
Serial		: 0000000066a17c79
Model		: Raspberry Pi 3 Model B Plus Rev 1.3

[guymcswain]

Interesting. Have you looked at the signal with oscilloscope and is it clean? I'm curious as to why you set the pulldown.

[joan2937]

There is a timing problem on some Pis which has never been tracked down. This may be another example of the same problem.

[guymcswain]

@joan2937 , is the timing issue you're referring to the one associated with have a monitor/display attached? I seem to recall something of that nature.

[hayguen]

from cat /proc/cpuinfo i get exactly same as you:

Hardware        : BCM2835
Revision        : a020d3
Serial          : 00000000ee3a9c68
Model           : Raspberry Pi 3 Model B Plus Rev 1.3

changing to PUD_OFF gives same doubled delay on my Pi 3B+.

i don't have an oscilloscope here at home :-(
i could try on one more Pi 3B+ ..
but i would like to remind, that i have the doubled delay also on a Pi 1.

any idea, how we could track this down? how can i assist?

[hayguen]

@joan2937 , is the timing issue you're referring to the one associated with have a monitor/display attached? I seem to recall something of that nature.

i have doubled delay on Pi 3B+ with display connected (working with screen/keyboard)
but also when working headless over ssh: same double delay.

previous test on Pi 4B was headless. would need to look for a display adapter ..

[joan2937]

@guymcswain That sounds right. It was never resolved. Nobody ever discovered a pattern as to which Pis were affected or why.

[hayguen]

tested on the another Pi 3B+: timing looks GOOD, delay factor is 1.

it's exactly same model (pinout command is in package python3-gpiozero !?!):

Revision           : a020d3
SoC                : BCM2837
RAM                : 1024Mb

cat /proc/cpuinfo delivers:

Hardware        : BCM2835
Revision        : a020d3
Serial          : 000000001fd6c90c
Model           : Raspberry Pi 3 Model B Plus Rev 1.3

[joan2937]

@hayguen Were you using the same SD card and PSU on the working and non-working Pi3B+ ?

[hayguen]

2nd Pi 3B+:
it was/still is different SD-card. PSU was just same model .. and now is exactly same PSU device.
WiFi is configured on this SD card.
always getting good results with this one.

now changed the SD-card for 2nd Pi 3B+ .. and have to connect Ethernet:
whoooo. now i get the doubled delay!!!

removed Ethernet, configured WiFi on 2nd Pi 3B+:
again: doubled delay.

[guymcswain]

@hayguen , prior to your initial testing, did you run the pigpio's test suite - x_pigpio.c et al? If not, can you run them and report the results.

[joan2937]

Okay. I have downloaded and burnt the image.

My initial tests seem to be seeing the same as you, i.e. the waveforms are twice as long as expected.

For my test I did the following after logging in to the image.

sudo pigpiod
pigs m 4 w
pigs wvag 16 0 100 0 16 100
pigs wvcre
pigs wvtxr 0

That should have resulted in a continuous square wave of 100µs on and 100µs off.

Instead I see a square wave of 200µs on and 200µs off (using piscope).

It's good that we can replicate the problem.

That said I am busy at the moment and need to prioritise tasks needed for @guymcswain so can't be sure when I will be able to investigate.

[hayguen]

@hayguen , prior to your initial testing, did you run the pigpio's test suite - x_pigpio.c et al? If not, can you run them and report the results.

i had not executed the test suite before - even wasn't aware of it.
here results of x_pigpio:

TEST  5.4  FAILED got 25 (callback: 50)
TEST  5.11 FAILED got 10 (wave tx busy, serial read: 0)

this happended 3 times on gpio25.
then, i changed the pin to gpio8 and gpio7: same results

[joan2937]

@hayguen Could you start the pigpio daemon with the -t0 option and see if that works okay.

sudo pigpiod -t0

[hayguen]

some more tests / insight:

setting hdmi_safe=1 in /boot/config.txt

• connecting a display (before powering the Pi),
  the error is gone: my test program and also the x_pigpio tests 5.4 and 5.11 no longer fail.

• having the display disconnected (headless), the error is still there; tests 5.4 and 5.11 fail

activating the comment in /boot/config.txt, thus removing hdmi_safe

• with display connected, there is no error with my test program and also no error with x_pigpio

• having the display disconnected (headless), the error is still there

before having played with hdmi_safe

by default hdmi_safe was commented in /boot/config.txt
and the error occured independent of display connected - or not

[hayguen]

@hayguen Could you start the pigpio daemon with the -t0 option and see if that works okay.

sudo pigpiod -t0

that is quite quite interesting!

• the display is currently disconnected - thus, i get the delay error
• killing the running daemon - and restarting the daemon (NOT the Pi) with option -t0: there is NO delay error :-)

-t value, clock peripheral, 0=PWM 1=PCM, default PCM
hmmm, now i remember, that i also played with the audio setting with sudo raspi-config
usually, i set 'force 3.5mm jack' .. what might have provoked the error

[hayguen]

let me ask, what are the implications for using PWM or PCM clock?
on what criterions, to make a choice as end user or even programmer, regarding pigpio as a black box?
think, we need some more documentation on this.

setting audio to 'always 3.5mm' with sudo raspi-config,
i get the delay error with display connected - or not, when starting gpiod without any options.

i'd suggest:

1. change the gpiod default clock to PWM, if it does not break something?!
2. print a warning, when setting PCM clock, that it could interfere with soundcard's 3.5mm output

[joan2937]

http://abyz.me.uk/rpi/pigpio/faq.html#Sound_isnt_working

[guymcswain]

@hayguen , pigpio has a wide user base and has been in existence for several years so changing default config is out of the question. But I could see value in coming up with a test that could determine if the alternate clock peripheral should be used. Since you have invested some time on this issue would you be interested in supporting the development of such a test?

I should add that there is already documentation in place. Selecting the alternate as default will create the need to document the cases that break under that scenario. This is why I suggest a test.

[hayguen]

Yes, I'd like to help.

[hayguen]

http://abyz.me.uk/rpi/pigpio/faq.html#Sound_isnt_working

let me notice, that i had no speakers connected at any time

[guymcswain]

Off the top of my head, using the C library one could generate pulses for timing measurement and switch between the two clock sources. If you want to help I'll accept a PR. Maybe it could be a part of x_pigpio.c

[hayguen]

x_pigpio requires that pin GPIO25 is unconnected or open. Suppose, this is why the tests are not automatically executed with every build / make.

the (python) test program (from above) requires having connected 2 pins.

however, both test programs have the problem, that they are executed only once in lifetime and usually not again. thus, end users would not realize the problem :-(
in addition, we know, that the problem depends on sound output configuration and/or connection of display, what might change over time - possibly even at runtime!?

i would prefer something, to run at every start of pigpiod - without any requirements.
can we check the audio output configuration somehow?
can we check the clock settings somehow? what piece of OS kernel / sound driver does reconfigure the PCM clock?
however, can someone point me to some reference documentation? give me a starting point?

[guymcswain]

Just looking for something simple that users can run when the question comes up. I don't want to support anything complex nor try to protect against anything a user might do to his system.

[joan2937]

Perhaps something like the following. It should print 1.00 for no problem

#!/usr/bin/env python

import time
import pigpio

GPIO=4
MICROS=1000

pi = pigpio.pi()
if not pi.connected:
   exit()

pi.set_mode(GPIO, pigpio.OUTPUT)

pi.wave_add_generic(
   [pigpio.pulse(1<<GPIO,       0, MICROS), 
    pigpio.pulse(      0, 1<<GPIO, MICROS)])
wid = pi.wave_create()
if wid >= 0:
   start = time.time()
   pi.wave_chain([255, 0, wid, 255, 1, 200, 0]) # send wave 200 times
   while pi.wave_tx_busy():
      time.sleep(0.001)
   duration = time.time() - start
   pi.wave_delete(wid)
pi.stop()

EXPECTED_SECS = 400.0 * MICROS / 1000000.0

ratio = duration / EXPECTED_SECS

print("{:.2f}".format(ratio))

[guymcswain]

@joan2937 , yes this is along the line I'm thinking about. However, if the result is negative, can the test verify success when the alternate clock is selected. I don't think that can be done via pigpiod client

[hayguen]

i had a similar idea, but did go one step further:
it looks, there is no need to write to any pin, making it possible to test the clock even inside pigpiod.

following script works fine, to detect the erroneous timing - or not,
tested on Pi3B+ with different sound settings and different display connections:

#!/usr/bin/env python3
import time
import pigpio

DELAYUS = 500

p = pigpio.pi()
print("pigpio version: ", p.get_pigpio_version())

pulseTrain=[ pigpio.pulse(0, 0, DELAYUS), pulseTrain.append(pigpio.pulse(0, 0, DELAYUS) ]

p.wave_clear()
p.wave_add_generic(pulseTrain)
pT = p.wave_create()

p.wave_send_once(pT)
t1 = p.get_current_tick()
while p.wave_tx_busy():
  pass
t2 = p.get_current_tick()

p.wave_clear()
deltaT = pigpio.tickDiff(t1, t2)
ratio = deltaT / (2*DELAYUS)
print("passed time: {} us, expected {} us => ratio {}".format(deltaT, 2*DELAYUS, ratio))

increasing the test duration (above, only 1 ms), the determined ratio gets more accurate.
i'm just unsure for the busy loop and what the multitasking OS will do ..
with a higher test duration and accepting some inaccuracy, we could use normal sleeps, similar to Joan's variant.

it also looks, that timing does only change on (re)boot - and happily not at runtime.
having 'auto' setting for sound, booting with display has good timing, which stays good when removing the display. but no idea, what sound output did meanwhile .. however.

i'm working on a C version testing both clocks .. and want to test on Pi 1.
you can await test results and C version this evening or tomorrow.

[hayguen]

here's the standalone test program:

#include <stdio.h>
#include <stdlib.h>
#include <string.h>

#include <pigpio.h>

#define DELAY_US 25000

int main(int argc, char *argv[])
{
  gpioPulse_t pulse[2];
  uint32_t t0, t1, diffTick, expectedDelta;
  int k, ret, wave_id, testClock;
  float ratio;
  unsigned cfgMicros, cfgPeripheral;

  testClock = -1;  /* -1: test both configurations; 0: test PWM; 1: test PCM */

  if ( 1 < argc ) {
    if (!strcmp(argv[1], "pcm"))
      testClock = 1;
    else if (!strcmp(argv[1], "pwm"))
      testClock = 0;
    else
      testClock = atoi(argv[1]);
    if (testClock)
      testClock = 1;
  }

  for ( cfgPeripheral = 0; cfgPeripheral < 2; ++cfgPeripheral ) {
    if ( !( testClock == -1 || testClock == cfgPeripheral ) )
      continue;

    cfgMicros = 5;
    fprintf(stdout, "testing %s clock\n", (cfgPeripheral ? "PCM" : "PWM") );

    gpioCfgClock(cfgMicros, cfgPeripheral, 0);
    if (gpioInitialise() < 0)
    {
      fprintf(stderr, "pigpio initialisation failed.\n");
      return (cfgPeripheral+1)*10;
    }

    for ( k = 0; k < 2; ++k ) {
      pulse[k].gpioOn = 0;
      pulse[k].gpioOff = 0;
      pulse[k].usDelay = DELAY_US;
    }

    ret = gpioWaveAddNew();
    if (ret) {
      fprintf(stderr, "error at gpioWaveAddNew()\n");
      return 1;
    }
    ret = gpioWaveAddGeneric(2, pulse);
    if (ret != 2) {
      fprintf(stderr, "error at gpioWaveAddGeneric()\n");
      return 2;
    }
    wave_id = gpioWaveCreate();
    if (wave_id < 0) {
      fprintf(stderr, "error at gpioWaveCreate()\n");
      return 3;
    }

    ret = gpioWaveTxSend(wave_id, PI_WAVE_MODE_ONE_SHOT );
    t0 = gpioTick();
    if (ret <= 0) {
      fprintf(stderr, "error at gpioWaveTxSend()\n");
      return 4;
    }

    while ( gpioWaveTxBusy() ) {
      gpioDelay(500);
    }
    t1 = gpioTick();

    /*gpioWaveTxStop();*/
    gpioWaveClear();
    gpioTerminate();

    diffTick = t1 - t0;
    expectedDelta = DELAY_US + DELAY_US;
    ratio = (float)(diffTick) / (float)(expectedDelta);

    fprintf(stdout, "  delta = %u, expected = %u, ratio = %f\n", diffTick, expectedDelta, ratio);
    if ( 0.8F <= ratio && ratio <= 1.5F )
      fprintf(stdout, "  clock is OK\n");
    else if ( 1.8F <= ratio && ratio <= 2.2F )
      fprintf(stdout, "  clock is at half speed. all delays are doubled!\n");
    else
      fprintf(stdout, "  clock is corrupt!\n");
  }

  return 0;
}

i've extended the test duration to 50 ms per clock.
time reports ~ 550 ms on Raspi 1, with the PCM clock doubling the duration.
here the full output:

# time build/test_delay
testing PWM clock
  delta = 50281, expected = 50000, ratio = 1.005620
  clock is OK
testing PCM clock
  delta = 100270, expected = 50000, ratio = 2.005400
  clock is at half speed. all delays are doubled!

real    0m0,551s
user    0m0,075s
sys     0m0,302s

one more info:

• the doubled delay does occur after first activation of sound output,
  which is automatically initalized with the sound daemon (think pulseaudio),
  when booting into GUI (systemctl set-default graphical.target)
• having switched off boot to GUI (systemctl set-default multi-user.target),
  because that takes lots of time on Raspi 1, i wondered why the error doesn't occur.
  after playing some silence to the 3.5mm audio output (advanced options of raspi-config)
  with dd if=/dev/zero bs=4 count=24000 of=- |aplay -f dat,
  the error returned

i'll prepare a pull request ..

[hayguen]

see pull request #332