wow
I have a video from 2nd April which started and has a jump of ~72 minutes and then completes !
jump from 14:11:59 to next frame 15:23:39
Totally coincides with my little logger (30s intervals):
2022-04-02 14:11:44 35.2 0x0 1000000000 170888 kB
2022-04-02 15:23:24 30.4 0x0 800000000 169540 kB
and journalctl extract:
Apr 02 14:02:09 DietPi19 dietpi-wifi-monitor.sh[361]: [ OK ] DietPi-WiFi_Monitor | Completed
Apr 02 14:09:00 DietPi19 systemd[1]: Starting Clean php session files...
Apr 02 14:09:01 DietPi19 CRON[12142]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Apr 02 14:09:01 DietPi19 CRON[12145]: (root) CMD ( [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Apr 02 14:09:01 DietPi19 CRON[12142]: pam_unix(cron:session): session closed for user root
Apr 02 14:09:01 DietPi19 systemd[1]: phpsessionclean.service: Succeeded.
Apr 02 14:09:01 DietPi19 systemd[1]: Finished Clean php session files.
Apr 02 14:09:01 DietPi19 systemd[1]: phpsessionclean.service: Consumed 1.198s CPU time.
Apr 02 15:23:24 DietPi19 systemd[1]: Starting Clean php session files...
Apr 02 15:23:26 DietPi19 systemd[1]: phpsessionclean.service: Succeeded.
Apr 02 15:23:26 DietPi19 systemd[1]: Finished Clean php session files.
Apr 02 15:23:26 DietPi19 camrun.sh[360]: [b3b006c0] main input error: ES_OUT_SET_(GROUP_)PCR is called too late (jitter of -31499 ms ignored)
real time clock was reset by the daily CRON job at ~1:30 am
some observed unusual behaviour when investigating clock and ntp.
the command timedatectl timesync-status restarts the systemd.timesyncd service (see below)
It’s odd that a status check restarts a service?
Other than that, could it be that I have process (perhaps VLC) that needs the ntp service to be active, and maybe with the relevant files in /var/lib/systemd/timesync ?
There’s no other issues that I can find on the web regarding cam streaming, but then I guess they are not running on DietPi - therefore, probably have systemd.timesyncd service running and therefore an active ntp service ?
Can I switch DietPi-TimeSync off and run systemd.timesyncd ?
dietpi@DietPi19:~$ timedatectl
Local time: Wed 2022-04-20 15:58:34 BST
Universal time: Wed 2022-04-20 14:58:34 UTC
RTC time: n/a
Time zone: Europe/London (BST, +0100)
System clock synchronized: yes
NTP service: active
RTC in local TZ: no
dietpi@DietPi19:~$ sudo systemctl stop systemd-timesyncd
dietpi@DietPi19:~$ timedatectl
Local time: Wed 2022-04-20 15:59:04 BST
Universal time: Wed 2022-04-20 14:59:04 UTC
RTC time: n/a
Time zone: Europe/London (BST, +0100)
System clock synchronized: yes
NTP service: inactive
RTC in local TZ: no
dietpi@DietPi19:~$ timedatectl timesync-status
Server: 192.168.1.1 (192.168.1.1)
Poll interval: 32s (min: 32s; max 34min 8s)
Packet count: 0
dietpi@DietPi19:~$ timedatectl
Local time: Wed 2022-04-20 15:59:54 BST
Universal time: Wed 2022-04-20 14:59:54 UTC
RTC time: n/a
Time zone: Europe/London (BST, +0100)
System clock synchronized: yes
NTP service: active
RTC in local TZ: no
dietpi@DietPi19:~$
Basically the DietPi daily job will trigger a time sync once a nigh. The default execution time for daily jobs is 1:25. This this is not required, daily time sync could be disabled using dietpi-config.
To be able to check the status, you simple could use
systemctl status systemd-timesyncd.service
journalctl -u systemd-timesyncd.service
Thanks, with dietpi-config I set time sync to mode 4, ie using timesyncd.service
Let’s see what happens …
Before this, this morning system clock to real clock was out by the 72 minutes
By this afternoon, it was out by 2x72 minutes when I reset to mode 4 timesyncd at 15:43
journalctl … contiguous log
Apr 22 13:20:20 DietPi19 camrun.sh[363]: [b3b006c0] main input error: ES_OUT_SET_(GROUP_)PCR is called too late (jitter of -31939 ms ignored)
Apr 22 13:20:20 DietPi19 camrun.sh[363]: [018467f8] main decoder error: Timestamp conversion failed for 256091500001: no reference clock
Apr 22 13:20:20 DietPi19 camrun.sh[363]: [018467f8] main decoder error: Could not convert timestamps 0, 0 for h264
Apr 22 13:20:21 DietPi19 systemd[1]: Starting Network Time Synchronization...
Apr 22 13:20:22 DietPi19 systemd[1]: Started Network Time Synchronization.
Apr 22 15:43:34 DietPi19 systemd-timesyncd[2182]: Initial synchronization to time server 192.168.1.1:123 (192.168.1.1).
Apr 22 15:43:34 DietPi19 systemd[1]: Starting Clean php session files...
Do you know what this camrun.sh is?
It looks good based on your logs from 18/19. April, doesn’t it? Successful sync at boot and successful sync at 1:25 without a jump. So it really seems to be the cam service which causes the system clock hanging 
. Let’s see whether daemon mode helps.
Another idea would be to switch to modern camera driver stack:
sed -i 's/^[[:blank:]]*start_x=.*$/#start_x=0/' /boot/config.txt # disable legacy camera stack
sed -i 's/^[[:blank:]]*gpu_mem/#gpu_mem/' /boot/config.txt # revert to default GPU memory (sufficient for modern camera driver)
G_CONFIG_INJECT 'dtoverlay=vc4-f?kms-v3d' 'dtoverlay=vc4-kms-v3d' /boot/config.txt # enable KMS display driver stack
G_CONFIG_INJECT 'camera_auto_detect=' 'camera_auto_detect=1' /boot/config.txt # enable modern camera driver
reboot
that’s my camera stream script !!
I’m more suspicious of vlc
I guess I’ll need to switch to the modern stack sometime though.
I’m also thinking of trying a different camera and connector - just in case hardware.
Thanks for keeping an eye on this even though I’m intermittent on responses.
recent results with systemd.timectl.service
Clock kept time OK, but the system stalling still occurs, about 3 times per day, 5 times yesterday.
extracts from my logger script running every 30 seconds
note that CPU increase to 1000k about an hour after the restart at 800k then runs at that (max) until the stall.
Nothing else untoward in the logs
- php session clean at 19 and 39 minutes past the hour
- CRON at 17 minutes past for pam session
So, I can easily detect the stall, but cannot predict it or get a system snapshot when it happens.
logger extracts from this period:
– Journal begins at Fri 2022-04-22 16:30:11 BST, ends at Mon 2022-04-25 17:39:02 BST. –
2022-04-23 12:54:33 41.2 0x0 1000000000 154344 kB
2022-04-23 14:06:11 37.4 0x0 800000000 154344 kB
2022-04-23 17:18:58 42.8 0x0 1000000000 135884 kB
2022-04-23 18:30:46 37.9 0x0 800000000 135884 kB
2022-04-23 19:27:19 43.3 0x0 1000000000 135884 kB
2022-04-23 20:39:12 38.5 0x0 800000000 135884 kB
2022-04-24 08:01:05 39.5 0x0 1000000000 135404 kB
2022-04-24 09:13:08 34.2 0x0 700000000 135280 kB
2022-04-24 12:55:16 40.1 0x0 1000000000 135280 kB
2022-04-24 14:06:58 37.9 0x0 800000000 135280 kB
2022-04-24 15:09:35 41.2 0x0 1000002000 135280 kB
2022-04-24 16:21:22 36.9 0x0 800000000 135280 kB
2022-04-25 06:14:41 36.9 0x0 1000000000 124760 kB
2022-04-25 07:26:28 37.4 0x0 800000000 124516 kB
2022-04-25 09:05:24 41.2 0x0 1000000000 122036 kB
2022-04-25 10:17:08 36.3 0x0 800000000 121916 kB
2022-04-25 11:29:50 40.1 0x0 1000000000 121672 kB
2022-04-25 12:41:39 35.8 0x0 800000000 121300 kB
2022-04-25 13:43:15 40.1 0x0 1000000000 121188 kB
2022-04-25 14:55:01 35.8 0x0 800000000 121188 kB
2022-04-25 16:13:43 37.9 0x0 1000000000 120444 kB
2022-04-25 17:25:46 37.4 0x0 800000000 108416 kB
Just noting here … I started a new topic, because…
I discovered VLC is not optimal anymore - just broken.
I upgraded to the ‘modern’ libcamera stack.
I used a RTSP streamer solution: Mediamtx.
1 Like