bash sleep 10 is very inconsistent on VM

N

Nathan Stratton

Well-Known Member
Dec 28, 2018
47
3
48
49
Running Proxmox 9.0.10 with Ubuntu 24.04 guest. I have been working with voipmonitor support staff who say my issues are because of my clock. I tested a simple script that SHOULD run every 10 seconds, but does not. This is on the weekend when my load is almost zero. Any ideas?

Code: 
#!/bin/bash
while true; do
  logger "testing"
  sleep 10
done

root@sbc1:~# ./vm_ts_delta.py -m "root: testing"
2025-10-04T17:29:53.300569+00:00 Δ --
2025-10-04T17:30:03.305025+00:00 Δ 10.004456s
2025-10-04T17:30:13.310022+00:00 Δ 10.004997s
2025-10-04T17:30:23.314695+00:00 Δ 10.004673s
2025-10-04T17:30:33.319805+00:00 Δ 10.005110s
2025-10-04T17:31:28.391582+00:00 Δ 55.071777s
2025-10-04T17:31:33.345483+00:00 Δ 4.953901s
2025-10-04T17:31:43.715279+00:00 Δ 10.369796s
2025-10-04T17:31:53.354599+00:00 Δ 9.639320s
2025-10-04T17:32:03.359214+00:00 Δ 10.004615s
2025-10-04T17:32:13.363874+00:00 Δ 10.004660s
2025-10-04T17:32:23.368547+00:00 Δ 10.004673s
2025-10-04T17:32:33.373016+00:00 Δ 10.004469s
2025-10-04T17:32:43.378332+00:00 Δ 10.005316s
2025-10-04T17:32:53.383152+00:00 Δ 10.004820s
2025-10-04T17:33:03.387500+00:00 Δ 10.004348s
2025-10-04T17:33:13.392116+00:00 Δ 10.004616s
2025-10-04T17:33:23.396723+00:00 Δ 10.004607s
2025-10-04T17:33:33.401224+00:00 Δ 10.004501s
2025-10-04T17:33:43.406053+00:00 Δ 10.004829s
2025-10-04T17:33:53.410427+00:00 Δ 10.004374s
2025-10-04T17:34:03.415093+00:00 Δ 10.004666s
2025-10-04T17:34:13.419749+00:00 Δ 10.004656s
2025-10-04T17:34:23.424383+00:00 Δ 10.004634s
2025-10-04T17:34:33.428689+00:00 Δ 10.004306s
2025-10-04T17:34:43.432382+00:00 Δ 10.003693s
2025-10-04T17:34:53.437171+00:00 Δ 10.004789s
2025-10-04T17:35:03.441862+00:00 Δ 10.004691s
2025-10-04T17:35:13.446552+00:00 Δ 10.004690s
2025-10-04T17:35:23.450848+00:00 Δ 10.004296s
2025-10-04T17:35:33.455303+00:00 Δ 10.004455s
2025-10-04T17:35:43.459681+00:00 Δ 10.004378s
2025-10-04T17:35:53.463755+00:00 Δ 10.004074s
2025-10-04T17:36:03.468143+00:00 Δ 10.004388s
2025-10-04T17:36:13.472586+00:00 Δ 10.004443s
2025-10-04T17:36:23.476673+00:00 Δ 10.004087s
2025-10-04T17:36:33.481269+00:00 Δ 10.004596s
2025-10-04T17:36:43.485596+00:00 Δ 10.004327s
2025-10-04T17:36:53.489842+00:00 Δ 10.004246s
2025-10-04T17:37:03.493716+00:00 Δ 10.003874s
2025-10-04T17:37:13.497918+00:00 Δ 10.004202s
2025-10-04T17:37:23.502030+00:00 Δ 10.004112s
2025-10-04T17:37:33.506134+00:00 Δ 10.004104s
2025-10-04T17:37:43.510638+00:00 Δ 10.004504s
2025-10-04T17:37:53.514893+00:00 Δ 10.004255s
2025-10-04T17:38:03.519455+00:00 Δ 10.004562s
2025-10-04T17:38:13.523952+00:00 Δ 10.004497s
2025-10-04T17:38:23.528298+00:00 Δ 10.004346s
2025-10-04T17:38:33.532831+00:00 Δ 10.004533s
2025-10-04T17:38:43.537448+00:00 Δ 10.004617s
2025-10-04T17:38:53.542177+00:00 Δ 10.004729s
2025-10-04T17:39:03.546425+00:00 Δ 10.004248s
2025-10-04T17:39:13.551075+00:00 Δ 10.004650s
2025-10-04T17:39:23.555882+00:00 Δ 10.004807s
2025-10-04T17:39:33.560538+00:00 Δ 10.004656s
2025-10-04T17:39:43.565025+00:00 Δ 10.004487s
2025-10-04T17:39:53.569707+00:00 Δ 10.004682s
2025-10-04T17:40:03.574346+00:00 Δ 10.004639s
2025-10-04T17:40:13.578952+00:00 Δ 10.004606s
2025-10-04T17:40:23.583312+00:00 Δ 10.004360s
2025-10-04T17:40:33.587313+00:00 Δ 10.004001s
2025-10-04T17:40:43.592147+00:00 Δ 10.004834s
2025-10-04T17:40:53.596769+00:00 Δ 10.004622s
2025-10-04T17:41:03.601114+00:00 Δ 10.004345s
2025-10-04T17:41:13.606131+00:00 Δ 10.005017s
2025-10-04T17:41:23.610568+00:00 Δ 10.004437s
2025-10-04T17:41:33.614704+00:00 Δ 10.004136s
2025-10-04T17:42:03.627976+00:00 Δ 30.013272s
2025-10-04T17:42:33.641606+00:00 Δ 30.013630s
2025-10-04T17:43:03.654901+00:00 Δ 30.013295s
2025-10-04T17:43:33.667864+00:00 Δ 30.012963s
2025-10-04T17:44:03.680685+00:00 Δ 30.012821s
2025-10-04T17:44:13.684866+00:00 Δ 10.004181s
2025-10-04T17:44:23.689004+00:00 Δ 10.004138s
2025-10-04T17:44:33.693491+00:00 Δ 10.004487s
2025-10-04T17:44:43.697769+00:00 Δ 10.004278s
2025-10-04T17:44:53.702312+00:00 Δ 10.004543s
2025-10-04T17:45:03.706611+00:00 Δ 10.004299s
2025-10-04T17:45:13.710896+00:00 Δ 10.004285s
2025-10-04T17:45:23.715515+00:00 Δ 10.004619s
2025-10-04T17:45:33.720136+00:00 Δ 10.004621s
 
You might want to share the script you're calling there. Information about your node and VM are also of interest.
 
Try this:

BEGIN countdown.sh
<code>
#!/bin/bash

# REF: https://stackoverflow.com/questions/12498304/using-bash-to-display-a-progress-indicator

# number
declare -i countto=$1
ctr=0

declare -a spin
spin[0]="-"
spin[1]='\'
spin[2]="|"
spin[3]="/"

echo -n "[$countto] ${spin[0]} " #$ctr"
#while [ kill -0 $pid ]
while [ $countto -ge $ctr ]; do
for i in "${spin[@]}"
do
# echo -ne "\b$i $ctr"
let cdown=$countto-$ctr
printf "\r$countto $i $cdown "
sleep 1
let ctr=$ctr+1
[ $ctr -ge $countto ] && break
read -n 1 -t .1 && break 2
done
done
echo ''

exit;
</code>

# ( in-vm )
time ./countdown.sh 10
10 - 0
real 0m11.952s

Edit - on my Mac host, it actually takes 12 sec and change! Time is not 100% accurate in a VM due to host scheduling and overall load, that's why we have stuff like ntp and chronyd

The script above adds .1 interrupt to check for any keyboard input and will do an early breakout if it detects any, btw, you can comment that out if you like

Make sure your VM has chronyd running and configured, and has accurate time...

https://search.brave.com/search?q=h...summary=1&conversation=8c2bb0e278aa783fc24229
 
Last edited:
Impact said:
You might want to share the script you're calling there. Information about your node and VM are also of interest.
Click to expand...
I shared the script, its very simple, its just sleep 10 and a writing to syslog.

The host nodes are all AMD EPYC 7763 64-Core Processor, 512G RAM, Linux virt1 6.14.11-2-pve #1 SMP PREEMPT_DYNAMIC PMX 6.14.11-2

VM is range from 4 cores 1 socket to 8 cores 1 socket, 6.8.0-79-generic #79-Ubuntu SMP PREEMPT_DYNAMIC

I tested 4 VMs on different nodes and the issue is on all of them.
 
You shared a bash script which does not accept arguments but then call a .py script with. One cannot reproduce your output with what you shared.
Have you tested with something simple like date -Ins or time sleep 10? I'm guessing it's not necessarily a timing issue but has more to do with the logging part.
 
Last edited:
Impact said:
You shared a bash script which does not accept arguments but then call a .py script with. One cannot reproduce your output with what you shared.
Have you tested with something like date -Ins or time sleep 10? I'm guessing it's not necessarily a timing issue but has more to do with the logging part.
Click to expand...
I think you may be right, the .py script just tails the log and greps a line and shows the difference since last. Any idea why sending a line to syslog every 10 sec would be an issue, but writing to a file the same log line every 10 seconds would not?

Code: 
#!/usr/bin/env python3
import argparse, os, time, re, sys
from datetime import datetime

TS_AT_START = re.compile(r'^(\S+)')  # first whitespace-separated token
ENCODING = "utf-8"

def parse_iso_ts(s: str) -> datetime:
    # Handle both ...Z and ...+00:00
    if s.endswith("Z"):
        s = s[:-1] + "+00:00"
    return datetime.fromisoformat(s)

def follow(path, match):
    last_inode = None
    f = None

    def open_file():
        nonlocal last_inode, f
        if f:
            try: f.close()
            except: pass
        f = open(path, "r", encoding=ENCODING, errors="replace")
        st = os.fstat(f.fileno())
        last_inode = st.st_ino
        f.seek(0, os.SEEK_END)  # tail: jump to EOF

    def rotated():
        try:
            st = os.stat(path)
            return st.st_ino != last_inode
        except FileNotFoundError:
            return True

    open_file()
    last_ts = None

    while True:
        line = f.readline()
        if not line:
            # file may be quiet or rotated
            if rotated():
                time.sleep(0.2)
                try:
                    open_file()
                except FileNotFoundError:
                    time.sleep(0.5)
            else:
                time.sleep(0.1)
            continue

        if match not in line:
            continue

        m = TS_AT_START.match(line)
        if not m:
            continue

        ts_str = m.group(1)
        try:
            ts = parse_iso_ts(ts_str)
        except Exception:
            continue

        if last_ts is None:
            print(f"{ts_str}  Δ --")
        else:
            delta = (ts - last_ts).total_seconds()
            print(f"{ts_str}  Δ {delta:.6f}s")
        sys.stdout.flush()
        last_ts = ts

def main():
    p = argparse.ArgumentParser(description="Tail syslog for voipmonitor timestamps with deltas.")
    p.add_argument("--file", "-f", default="/var/log/syslog", help="Path to syslog (default: /var/log/syslog)")
    p.add_argument("--match", "-m", default="voipmonitor", help="Substring to match (default: voipmonitor)")
    args = p.parse_args()
    try:
        follow(args.file, args.match)
    except KeyboardInterrupt:
        pass

if __name__ == "__main__":
    main()
 
You must log in or register to reply here.
Top Bottom