Another flicker issue

[btownshend]

First, thanks for a great library and all the thought that's gone into the details!

I'm working with a 64x64 matrix and see drops in intensity randomly every 5-15s. I've gone through your notes and tried everything to eliminate these:

• added 3300 uf low-ESD caps at the leads
• have a solid 40A power supply with heavy gauge hookup
• using an Adafruit hat with the PWM modification
• stopped audio, GUI on the Pi
• no other processes running
• tried the iso1cpus=3 setting
• running with
  pixel-push -i wlan0 -U --led-chain=4 --led-parallel=1 -R 90 -u 65507 --led-show-refresh --led-scan-mode=0 --led-gpio-mapping=adafruit-hat-pwm --led-slowdown-gpio=2 -d
• uname -a:
  Linux raspberrypi 4.9.35-v7+ Added V-Mapper:Z for flipped orientation panels chains #1014 SMP Fri Jun 30 14:47:43 BST 2017 armv7l GNU/Linux
• running on Pi 3 Model B

I hooked up a photoresistor to a scope to capture what I'm seeing visually -- see attached image. Looks like ~160Hz refresh rate with occasional drops in level.

Any other ideas?

Thanks,
Brent

[hzeller]

• Make sure to not run anything else on the Pi. Just having a top running, will reduce brightness every time there is refresh of the display.
• it is isolcpus not iso1cpus (for cpu isolation)
• Try setting the DISABLE_RT_THROTTLE setting. This in particular could explain relatively regular brightness changes.

[btownshend]

• Nothing else running
• Compiled with DISABLE_RT_THROTTLE -- no difference
• Yes, I put in "isolcpus=3" in /boot/cmdline.txt (with an "el" not "1")
On the last point though, looking at the output of pidstat shows pixel-push on CPU1 along with several other daemons.

[btownshend]

`pi@raspberrypi:~/Beatfield/RaspberryPi/extern/rpi-matrix-pixelpusher $ pidstat
Linux 4.9.35-v7+ (raspberrypi)  01/19/2018      _armv7l_        (4 CPU)

10:24:27 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
10:24:27 PM     0         1    0.04    0.04    0.00    0.08     2  systemd
10:24:27 PM     0         3    0.00    0.00    0.00    0.00     0  ksoftirqd/0
10:24:27 PM     0         7    0.02    0.00    0.00    0.02     2  rcu_sched
10:24:27 PM     0         9    0.00    0.00    0.00    0.00     0  migration/0
10:24:27 PM     0        13    0.00    0.00    0.00    0.00     1  migration/1
10:24:27 PM     0        14    0.00    0.00    0.00    0.00     1  ksoftirqd/1
10:24:27 PM     0        18    0.00    0.00    0.00    0.00     2  migration/2
10:24:27 PM     0        19    0.00    0.00    0.00    0.00     2  ksoftirqd/2
10:24:27 PM     0        23    0.00    0.00    0.00    0.00     3  migration/3
10:24:27 PM     0        87    0.00    0.07    0.00    0.07     0  irq/92-mmc1
10:24:27 PM     0        90    0.00    0.02    0.00    0.02     0  mmcqd/0
10:24:27 PM     0        92    0.00    0.00    0.00    0.00     3  kworker/3:1
10:24:27 PM     0        93    0.00    0.00    0.00    0.00     0  jbd2/mmcblk0p7-
10:24:27 PM     0       128    0.03    0.02    0.00    0.05     1  systemd-journal
10:24:27 PM     0       136    0.00    0.01    0.00    0.01     0  kworker/0:2
10:24:27 PM     0       147    0.01    0.00    0.00    0.01     0  systemd-udevd
10:24:27 PM     0       256    0.03    0.00    0.00    0.03     0  brcmf_wdog/mmc1
10:24:27 PM     0       433    0.00    0.00    0.00    0.00     2  cron
10:24:27 PM     0       434    0.01    0.01    0.00    0.02     0  rsyslogd
10:24:27 PM   105       435    0.21    0.07    0.00    0.28     0  avahi-daemon
10:24:27 PM   104       440    0.01    0.00    0.00    0.01     1  dbus-daemon
10:24:27 PM 65534       475    0.00    0.00    0.00    0.00     1  thd
10:24:27 PM     0       477    0.00    0.00    0.00    0.00     0  dhcpcd
10:24:27 PM     0       519    0.00    0.00    0.00    0.00     2  systemd-logind
10:24:27 PM     0       536    0.00    0.00    0.00    0.00     0  sshd
10:24:27 PM     0       538    0.00    0.00    0.00    0.00     2  vncserver-x11-s
10:24:27 PM     0       561    0.02    0.04    0.00    0.05     0  vncserver-x11-c
10:24:27 PM     0       562    0.00    0.00    0.00    0.00     1  wpa_supplicant
10:24:27 PM     0       572    0.00    0.00    0.00    0.00     1  agetty
10:24:27 PM   106       574    0.01    0.01    0.00    0.01     1  ntpd
10:24:27 PM     0       709    0.00    0.00    0.00    0.00     2  bluetoothd
10:24:27 PM     0      1082    0.00    0.00    0.00    0.00     2  kworker/2:0
10:24:27 PM     0      1243    0.00    0.00    0.00    0.00     0  sshd
10:24:27 PM  1000      1247    0.00    0.00    0.00    0.00     2  systemd
10:24:27 PM  1000      1254    0.03    0.03    0.00    0.05     2  sshd
10:24:27 PM  1000      1256    0.05    0.01    0.00    0.05     0  bash
10:24:27 PM     0      1257    0.00    0.06    0.00    0.06     2  kworker/u8:2
10:24:27 PM     0      2159    0.00    0.00    0.00    0.00     0  packagekitd
10:24:27 PM     0      2163    0.00    0.00    0.00    0.00     0  polkitd
10:24:27 PM     0      2183    0.00    0.01    0.00    0.01     0  kworker/u8:3
10:24:27 PM     0      2266    0.00    0.00    0.00    0.00     1  kworker/1:0
10:24:27 PM     0      2301    0.00    0.00    0.00    0.00     2  kworker/u8:1
10:24:27 PM     0      2473    0.00    0.00    0.00    0.00     1  kworker/1:1
10:24:27 PM     0      2539    0.00    0.00    0.00    0.00     3  kworker/3:0
10:24:27 PM     1      2550    6.64    0.26    0.00    6.90     1  pixel-push
10:24:27 PM     0      3429    0.00    0.01    0.00    0.01     0  kworker/u8:0
10:24:27 PM     0      3432    0.00    0.00    0.00    0.00     1  kworker/1:2
10:24:27 PM  1000      3537    0.00    0.00    0.00    0.00     1  pidstat
pi@raspberrypi:~/Beatfield/RaspberryPi/extern/rpi-matrix-pixelpusher $ `

[btownshend]

Or am I missing something? Do I need to use taskset to assign pixel-push to CPU 3?

[btownshend]

Hmm, modified my startup script to use:

taskset -c 3 pixel-push -i wlan0 -U --led-chain=4 --led-parallel=1 -R 90 -u 65507 --led-
show-refresh --led-scan-mode=0 --led-gpio-mapping=adafruit-hat-pwm --led-slowdown-gpio=2 -d

Check with pidstat now shows only pixel-push on CPU 3 (with only kworker/3:0, kworker/3:1, and migration/3), other processes on other CPUs

But, perhaps it glitches a little less, but there are still noticeable dropouts at 5-10s intervals.

Also, note that I'm not sending any data continually to the pixelpush -- just sent a fixed all-on display and then leaving that static.

[hzeller]

Unfortunately, the kernel sometimes takes away some CPU time doing just whatever accounting it wants, even though it should leave a RT thread isolated on core3 alone. But yeah, there are kernel workers on that core - I wonder if they can be disabled ?

Only the main update thread should run on core3, all the other threads of pixel-push can (and should) be on other cores.

Interesting if the taskset is not working, I wonder if this also results in the realtime-thread not being a realtime thread ? Can you check if the thread that is using the most CPU (that is the update thread) is actually a RT thread ? Maybe that feature is not compiled into that kernal ?

In the end, we're dealing with a multuser/multitasking operating system that in the stock kernel version is not optimized for realtime stuff. So it might be worthwhile trying to get the most stripped-down kernel with all the realtime-ness goodies enabled compiled. Unfortunately, I don't know the best settings here, but if there is someone here knowing about a good set of kernel settings to enable and disable, that would be very helpful.

[btownshend]

If I understand correctly, then pidstat and chrt will not show the process on CPU 3 or the scheduling as FIFO because only the refresh thread is set to be realtime on CPU 3? Because if it is launched normally, the process ends up with SCHED_OTHER and not bound to CPU 3.

I tried launching it with:
chrt -f 99 taskset -c 3
and then I do indeed see that chrt shows the correct scheduler (FIFO) and priority (99) and pidstat does show CPU3.

Yet, the flickering continues.

I noticed that there is a SLEEP_JITTER define in the code -- will that help isolate whether the issue is really CPU scheduling?

[hzeller]

the DEBUG_SLEEP_JITTER is just a way to quantify the jitter for sleeping, but if you are using the PWM, sleep is essentially not used.

I suspect that the kernel is taking some CPU time when clocking in the data, which means that the time sending things into the matrix takes longer, so there are longer dark phases.

Best next steps are essentially looking what is happening when you see the brightness change. As described in the readme, some user was seeing that a regular ntp update was creating some faint flicker, which went away when it was disabled.

[btownshend]

Sounds like a tricky thing to debug!

I killed ntpd, might've made things a little better, but there are still flickers.

Note that running things in a terminal window creates a lot of flicker (e.g. "service --status-all"
is especially bad). Seems to me that if the panel is running on an isolated CPU, running user-level commands shouldn't affect it much.

Is there any way the library can detect if something was off in timing? Or, failing that, is there a good place (or place(s)) to hook a scope onto the PI to measure precisely what's going wrong?

Thanks for all the help!
Brent

[hzeller]

yes, running things in the terminal creates a lot of flicker. I suspect there is something going on with using the memory bus that starves the memory bus. I noticed that myself in some situations, but haven't had a time to find a strategy how to poke inside the kernel to figure out what is going on. So if you want to look into that, that would be highly appreciated.

Regarding measuring, I'd probably hook the scope on the strobe/latch signal. It should be triggered with (number_of_rows/2) * refresh frequency so you can quickly see if there is some huge variation. Now, how to correlate that with something that goes on inside the kernel (between the last and the delayed strobe signal that is), I don't know. I suspect, there are some kernel activity logging tools, so if we can timestamp things properly there, it might lead to the culprit...

[btownshend]

Ok, will try that. In the meantime, have been playing with the 'perf' command and looking at:
[http://epickrram.blogspot.com/2015/09/reducing-system-jitter.html]

Using:
sudo perf record -e "sched:sched_switch" -C 3
then
sudo perf script

Clearly shows context switching between pixel_push on CPU 3 and other processes (such as the bash, grep, etc generated by running "service -s-status-all") that shouldn't be on CPU 3, if I understand isolcpu correctly. Yet, pidstat never shows anything but the kworkers and migration on that CPU.

[hzeller]

Yes, I also have the strong suspicion that the kernel only takes the isolcpu as, uhm, 'suggestion'.
So would be good if you could figure out what else we have to do to make it work as we expect it to.

[andygrace]

Hi and just popping up for a second. This behaviour mentioned is what I’ve always understood to be the case. isolcpus is only effective for isolation inside user-space. The kernel still decides if and when it wants to schedule kworker processes, right when your time-critical, cycle-accurate code is in the critical phase of its loop. That's the difference between a best-effort and a true real-time kernel, or at least it used to be that way! Cheers Andy

…

On 20 Jan 2018, at 7:38 pm, Henner Zeller ***@***.***> wrote: So would be good if you could figure out what else we have to do to make it work as we expect it to.

[btownshend]

Thanks for joining in Andy.

That sounds reasonable, but what I'm seeing is that shell scripts run on the command line end up with their commands (grep, bash, etc) running on the isolated CPU. Or at least that's what perf shows. I'm wondering if maybe they get launched on whatever CPU and then subsequently get moved off of the isolated one.

[btownshend]

Henner,
I was able to capture the signals on a scope and I think I see the physical manifestation of this. On the image below, the top trace is clk, then latch, and the bottom is OE. This appears to have captured 3 full updates. The right 2 look similar, but the left one has a 20usec gap in it. There may also be longer gaps, but I haven't figured out how to get the scope to trigger on the failures.