Field report -- OpenWRT 23.05 virtual router on Intel N100 running Proxmox PVE 8.0

[mcuee]

PVE 8.0 host: Intel N100 mini PC with quad Intel I226-V 2.5G adapter

OpenWRT virtual router: using two cores. no network passthrough, just use the Linux bridge. 4GB RAM, 4GB Storage.

Hostname	OpenWrt
Model	QEMU Standard PC (i440FX + PIIX, 1996)
Architecture	QEMU Virtual CPU version 2.5+
Target Platform	x86/64
Firmware Version	OpenWrt 23.05.2 r23630-842932a63d / LuCI openwrt-23.05 branch git-24.048.61449-c66fc92
Kernel Version	5.15.137

cake-autorate Configuration:

root@OpenWrt:~/cake-autorate# cat config.primary.sh
#!/usr/bin/env bash

# *** INSTANCE-SPECIFIC CONFIGURATION OPTIONS ***
#
# cake-autorate will run one instance per config file present in the /root/cake-autorate
# directory in the form: config.instance.sh. Thus multiple instances of cake-autorate
# can be established by setting up appropriate config files like config.primary.sh and
# config.secondary.sh for the respective first and second instances of cake-autorate.

### For multihomed setups, it is the responsibility of the user to ensure that the probes
### sent by this instance of cake-autorate actually travel through these interfaces.
### See ping_extra_args and ping_prefix_string

dl_if=ifb4eth0 # download interface
ul_if=eth0    # upload interface

# Set either of the below to 0 to adjust one direction only
# or alternatively set both to 0 to simply use cake-autorate to monitor a connection
adjust_dl_shaper_rate=1 # enable (1) or disable (0) actually changing the dl shaper rate
adjust_ul_shaper_rate=1 # enable (1) or disable (0) actually changing the ul shaper rate

min_dl_shaper_rate_kbps=5000  # minimum bandwidth for download (Kbit/s)
base_dl_shaper_rate_kbps=650000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=750000  # maximum bandwidth for download (Kbit/s)

min_ul_shaper_rate_kbps=5000  # minimum bandwidth for upload (Kbit/s)
base_ul_shaper_rate_kbps=200000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=380000  # maximum bandwidth for upload (Kbit/s)

connection_active_thr_kbps=20  # threshold in Kbit/s below which dl/ul is considered idle

# Logging toggles for various stats
output_processing_stats=0 # enable (1) or disable (0) output monitoring lines showing processing stats
output_load_stats=0       # enable (1) or disable (0) output monitoring lines showing achieved loads
output_reflector_stats=0  # enable (1) or disable (0) output monitoring lines showing reflector stats
output_summary_stats=0    # enable (1) or disable (0) output monitoring lines showing summary stats

# *** OVERRIDES ***

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.
# dl_owd_delta_thr_ms=100.0

Example run-log on the router.

root@OpenWrt:~/cake-autorate# ./cake-autorate.sh
DEBUG; 2024-03-31-10:55:38; 1711882538.373665; Starting: rotate_log_file with PID: 13048
SYSLOG; 2024-03-31-10:55:38; 1711882538.374935; Starting cake-autorate with PID: 13048 and config: /root/cake-autorate/config.primary.sh
DEBUG; 2024-03-31-10:55:38; 1711882538.377313; CAKE-autorate version: 3.2.0-PRERELEASE
DEBUG; 2024-03-31-10:55:38; 1711882538.377493; config_path: /root/cake-autorate/config.primary.sh
DEBUG; 2024-03-31-10:55:38; 1711882538.377664; run_path: /var/run/cake-autorate/primary
DEBUG; 2024-03-31-10:55:38; 1711882538.377818; log_file_path: /var/log/cake-autorate.primary.log
DEBUG; 2024-03-31-10:55:38; 1711882538.377970; pinger_binary:fping
DEBUG; 2024-03-31-10:55:38; 1711882538.378171; download interface: ifb4eth0 (5000 / 650000 / 750000)
DEBUG; 2024-03-31-10:55:38; 1711882538.378341; upload interface: eth0 (5000 / 200000 / 380000)
DEBUG; 2024-03-31-10:55:38; 1711882538.378500; rx_bytes_path: /sys/class/net/ifb4eth0/statistics/tx_bytes
DEBUG; 2024-03-31-10:55:38; 1711882538.378659; tx_bytes_path: /sys/class/net/eth0/statistics/tx_bytes
DEBUG; 2024-03-31-10:55:38; 1711882538.378849; Starting: verify_ifs_up with PID: 13048
DEBUG; 2024-03-31-10:55:38; 1711882538.380601; Starting: maintain_log_file with PID: 13139
DEBUG; 2024-03-31-10:55:38; 1711882538.380988; Starting: print_headers with PID: 13139
DEBUG; 2024-03-31-10:55:38; 1711882538.389954; Starting: export_proc_pids with PID: 13048
DEBUG; 2024-03-31-10:55:38; 1711882538.390010; Starting: monitor_achieved_rates with PID: 13151
DEBUG; 2024-03-31-10:55:38; 1711882538.397576; Starting: start_pingers with PID: 13048
DEBUG; 2024-03-31-10:55:38; 1711882538.397837; Starting: start_pinger with PID: 13048
DEBUG; 2024-03-31-10:55:38; 1711882538.398347; Starting: export_proc_pids with PID: 13048
INFO; 2024-03-31-10:55:38; 1711882538.398901; Started cake-autorate with PID: 13048 and config: /root/cake-autorate/config.primary.sh
DEBUG; 2024-03-31-10:56:38; 1711882598.527507; Warning: reflector: 94.140.14.141 sum_owd_baselines_us exceeds the minimum by set threshold.
DEBUG; 2024-03-31-10:56:38; 1711882598.527904; Starting: replace_pinger_reflector with PID: 13048
DEBUG; 2024-03-31-10:56:38; 1711882598.528134; replacing reflector: 94.140.14.141 with 156.154.70.3.
DEBUG; 2024-03-31-10:56:38; 1711882598.528353; Starting: kill_pinger with PID: 13048
DEBUG; 2024-03-31-10:56:38; 1711882598.630457; Starting: start_pinger with PID: 13048
DEBUG; 2024-03-31-10:56:38; 1711882598.630997; Starting: export_proc_pids with PID: 13048
DEBUG; 2024-03-31-10:56:38; 1711882598.631607; Resetting reflector offences associated with reflector: 156.154.70.3.

OOkla SpeedTest run log on an Windows 11 laptop connected wireless to the Asus RT-AX82U AP which is connected to the OpenWRT virtual router LAN port.

PS C:\work\speedtest\ookla-speedtest-1.2.0-win64> .\speedtest.exe -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     3.81 ms   (jitter: 0.76ms, low: 3.37ms, high: 4.85ms)
    Download:   663.16 Mbps (data used: 730.2 MB)
                 10.85 ms   (jitter: 3.52ms, low: 4.05ms, high: 68.88ms)
      Upload:   345.39 Mbps (data used: 416.4 MB)
                  6.88 ms   (jitter: 3.17ms, low: 3.23ms, high: 52.28ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/a48e4a39-829e-4ed6-a35a-2698d64764cb

CPU load from htop: Download -- peak load: one CPU goes to near 100% where the other CPU is less than 20%. Upload -- peak load: one CPU goes to about 40% whereas the other CPU is about 35%

waveform.com bufferbloat test results: Speed is on the low side so may not be that useful. https://www.waveform.com/tools/bufferbloat?test-id=b47574e2-385b-4252-8dc3-e4b04a46c4e5 https://www.waveform.com/tools/bufferbloat?test-id=be87e694-b9ed-42fa-b0ed-db5185c372a7

[moeller0]

I can understand this setup for testing purpose. It seesm to be a complex setup. My original idea is to use single cake instance to deal with both wired and wireless connection. But it seems to be difficult now.

Yeah, I think this is sub-optimal. Assuming your trie internet/WAN delay is well behaved you need a single cake instance per direction to control internet bufferbloat, and then deal with WiFi locally. The problems with WiFi are myriad: a) WiFi is half duplex, and hence you need to run cake-autorate on all wirelessly connected devices and the AP b) internet latency targets are unlikely to be ideal for a WiFi traffic shaper and vice versa c) active measurements even with small ICMP packets waste an airtime slot, so have considerable side effects, especially if you consider a larger set of wifi connected devices...

In short, I would look for an airtime fairness/AQL capable WiFi-AP, that should deal with the AP to station bufferbloat decently. For the other direction you would need to fix the station's WiFi stack somehow... or hope that stations send far less than they receive...

[moeller0]

In Singapore, ISPs offer dual 1Gbps plan using single GPON ONT (two networks, total download up to 2Gbps, total upload up to 1Gbps).

My ISP has a loophole where even for 1Gbps plan it is possible to split the home network into two using a smart switch (total download and upload will still be 1Gbps).

GPON ONT -- TP-Link TL-SG105E smart switch -- Asus RT-AX86U router (network one, one public IPv4 address and /56 IPv6) -- Linux LxC continer as the crusader and iperf3 server. flent/netperf server does not seem to work.

GPON ONT -- TP-Link TL-SG105E smart switch -- OpenWRT virtual machine (with SQM) -- Asus RT-AX82U AP (network two, one public IPv4 address and /56 IPv6) -- Acer Laptop as the crusader and iperf3 client.

So here is an idea, instead of just using the switch to connect both networks to the internet, why not also use it to directly connect the two networks? E.g. by using VLANs to separate WAN and local traffic? Or is the goal to fully separate these two networks?

[mcuee]

Total latency = wireless client to router (variable speed, say 200Mbps to 800Mbps) + [link to ISP] + [ISP's own latency]

Note that good routers (such as OpenWrt) generally have Wi-Fi drivers that use ATF and AQL (that in turn incorporate fq_codel ) to control the wireless latency (see my post on the OpenWrt forum for details.) These do a good job of keeping the Wi-Fi latency as low as possible.

Since ATF/AQL control the Wi-Fi, it strikes me that there's no need to incorporate it into the overall latency process. That is, I see the Wi-Fi latency as a random perturbation but with limited/constrained effect. A "global optimizer" (rolling all these into one) won't be able to improve the situation. Or am I missing the point? Thanks.

@richb-hanover

Thanks for the comment. The whole issue seems to be how to find a good one which can do SQM at higher speed like 800 Mbps.

In your OpenWRT forum thread you are lookling for low cost OpenWRT capable wireless router which can do 300Mbps and it does not seem to be an easy task. https://forum.openwrt.org/t/best-newcomer-routers-2024/189050

Now if I want to look for one which can do 800Mbps, it will be even more difficult.

Quoting the comment from slh.

Things like the NanoPi r2s/ r4s or a four-port x86_64 system (e.g. alderlake-n/ n100) solve the sqm/cake vs performance issue easily, but obviously lack the wireless capabilites (but maybe the existing/ old router (with its OEM firmware) can be used as dumb-AP, in the worst case in a double-NAT setup).

My current setup is more in line with that comment. I use OpenWRT virtual router in an Intel N100 mini PC with quad 2.5G NIC. Then I have Asus RT-AX82U as the AP and I have also got a new ZTE BE7200 Pro+ (with dual 2.5G ports) to use as an AP.

[mcuee]

So here is an idea, instead of just using the switch to connect both networks to the internet, why not also use it to directly connect the two networks? E.g. by using VLANs to separate WAN and local traffic? Or is the goal to fully separate these two networks?

Yes the idea is to seperate the two home networks and get two public IPv4 addresses, one for family member (even though I also play with it) and the other is mainly for me to play with.

But yes your suggestion is in my consideration as well. In fact I am buying a 2.5G capable smart switch. GPON ONT -- OpenWRT virtual router -- VLAN capable switch -- AP 1 for family member (one VLAN) and AP 2 for me (another VLAN).

The drawback is that I will only have one public IPv4 address and one /56 IPv6, I cannot test crusader/iperf3 over the internet in this case.

[moeller0]

Well you should be able to keep your current configuration in regards to your ISP and add a direct connection between your two network... you then might even be able to select the direct or indrect path by selecting the correct IP address for the iperf3/crusader server ion the other of your networks. But I just wanted to throw that out there, I am sure you have your network set-up that way for a reason, and I was mostly trying to figure that out; getting more public IP addresses is a good rationale in my book ;)

[lynxthecat]

Your logfiles keep ending in incomplete lines, and the parser was not expecting that, I will send an update later...

Also addressed here: https://github.com/lynxthecat/cake-autorate/commit/f3d1f99fcb8e674f3f8b68414d94b1d2ab876f55.

Some time ago I switched to buffered log file writes to significantly cut down on CPU usage.

So now we just flush the log file pipe on any export to ensure any buffered data is written out first.

[moeller0]

Ah, great, we are fixing it from both ends then...

[mcuee]

Ah, great, we are fixing it from both ends then...

That will be great.

[mcuee]

@richb-hanover

Thanks for the comment. The whole issue seems to be how to find a good one which can do SQM at higher speed like 800 Mbps.

In your OpenWRT forum thread you are lookling for low cost OpenWRT capable wireless router which can do 300Mbps and it does not seem to be an easy task. https://forum.openwrt.org/t/best-newcomer-routers-2024/189050

Now if I want to look for one which can do 800Mbps, it will be even more difficult.

Quoting the comment from slh.

Things like the NanoPi r2s/ r4s or a four-port x86_64 system (e.g. alderlake-n/ n100) solve the sqm/cake vs performance issue easily, but obviously lack the wireless capabilites (but maybe the existing/ old router (with its OEM firmware) can be used as dumb-AP, in the worst case in a double-NAT setup).

My current setup is more in line with that comment. I use OpenWRT virtual router in an Intel N100 mini PC with quad 2.5G NIC. Then I have Asus RT-AX82U as the AP and I have also got a new ZTE BE7200 Pro+ (with dual 2.5G ports) to use as an AP.

@richb-hanover and @moeller0 I think I make a mistake here. The wireless router does not need to handle the SQM in my case. I need to get a good wireless router like GL.iNET Flint 2 (GL-MT6000) or similar to handle the wireless portion.

Intel N100 Mini PC running OpenWRT with cake settings for wired devices -- GL.iNET Flint 2 (GL-MT6000) or similar to handle the wireless.

The goal of the new comer router thread is to try to find two-in-one solution so that the router needs to handle both SQM and Wireless. https://forum.openwrt.org/t/best-newcomer-routers-2024/189050

[moeller0]

Just wondering if I choose the reflectors wrongly. My ISP DNS (Singtel DNS) and Google DNS are just too fast. On the other hand, I do not want to choose Adguard and CleanBrowsing DNS because they are slow. Cloudflare/Quad9/OpenDNS are in between.

What do you mean, with DNS are just too fast? The shorter the baseline delay to the reflectors the better for our control loop, we operate not on the base delay, but on increases above the baseline, so in theory the shortest baselines are the best as we get the congestion information faster...

[mcuee]

Just wondering if I choose the reflectors wrongly. My ISP DNS (Singtel DNS) and Google DNS are just too fast. On the other hand, I do not want to choose Adguard and CleanBrowsing DNS because they are slow. Cloudflare/Quad9/OpenDNS are in between.

What do you mean, with DNS are just too fast? The shorter the baseline delay to the reflectors the better for our control loop, we operate not on the base delay, but on increases above the baseline, so in theory the shortest baselines are the best as we get the congestion information faster...

I see. Thanks for the clarifications.

You can see my problem is to get a test server over the internet which can trigger the increased delta delay to be above the threshold delay.

Maybe redo the test with a a rather more involved up- down- and bidirectional load? Here we really just see autorate slowly increasing the shaper rate up but since the delta delay never crosses the thresholds you do not see the actual rate reduction steps...

[moeller0]

You can see my problem is to get a test server over the internet which can trigger the increased delta delay to be above the threshold delay.

Or you could simply configure lower thresholds in your autorate config file? The defaults tend to be tested/optimised for @lynxthecat's LTE link and responsiveness requirements and are unlikely to be perfect for a fast PON link like yours...

[mcuee]

Your logfiles keep ending in incomplete lines, and the parser was not expecting that, I will send an update later... Ah, great, we are fixing it from both ends then...

Great, I can confirm that the issue has been fixed.

[mcuee]

Strange, now I can not get download related logs, not so sure what I am doing wrong.

root@OpenWrt:~/cake-autorate# cat config.primary.sh
#!/usr/bin/env bash

# *** INSTANCE-SPECIFIC CONFIGURATION OPTIONS ***
#
# cake-autorate will run one instance per config file present in the /root/cake-autorate
# directory in the form: config.instance.sh. Thus multiple instances of cake-autorate
# can be established by setting up appropriate config files like config.primary.sh and
# config.secondary.sh for the respective first and second instances of cake-autorate.

### For multihomed setups, it is the responsibility of the user to ensure that the probes
### sent by this instance of cake-autorate actually travel through these interfaces.
### See ping_extra_args and ping_prefix_string

dl_if=ifb4eth0 # download interface
ul_if=eth0     # upload interface

# Set either of the below to 0 to adjust one direction only
# or alternatively set both to 0 to simply use cake-autorate to monitor a connection
adjust_dl_shaper_rate=1 # enable (1) or disable (0) actually changing the dl shaper rate
adjust_ul_shaper_rate=1 # enable (1) or disable (0) actually changing the ul shaper rate

min_dl_shaper_rate_kbps=5000  # minimum bandwidth for download (Kbit/s)
base_dl_shaper_rate_kbps=650000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=950000  # maximum bandwidth for download (Kbit/s)

min_ul_shaper_rate_kbps=5000  # minimum bandwidth for upload (Kbit/s)
base_ul_shaper_rate_kbps=300000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=800000  # maximum bandwidth for upload (Kbit/s)

connection_active_thr_kbps=20  # threshold in Kbit/s below which dl/ul is considered idle

# Logging toggles for various stats
output_processing_stats=1 # enable (1) or disable (0) output monitoring lines showing processing stats
output_load_stats=1       # enable (1) or disable (0) output monitoring lines showing achieved loads
output_reflector_stats=1  # enable (1) or disable (0) output monitoring lines showing reflector stats
output_summary_stats=1    # enable (1) or disable (0) output monitoring lines showing summary stats

# *** OVERRIDES ***

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.
reflectors=(
"165.21.83.88" "165.21.100.88"  # Singtel
"8.8.8.8" "8.8.4.4"  # Google
)

no_pingers=4
reflector_ping_interval_s=0.05
#randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors on startup

reflector_comparison_interval_mins=1            # how often to compare reflectors
reflector_sum_owd_baselines_delta_thr_ms=10.0   # max increase from min sum owd baselines before reflector rotated
reflector_owd_delta_ewma_delta_thr_ms=10.0      # max increase from min delta ewma before reflector rotated

# ** Take care with these settings to ensure you won't run into OOM issues on your router ***
# every write the cumulative write time and bytes associated with each log line are checked
# and if either exceeds the configured values below, the log file is rotated
log_to_file=1              # enable (1) or disable (0) output logging to file (/tmp/cake-autorate.log)
log_file_max_time_mins=10  # maximum time between log file rotations
log_file_max_size_KB=8000  # maximum KB (i.e. bytes/1024) worth of log lines between log file rotations

Wireless OOkla SpeedTest.

PS C:\work\speedtest\ookla-speedtest-1.2.0-win64> .\speedtest.exe -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     4.12 ms   (jitter: 0.13ms, low: 4.00ms, high: 4.34ms)
    Download:   725.81 Mbps (data used: 835.3 MB)
                 11.94 ms   (jitter: 3.40ms, low: 3.51ms, high: 30.10ms)
      Upload:   557.27 Mbps (data used: 963.3 MB)
                 10.45 ms   (jitter: 4.23ms, low: 3.25ms, high: 63.45ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/edc83666-8ba9-4fe5-a05c-17a454952448

Log file generated. cake-autorate.primary_2024_04_05_22_06_17.log.gz

Analysis:

[mcuee]

Hmm, the following file still failed to be parsed. Strange.

cake-autorate.primary_2024_04_05_22_22_35.log.gz

warning: =: nonconformant arguments (op1 is 1x1, op2 is 2x1)
warning: called from
    fn_parse_autorate_log at line 743 column 5

err =

  scalar structure containing the fields:

    message = =: nonconformant arguments (op1 is 1x1, op2 is 2x1)
    identifier = Octave:nonconformant-args
    stack =

      3x1 struct array containing the fields:

        file
        name
        line
        column

Stack #: 1:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log>fn_parse_current_line
    line = 1247
    column = 73
Stack #: 2:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log>fn_parse_autorate_logfile
    line = 859
    column = 3
Stack #: 3:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log
    line = 83
    column = 27
INFO: available graphics toolkits:
{
  [1,1] = fltk
  [1,2] = gnuplot
  [1,3] = qt
}
INFO: Selected graphics toolkit: qt
INFO: Octave version: 9.1.0
Please report any issue to https://github.com/lynxthecat/cake-autorate/issues and consider sharing the log file that revealed the problem.
INFO: fn_parse_autorate_log took: 93.2169 seconds.

[lynxthecat]

Are you sure that you mean to use these parameters:

reflector_comparison_interval_mins=1            # how often to compare reflectors
reflector_sum_owd_baselines_delta_thr_ms=10.0   # max increase from min sum owd baselines before reflector rotated
reflector_owd_delta_ewma_delta_thr_ms=10.0      # max increase from min delta ewma before reflector rotated

I suspect rather you will want to play with:

dl_owd_delta_thr_ms=5.0 # (milliseconds)
ul_owd_delta_thr_ms=5.0 # (milliseconds)

dl_avg_owd_delta_thr_ms=10.0 # (milliseconds)
ul_avg_owd_delta_thr_ms=10.0 # (milliseconds)

This would mean classify a delay with an increase of 5ms, and maximally punish the shaper rate at a delay of 10ms.

[mcuee]

@lynxthecat

You are absolute right. I do not know why I made such a stupid mistake, guess it was late Friday evening.

Updated the config file as per the suggestion.

root@OpenWrt:~/cake-autorate# cat config.primary.sh
#!/usr/bin/env bash

# *** INSTANCE-SPECIFIC CONFIGURATION OPTIONS ***
#
# cake-autorate will run one instance per config file present in the /root/cake-autorate
# directory in the form: config.instance.sh. Thus multiple instances of cake-autorate
# can be established by setting up appropriate config files like config.primary.sh and
# config.secondary.sh for the respective first and second instances of cake-autorate.

### For multihomed setups, it is the responsibility of the user to ensure that the probes
### sent by this instance of cake-autorate actually travel through these interfaces.
### See ping_extra_args and ping_prefix_string

dl_if=ifb4eth0 # download interface
ul_if=eth0     # upload interface

# Set either of the below to 0 to adjust one direction only
# or alternatively set both to 0 to simply use cake-autorate to monitor a connection
adjust_dl_shaper_rate=1 # enable (1) or disable (0) actually changing the dl shaper rate
adjust_ul_shaper_rate=1 # enable (1) or disable (0) actually changing the ul shaper rate

min_dl_shaper_rate_kbps=5000  # minimum bandwidth for download (Kbit/s)
base_dl_shaper_rate_kbps=650000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=950000  # maximum bandwidth for download (Kbit/s)

min_ul_shaper_rate_kbps=5000  # minimum bandwidth for upload (Kbit/s)
base_ul_shaper_rate_kbps=300000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=800000  # maximum bandwidth for upload (Kbit/s)

connection_active_thr_kbps=20  # threshold in Kbit/s below which dl/ul is considered idle

# Logging toggles for various stats
output_processing_stats=1 # enable (1) or disable (0) output monitoring lines showing processing stats
output_load_stats=1       # enable (1) or disable (0) output monitoring lines showing achieved loads
output_reflector_stats=1  # enable (1) or disable (0) output monitoring lines showing reflector stats
output_summary_stats=1    # enable (1) or disable (0) output monitoring lines showing summary stats

# *** OVERRIDES ***

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.
reflectors=(
"165.21.83.88" "165.21.100.88"  # Singtel
"8.8.8.8" "8.8.4.4"  # Google
)

no_pingers=4
reflector_ping_interval_s=0.05
#randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors on startup

# classify a delay with an increase of 5ms, and maximally punish the shaper rate at a delay of 10ms.
dl_owd_delta_thr_ms=5.0 # (milliseconds)
ul_owd_delta_thr_ms=5.0 # (milliseconds)

dl_avg_owd_delta_thr_ms=10.0 # (milliseconds)
ul_avg_owd_delta_thr_ms=10.0 # (milliseconds)

# ** Take care with these settings to ensure you won't run into OOM issues on your router ***
# every write the cumulative write time and bytes associated with each log line are checked
# and if either exceeds the configured values below, the log file is rotated
log_to_file=1              # enable (1) or disable (0) output logging to file (/tmp/cake-autorate.log)
log_file_max_time_mins=10  # maximum time between log file rotations
log_file_max_size_KB=8000  # maximum KB (i.e. bytes/1024) worth of log lines between log file rotations

[mcuee]

@moeller0

Unfortunately the following log is problematic again (wireless client iperf3 download test first and then upload test, over the internet). Please take a look. Thanks.

cake-autorate.primary_2024_04_06_11_24_08.log.gz

warning: =: nonconformant arguments (op1 is 1x1, op2 is 0x1)
warning: called from
    fn_parse_autorate_log at line 743 column 5

err =

  scalar structure containing the fields:

    message = =: nonconformant arguments (op1 is 1x1, op2 is 0x1)
    identifier = Octave:nonconformant-args
    stack =

      3x1 struct array containing the fields:

        file
        name
        line
        column

Stack #: 1:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log>fn_parse_current_line
    line = 1247
    column = 73
Stack #: 2:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log>fn_parse_autorate_logfile
    line = 859
    column = 3
Stack #: 3:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log
    line = 83
    column = 27
INFO: available graphics toolkits:
{
  [1,1] = fltk
  [1,2] = gnuplot
  [1,3] = qt
}
INFO: Selected graphics toolkit: qt
INFO: Octave version: 9.1.0
Please report any issue to https://github.com/lynxthecat/cake-autorate/issues and consider sharing the log file that revealed the problem.
INFO: fn_parse_autorate_log took: 4.9515 seconds.

[mcuee]

@moeller0

Just wondering why I did not see the download achieve speed in the following log.

Wirelss client OOkla SpeedTest

PS C:\work\speedtest\ookla-speedtest-1.2.0-win64> .\speedtest.exe -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     3.59 ms   (jitter: 0.63ms, low: 3.05ms, high: 4.34ms)
    Download:   592.65 Mbps (data used: 725.4 MB)
                 12.98 ms   (jitter: 18.60ms, low: 4.97ms, high: 77.55ms)
      Upload:   476.47 Mbps (data used: 835.9 MB)
                 12.95 ms   (jitter: 5.03ms, low: 3.43ms, high: 132.86ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/0af7c873-95ac-436a-b935-d3a81d4787db

Log file cake-autorate.primary_2024_04_06_11_36_16.log.gz

Analysis results:

 MINGW64 /c/work/speedtest/cake-autorate
$ octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.png")'
INFO: C:\work\speedtest\cake-autorate
INFO: Processing log file: ./*primary*log.gz
INFO: Trying to save plot as: ./output.png
INFO: Parsing log file: C:\work\speedtest\cake-autorate\cake-autorate.primary_2024_04_06_11_36_16.log
INFO: might take a while...
WARNING: Unhandled type identifier encountered: SUMMA trying to ignore...
...
...
WARNING: Unhandled type identifier encountered: SUMMA trying to ignore...
INFO: Saving parsed data file as: C:\work\speedtest\cake-autorate\cake-autorate.primary_2024_04_06_11_36_16.log.mat
INFO: Empty x_range_sec specified, plotting the whole sample timestamp range (0 - 35.2382).
Selected DATA sample indices: 1  2721
Selected LOAD sample indices: 1  176
INFO: Adjusted y-limits based on ADJ_DELAY_THR_factor: -10084  10046
INFO: Grand adjusted y-limits based on OWD_DELTA_QUANTILE_factor and ADJ_DELAY_THR_factor: -28035  28035
INFO: Writing plot as: .\output.rawCDFs.png
INFO: Writing plot as: .\output.deltaCDFs.png
Samples per reflector:
ReflectorID: 165.21.100.88; N: 400
ReflectorID: 165.21.83.88; N: 400
ReflectorID: 8.8.4.4; N: 405
ReflectorID: 8.8.8.8; N: 405
DL: maximum 95.000%-ile delta delay over all 4 reflectors: 4.900 ms.
DL: maximum 99.000%-ile delta delay over all 4 reflectors: 8.690 ms.
DL: maximum 99.500%-ile delta delay over all 4 reflectors: 10.365 ms.
DL: maximum 99.900%-ile delta delay over all 4 reflectors: 19.825 ms.
DL: maximum 99.950%-ile delta delay over all 4 reflectors: 19.825 ms.
DL: maximum 99.990%-ile delta delay over all 4 reflectors: 19.825 ms.
DL: maximum 99.999%-ile delta delay over all 4 reflectors: 19.825 ms.
UL: maximum 95.000%-ile delta delay over all 4 reflectors: 4.900 ms.
UL: maximum 99.000%-ile delta delay over all 4 reflectors: 8.690 ms.
UL: maximum 99.500%-ile delta delay over all 4 reflectors: 10.365 ms.
UL: maximum 99.900%-ile delta delay over all 4 reflectors: 19.825 ms.
UL: maximum 99.950%-ile delta delay over all 4 reflectors: 19.825 ms.
UL: maximum 99.990%-ile delta delay over all 4 reflectors: 19.825 ms.
UL: maximum 99.999%-ile delta delay over all 4 reflectors: 19.825 ms.
hold is now on for specified axes
hold is now on for specified axes
INFO: Writing plot as: .\output.timecourse.png
INFO: fn_parse_autorate_log took: 133.5349 seconds.

[mcuee]

@lynxthecat

Maybe it is not the problem of the octave program, but rather the logging side, download seems to be always shows in idle state. Upload is okay.

Using crusader test (download for 10s and upload for 10s).

The log file always show download is idle. cake-autorate.primary_2024_04_06_11_56_28.log.gz

[lynxthecat]

You had download rates showing up just fine in the earlier logs and plots and presumably you didn’t change the interface?

Check that the output from:

tc qdisc ls

matches what you’ve set in the cake-autorate configuration file.

[mcuee]

You had download rates showing up just fine in the earlier logs and plots and presumably you didn’t change the interface?

Check that the output from:

tc qdisc ls

matches what you’ve set in the cake-autorate configuration file.

You are right. Sorry for the confusions.

I am playing with the /etc/config/sqm file and thus changes the interfaces.

This one is not matching the cake-autorate configuration file.

root@OpenWrt:~/cake-autorate# cat /etc/config/sqm 

config queue 'eth1'
    option enabled '1'
    option interface 'eth0'
    option download '0'
    option upload '700000'
    option qdisc 'cake'
    option script 'piece_of_cake.qos'
    option linklayer 'ethernet'
    option debug_logging '0'
    option verbosity '5'
    option overhead '44'

root@OpenWrt:~/cake-autorate# tc qdisc ls
qdisc noqueue 0: dev lo root refcnt 2 
qdisc cake 8019: dev eth0 root refcnt 2 bandwidth 700Mbit besteffort triple-isolate nonat nowash no-ack-filter split-gso rtt 100ms noatm overhead 44 
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc noqueue 0: dev br-lan root refcnt 2 
qdisc noqueue 0: dev wg_lan root refcnt 2 
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 

The following is matching with the cake-autorate configuration file.

root@OpenWrt:~/cake-autorate# cat /etc/config/sqm 

config queue 'eth1'
    option enabled '1'
    option interface 'eth0'
    option download '950000'
    option upload '700000'
    option qdisc 'cake'
    option script 'piece_of_cake.qos'
    option linklayer 'ethernet'
    option debug_logging '0'
    option verbosity '5'
    option overhead '44'

root@OpenWrt:~/cake-autorate# tc qdisc ls
qdisc noqueue 0: dev lo root refcnt 2 
qdisc cake 801c: dev eth0 root refcnt 2 bandwidth 700Mbit besteffort triple-isolate nonat nowash no-ack-filter split-gso rtt 100ms noatm overhead 44 
qdisc ingress ffff: dev eth0 parent ffff:fff1 ---------------- 
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc noqueue 0: dev br-lan root refcnt 2 
qdisc noqueue 0: dev wg_lan root refcnt 2 
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc cake 801d: dev ifb4eth0 root refcnt 2 bandwidth 950Mbit besteffort triple-isolate nonat wash no-ack-filter split-gso rtt 100ms noatm overhead 44 

[moeller0]

@moeller0

Unfortunately the following log is problematic again (wireless client iperf3 download test first and then upload test, over the internet). Please take a look. Thanks.

cake-autorate.primary_2024_04_06_11_24_08.log.gz

warning: =: nonconformant arguments (op1 is 1x1, op2 is 0x1)
warning: called from
    fn_parse_autorate_log at line 743 column 5

err =

  scalar structure containing the fields:

    message = =: nonconformant arguments (op1 is 1x1, op2 is 0x1)
    identifier = Octave:nonconformant-args
    stack =

      3x1 struct array containing the fields:

        file
        name
        line
        column

Stack #: 1:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log>fn_parse_current_line
    line = 1247
    column = 73
Stack #: 2:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log>fn_parse_autorate_logfile
    line = 859
    column = 3
Stack #: 3:
    file = C:\work\speedtest\cake-autorate\fn_parse_autorate_log.m
    name = fn_parse_autorate_log
    line = 83
    column = 27
INFO: available graphics toolkits:
{
  [1,1] = fltk
  [1,2] = gnuplot
  [1,3] = qt
}
INFO: Selected graphics toolkit: qt
INFO: Octave version: 9.1.0
Please report any issue to https://github.com/lynxthecat/cake-autorate/issues and consider sharing the log file that revealed the problem.
INFO: fn_parse_autorate_log took: 4.9515 seconds.

Mmmh this contains this gem:

DATA; 2024-04-05-22:22:35; 1712326955.101992; 1712326955.101872; 0; 82; 0; 0; 1712326955.101260; 165.21.100.88; 21295; 965; 1120; 267; 155; 30018; 965; 1120; 267; 155; 30041; 0; 246; 60018; 0; 246; 60041; dl_idle; uDEBUG; 2024-04-05-22:22:35; 1712326955.118157; Starting: export_log_file with PID: 2326

So the DEBUG writer sort of interrupted the last DATA record... Not sure that the new logfile handling/writing is as robust and reliable as desirable yet?

[mcuee]

This is a new test with Mac Mini M1 (wireless connection).

mcuee@mcuees-Mac-mini ookla % ./speedtest -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     4.99 ms   (jitter: 0.12ms, low: 4.89ms, high: 5.27ms)
    Download:   419.94 Mbps (data used: 345.7 MB)                                                   
                 17.50 ms   (jitter: 7.21ms, low: 4.76ms, high: 40.04ms)
      Upload:   329.28 Mbps (data used: 564.5 MB)                                                   
                 19.73 ms   (jitter: 7.20ms, low: 6.03ms, high: 71.95ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/54bc03f7-5833-4a6f-a258-19d8a1225165

OpenWRT settings

root@OpenWrt:~/cake-autorate# cat /etc/config/sqm 

config queue 'eth1'
    option enabled '1'
    option interface 'eth0'
    option download '950000'
    option upload '700000'
    option qdisc 'cake'
    option script 'piece_of_cake.qos'
    option linklayer 'ethernet'
    option debug_logging '0'
    option verbosity '5'
    option overhead '44'

root@OpenWrt:~/cake-autorate# tc qdisc ls
qdisc noqueue 0: dev lo root refcnt 2 
qdisc cake 801c: dev eth0 root refcnt 2 bandwidth 300Mbit besteffort triple-isolate nonat nowash no-ack-filter split-gso rtt 100ms noatm overhead 44 
qdisc ingress ffff: dev eth0 parent ffff:fff1 ---------------- 
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc noqueue 0: dev br-lan root refcnt 2 
qdisc noqueue 0: dev wg_lan root refcnt 2 
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64 
qdisc cake 801d: dev ifb4eth0 root refcnt 2 bandwidth 650Mbit besteffort triple-isolate nonat wash no-ack-filter split-gso rtt 100ms noatm overhead 44 

root@OpenWrt:~/cake-autorate# cat config.primary.sh
#!/usr/bin/env bash

# *** INSTANCE-SPECIFIC CONFIGURATION OPTIONS ***
# 
# cake-autorate will run one instance per config file present in the /root/cake-autorate
# directory in the form: config.instance.sh. Thus multiple instances of cake-autorate
# can be established by setting up appropriate config files like config.primary.sh and 
# config.secondary.sh for the respective first and second instances of cake-autorate.

### For multihomed setups, it is the responsibility of the user to ensure that the probes
### sent by this instance of cake-autorate actually travel through these interfaces.
### See ping_extra_args and ping_prefix_string

dl_if=ifb4eth0 # download interface
ul_if=eth0     # upload interface

# Set either of the below to 0 to adjust one direction only
# or alternatively set both to 0 to simply use cake-autorate to monitor a connection
adjust_dl_shaper_rate=1 # enable (1) or disable (0) actually changing the dl shaper rate
adjust_ul_shaper_rate=1 # enable (1) or disable (0) actually changing the ul shaper rate

min_dl_shaper_rate_kbps=5000  # minimum bandwidth for download (Kbit/s)
base_dl_shaper_rate_kbps=650000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=950000  # maximum bandwidth for download (Kbit/s)

min_ul_shaper_rate_kbps=5000  # minimum bandwidth for upload (Kbit/s)
base_ul_shaper_rate_kbps=300000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=800000  # maximum bandwidth for upload (Kbit/s)

connection_active_thr_kbps=20  # threshold in Kbit/s below which dl/ul is considered idle

# Logging toggles for various stats
output_processing_stats=1 # enable (1) or disable (0) output monitoring lines showing processing stats
output_load_stats=1       # enable (1) or disable (0) output monitoring lines showing achieved loads
output_reflector_stats=1  # enable (1) or disable (0) output monitoring lines showing reflector stats
output_summary_stats=1    # enable (1) or disable (0) output monitoring lines showing summary stats

# *** OVERRIDES ***

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.
reflectors=(
"165.21.83.88" "165.21.100.88"  # Singtel
"8.8.8.8" "8.8.4.4"  # Google
)

no_pingers=4
reflector_ping_interval_s=0.05
#randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors on startup

# classify a delay with an increase of 5ms, and maximally punish the shaper rate at a delay of 10ms.
dl_owd_delta_thr_ms=5.0 # (milliseconds)
ul_owd_delta_thr_ms=5.0 # (milliseconds)

dl_avg_owd_delta_thr_ms=10.0 # (milliseconds)
ul_avg_owd_delta_thr_ms=10.0 # (milliseconds)

# ** Take care with these settings to ensure you won't run into OOM issues on your router ***
# every write the cumulative write time and bytes associated with each log line are checked
# and if either exceeds the configured values below, the log file is rotated
log_to_file=1              # enable (1) or disable (0) output logging to file (/tmp/cake-autorate.log)
log_file_max_time_mins=10  # maximum time between log file rotations
log_file_max_size_KB=8000  # maximum KB (i.e. bytes/1024) worth of log lines between log file rotations

Log file: cake-autorate.primary_2024_04_06_16_28_57.log.gz

Generated output:

mcuee@mcuees-Mac-mini cake-autorate % octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.png")'
INFO: /Users/mcuee/build/speedtest/cake-autorate
INFO: Processing log file: ./*primary*log.gz
INFO: Trying to save plot as: ./output.png
INFO: Parsing log file: /Users/mcuee/build/speedtest/cake-autorate/cake-autorate.primary_2024_04_06_16_28_57.log
INFO: might take a while...
WARNING: Unhandled type identifier encountered: SUMMA trying to ignore...
...
...
WARNING: Unhandled type identifier encountered: SUMMA trying to ignore...
INFO: Saving parsed data file as: /Users/mcuee/build/speedtest/cake-autorate/cake-autorate.primary_2024_04_06_16_28_57.log.mat
INFO: Empty x_range_sec specified, plotting the whole sample timestamp range (0 - 30.5156).
Selected DATA sample indices: 1  2442
Selected LOAD sample indices: 1  153
INFO: Adjusted y-limits based on ADJ_DELAY_THR_factor: -10082  10036
INFO: Grand adjusted y-limits based on OWD_DELTA_QUANTILE_factor and ADJ_DELAY_THR_factor: -16725  16725
INFO: Writing plot as: ./output.rawCDFs.png
FALLBACK (log once): Fallback to SW vertex for line stipple
FALLBACK (log once): Fallback to SW vertex processing, m_disable_code: 2000
FALLBACK (log once): Fallback to SW vertex processing in drawCore, m_disable_code: 2000
INFO: Writing plot as: ./output.deltaCDFs.png
Samples per reflector:
ReflectorID: 165.21.100.88; N: 177
ReflectorID: 165.21.83.88; N: 177
ReflectorID: 8.8.4.4; N: 177
ReflectorID: 8.8.8.8; N: 178
DL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.565 ms.
DL: maximum 99.000%-ile delta delay over all 4 reflectors: 12.325 ms.
DL: maximum 99.500%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.900%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.950%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.990%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.999%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.565 ms.
UL: maximum 99.000%-ile delta delay over all 4 reflectors: 12.325 ms.
UL: maximum 99.500%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.900%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.950%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.990%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.999%-ile delta delay over all 4 reflectors: 16.955 ms.
hold is now on for specified axes
hold is now on for specified axes
INFO: Writing plot as: ./output.timecourse.png
INFO: fn_parse_autorate_log took: 39.3322 seconds.

[moeller0]

I note the issue is close to the end (in the last DATA record) so relatively easy to ignore, yet, this should not happen...

[mcuee]

@moeller0 and @lynxthecat

BTW, the document here may need a minor note about scp command, for macOS users. I just found it out on my Mac Mini M1 running latest macOS 14.4.1. https://github.com/lynxthecat/cake-autorate/blob/master/ANALYSIS.md

Reference: need to use scp -O command. https://forum.openwrt.org/t/ash-usr-libexec-sftp-server-not-found-when-using-scp/125772/2

[mcuee]

I note the issue is close to the end (in the last DATA record) so relatively easy to ignore, yet, this should not happen...

FYI I was using the following commands under OpenWRT.

Before the test:

/var/run/cake-autorate/*/log_file_reset

After the test:

/var/run/cake-autorate/*/log_file_export

Then I was using WinSCP to copy the log file to my Windows machine.

Under Linux and macOS I will use the script.

log_file=$(ssh root@192.168.38.1 '/var/run/cake-autorate/primary/log_file_export 1>/dev/null && cat /var/run/cake-autorate/primary/last_log_file_export') && scp root@192.168.38.1:${log_file} . && ssh root@192.168.38.1 "rm ${log_file}"
octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.png")'

[moeller0]

I created a PR with the required changes to robustify the parser. The parser will now try to skip incomplete lines but attempt to continue parsing beyond the problematic lines, hiw well this works is to be seen...

[mcuee]

@moeller0

Another thing, it is better to change the document as well to export png file and not pdf file. https://github.com/lynxthecat/cake-autorate/blob/master/ANALYSIS.md

Exporting pdf file is not working under Windows, it is even worse under macOS.

mcuee@mcuees-Mac-mini cake-autorate % octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.pdf")'
INFO: /Users/mcuee/build/speedtest/cake-autorate
INFO: Processing log file: ./*primary*log.gz
INFO: Trying to save plot as: ./output.pdf
INFO: Found already parsed log file (/Users/mcuee/build/speedtest/cake-autorate/cake-autorate.primary_2024_04_06_16_28_57.log.mat), loading...
INFO: Empty x_range_sec specified, plotting the whole sample timestamp range (0 - 30.5156).
Selected DATA sample indices: 1  2442
Selected LOAD sample indices: 1  153
INFO: Adjusted y-limits based on ADJ_DELAY_THR_factor: -10082  10036
INFO: Grand adjusted y-limits based on OWD_DELTA_QUANTILE_factor and ADJ_DELAY_THR_factor: -16725  16725
INFO: Writing plot as: ./output.rawCDFs.pdf
qt.qpa.fonts: Populating font family aliases took 132 ms. Replace uses of missing font family "FreeSans" with one that exists to avoid this cost. 
INFO: Writing plot as: ./output.deltaCDFs.pdf
qt.qpa.fonts: Populating font family aliases took 133 ms. Replace uses of missing font family "FreeSans" with one that exists to avoid this cost. 
Samples per reflector:
ReflectorID: 165.21.100.88; N: 177
ReflectorID: 165.21.83.88; N: 177
ReflectorID: 8.8.4.4; N: 177
ReflectorID: 8.8.8.8; N: 178
DL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.565 ms.
DL: maximum 99.000%-ile delta delay over all 4 reflectors: 12.325 ms.
DL: maximum 99.500%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.900%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.950%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.990%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.999%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.565 ms.
UL: maximum 99.000%-ile delta delay over all 4 reflectors: 12.325 ms.
UL: maximum 99.500%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.900%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.950%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.990%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.999%-ile delta delay over all 4 reflectors: 16.955 ms.
hold is now on for specified axes
hold is now on for specified axes
INFO: Writing plot as: ./output.timecourse.pdf
Failed to parse XML contents
Expected '#' or '[a-zA-Z]', but got ' '.
Error: /undefinedfilename in (/var/folders/zf/457r6vn50knfpnjgy1156llr0000gn/T/oct-kyCKwM)
Operand stack:
Execution stack:   %interp_exit   .runexec2   --nostringval--   --nostringval--   --nostringval--   2   %stopped_push   --nostringval--   --nostringval--   --nostringval--   false   1   %stopped_push
Dictionary stack:   --dict:751/1123(ro)(G)--   --dict:0/20(G)--   --dict:85/200(L)--
Current allocation mode is local
Last OS error: No such file or directoryGPL Ghostscript 10.03.0: Unrecoverable error, exit code 1
warning: broken pipe
warning: print: No such file or directory, '/var/folders/zf/457r6vn50knfpnjgy1156llr0000gn/T/oct-kyCKwM'
warning: called from
    print at line 818 column 9
    fn_parse_autorate_log>write_out_figure at line 1395 column 3
    fn_parse_autorate_log at line 740 column 4

INFO: fn_parse_autorate_log took: 9.5941 seconds.
error: ignoring const execution_exception& while preparing to exit

libc++abi: terminating due to uncaught exception of type octave::execution_exception: gl2ps_renderer::draw: internal pipe error
fatal: caught signal Abort trap: 6 -- stopping myself...
zsh: abort      octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.pdf")

[moeller0]

FYI I was using the following commands under OpenWRT.

As far as I can tell that is the recommended work-flow. I have not looked into the actual shell code in ages, so I have no theory what exactly is happening, bt the phenotype looks like some writes do not finish and leave incomplete entries (also lacking the final line feed). I tried to make the parser hobble over those lines, but this is really just papering over the issue (yet, might be a good enough solution).

[moeller0]

@moeller0

Another thing, it is better to change the document as well to export png file and not pdf file. https://github.com/lynxthecat/cake-autorate/blob/master/ANALYSIS.md

Exporting pdf file is not working under Windows, it is even worse under macOS.

mcuee@mcuees-Mac-mini cake-autorate % octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.pdf")'
INFO: /Users/mcuee/build/speedtest/cake-autorate
INFO: Processing log file: ./*primary*log.gz
INFO: Trying to save plot as: ./output.pdf
INFO: Found already parsed log file (/Users/mcuee/build/speedtest/cake-autorate/cake-autorate.primary_2024_04_06_16_28_57.log.mat), loading...
INFO: Empty x_range_sec specified, plotting the whole sample timestamp range (0 - 30.5156).
Selected DATA sample indices: 1  2442
Selected LOAD sample indices: 1  153
INFO: Adjusted y-limits based on ADJ_DELAY_THR_factor: -10082  10036
INFO: Grand adjusted y-limits based on OWD_DELTA_QUANTILE_factor and ADJ_DELAY_THR_factor: -16725  16725
INFO: Writing plot as: ./output.rawCDFs.pdf
qt.qpa.fonts: Populating font family aliases took 132 ms. Replace uses of missing font family "FreeSans" with one that exists to avoid this cost. 
INFO: Writing plot as: ./output.deltaCDFs.pdf
qt.qpa.fonts: Populating font family aliases took 133 ms. Replace uses of missing font family "FreeSans" with one that exists to avoid this cost. 
Samples per reflector:
ReflectorID: 165.21.100.88; N: 177
ReflectorID: 165.21.83.88; N: 177
ReflectorID: 8.8.4.4; N: 177
ReflectorID: 8.8.8.8; N: 178
DL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.565 ms.
DL: maximum 99.000%-ile delta delay over all 4 reflectors: 12.325 ms.
DL: maximum 99.500%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.900%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.950%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.990%-ile delta delay over all 4 reflectors: 16.955 ms.
DL: maximum 99.999%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.565 ms.
UL: maximum 99.000%-ile delta delay over all 4 reflectors: 12.325 ms.
UL: maximum 99.500%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.900%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.950%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.990%-ile delta delay over all 4 reflectors: 16.955 ms.
UL: maximum 99.999%-ile delta delay over all 4 reflectors: 16.955 ms.
hold is now on for specified axes
hold is now on for specified axes
INFO: Writing plot as: ./output.timecourse.pdf
Failed to parse XML contents
Expected '#' or '[a-zA-Z]', but got ' '.
Error: /undefinedfilename in (/var/folders/zf/457r6vn50knfpnjgy1156llr0000gn/T/oct-kyCKwM)
Operand stack:
Execution stack:   %interp_exit   .runexec2   --nostringval--   --nostringval--   --nostringval--   2   %stopped_push   --nostringval--   --nostringval--   --nostringval--   false   1   %stopped_push
Dictionary stack:   --dict:751/1123(ro)(G)--   --dict:0/20(G)--   --dict:85/200(L)--
Current allocation mode is local
Last OS error: No such file or directoryGPL Ghostscript 10.03.0: Unrecoverable error, exit code 1
warning: broken pipe
warning: print: No such file or directory, '/var/folders/zf/457r6vn50knfpnjgy1156llr0000gn/T/oct-kyCKwM'
warning: called from
    print at line 818 column 9
    fn_parse_autorate_log>write_out_figure at line 1395 column 3
    fn_parse_autorate_log at line 740 column 4

INFO: fn_parse_autorate_log took: 9.5941 seconds.
error: ignoring const execution_exception& while preparing to exit

libc++abi: terminating due to uncaught exception of type octave::execution_exception: gl2ps_renderer::draw: internal pipe error
fatal: caught signal Abort trap: 6 -- stopping myself...
zsh: abort      octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.pdf")

Great idea, but I am not one of the maintainers of cake-autorate, so I think @lynxthecat or @rany2 should do this, if they agree. The issue is that with more recent octave/ghostscript combinations the pdf export of the timeline plot results in a blank file and the above error message...

[moeller0]

@moeller0 and @lynxthecat

BTW, the document here may need a minor note about scp command, for macOS users. I just found it out on my Mac Mini M1 running latest macOS 14.4.1. https://github.com/lynxthecat/cake-autorate/blob/master/ANALYSIS.md

Reference: need to use scp -O command. https://forum.openwrt.org/t/ash-usr-libexec-sftp-server-not-found-when-using-scp/125772/2

I think this is not an macosx issue, but will affect all users of recent enough OpenSSH...

[rany2]

I've updated the instructions, thanks for the heads up and ping @moeller0.

[mcuee]

I've updated the instructions, thanks for the heads up and ping @moeller0.

@rany2

Please also update the following command to export png and not pdf file. Thanks.

https://github.com/lynxthecat/cake-autorate/blob/master/ANALYSIS.md

octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.pdf")'

-->

octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.png")'

[rany2]

@mcuee Why? Does it rely on latex or something?

[moeller0]

@rany2 the issue is that recent octave/ghostscript combinations crash while trying to export the timecourse plot... the png exporter however does seem to work...

[rany2]

Thanks, I updated the document now

[lynxthecat]

Mmmh this contains this gem:

DATA; 2024-04-05-22:22:35; 1712326955.101992; 1712326955.101872; 0; 82; 0; 0; 1712326955.101260; 165.21.100.88; 21295; 965; 1120; 267; 155; 30018; 965; 1120; 267; 155; 30041; 0; 246; 60018; 0; 246; 60041; dl_idle; uDEBUG; 2024-04-05-22:22:35; 1712326955.118157; Starting: export_log_file with PID: 2326

Ah yes, I see the issue. Fixing now.

[rany2]

@lynxthecat In the old code, I had it acquire a lock for log_msg to avoid this situation; was the overhead too great that it had to be removed?

[mcuee]

Now it seems to be much more stable now -- all log files can be parsed.

Run log for a OOkla Speedtest (wireless)

PS C:\work\speedtest\ookla-speedtest-1.2.0-win64> .\speedtest.exe -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     3.74 ms   (jitter: 0.56ms, low: 3.06ms, high: 4.42ms)
    Download:   729.88 Mbps (data used: 792.8 MB)
                  9.98 ms   (jitter: 4.09ms, low: 3.52ms, high: 21.92ms)
      Upload:   549.89 Mbps (data used: 954.4 MB)
                 14.81 ms   (jitter: 6.98ms, low: 3.09ms, high: 111.54ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/0e22d1a7-3c87-422f-b099-f1fe2dbd008c

$ octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.png")'
INFO: C:\work\speedtest\cake-autorate
INFO: Processing log file: ./*primary*log.gz
INFO: Trying to save plot as: ./output.png
INFO: Parsing log file: C:\work\speedtest\cake-autorate\cake-autorate.primary_2024_04_13_21_11_37.log
INFO: might take a while...
INFO: Processed line: 1000
INFO: Processed line: 2000
INFO: Processed line: 3000
INFO: Processed line: 4000
INFO: Processed line: 5000
INFO: Processed line: 6000
INFO: Saving parsed data file as: C:\work\speedtest\cake-autorate\cake-autorate.primary_2024_04_13_21_11_37.log.mat
INFO: Empty x_range_sec specified, plotting the whole sample timestamp range (0 - 40.3764).
Selected DATA sample indices: 1  3188
Selected LOAD sample indices: 1  201
INFO: Adjusted y-limits based on ADJ_DELAY_THR_factor: -10090  10038
INFO: Grand adjusted y-limits based on OWD_DELTA_QUANTILE_factor and ADJ_DELAY_THR_factor: -34282.5         34282.5
INFO: Writing plot as: .\output.rawCDFs.png
INFO: Writing plot as: .\output.deltaCDFs.png
Samples per reflector:
ReflectorID: 165.21.100.88; N: 306
ReflectorID: 165.21.83.88; N: 295
ReflectorID: 8.8.4.4; N: 322
ReflectorID: 8.8.8.8; N: 323
DL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.445 ms.
DL: maximum 99.000%-ile delta delay over all 4 reflectors: 0.650 ms.
DL: maximum 99.500%-ile delta delay over all 4 reflectors: 2.540 ms.
DL: maximum 99.900%-ile delta delay over all 4 reflectors: 11.000 ms.
DL: maximum 99.950%-ile delta delay over all 4 reflectors: 11.000 ms.
DL: maximum 99.990%-ile delta delay over all 4 reflectors: 11.000 ms.
DL: maximum 99.999%-ile delta delay over all 4 reflectors: 11.000 ms.
UL: maximum 95.000%-ile delta delay over all 4 reflectors: 0.445 ms.
UL: maximum 99.000%-ile delta delay over all 4 reflectors: 0.650 ms.
UL: maximum 99.500%-ile delta delay over all 4 reflectors: 2.540 ms.
UL: maximum 99.900%-ile delta delay over all 4 reflectors: 11.000 ms.
UL: maximum 99.950%-ile delta delay over all 4 reflectors: 11.000 ms.
UL: maximum 99.990%-ile delta delay over all 4 reflectors: 11.000 ms.
UL: maximum 99.999%-ile delta delay over all 4 reflectors: 11.000 ms.
hold is now on for specified axes
hold is now on for specified axes
INFO: Writing plot as: .\output.timecourse.png
INFO: fn_parse_autorate_log took: 122.0709 seconds.

Log file cake-autorate.primary_2024_04_13_21_11_37.log.gz

Generated pictures by Octave.

[moeller0]

Now it seems to be much more stable now -- all log files can be parsed.

In this case it was the fixes tp the code that wrote the log, the robustification of the log file parser did not matter/trigger here at all. Which IMHO is how it should be, thanks for helping getting both sides improved.

Looking at your speedtest, the Ookla servers did not manage to reach your shaper limit, but the overall mechanism seems to have worked well... similar for the Upload...

[mcuee]

Looking at your speedtest, the Ookla servers did not manage to reach your shaper limit, but the overall mechanism seems to have worked well... similar for the Upload...

Just wondering if I should lower which of the following parameters? I am reluctant to drop the max rate (that is the limit for wired connection). Shall I reduce the base rate?

base_dl_shaper_rate_kbps=650000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=950000  # maximum bandwidth for download (Kbit/s)

base_ul_shaper_rate_kbps=300000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=800000  # maximum bandwidth for upload (Kbit/s)

Full configuration file:

root@OpenWrt:~/cake-autorate# cat config.primary.sh
#!/usr/bin/env bash

# *** INSTANCE-SPECIFIC CONFIGURATION OPTIONS ***
#
# cake-autorate will run one instance per config file present in the /root/cake-autorate
# directory in the form: config.instance.sh. Thus multiple instances of cake-autorate
# can be established by setting up appropriate config files like config.primary.sh and
# config.secondary.sh for the respective first and second instances of cake-autorate.

### For multihomed setups, it is the responsibility of the user to ensure that the probes
### sent by this instance of cake-autorate actually travel through these interfaces.
### See ping_extra_args and ping_prefix_string

dl_if=ifb4eth0 # download interface
ul_if=eth0     # upload interface

# Set either of the below to 0 to adjust one direction only
# or alternatively set both to 0 to simply use cake-autorate to monitor a connection
adjust_dl_shaper_rate=1 # enable (1) or disable (0) actually changing the dl shaper rate
adjust_ul_shaper_rate=1 # enable (1) or disable (0) actually changing the ul shaper rate

min_dl_shaper_rate_kbps=5000  # minimum bandwidth for download (Kbit/s)
base_dl_shaper_rate_kbps=650000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=950000  # maximum bandwidth for download (Kbit/s)

min_ul_shaper_rate_kbps=5000  # minimum bandwidth for upload (Kbit/s)
base_ul_shaper_rate_kbps=300000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=800000  # maximum bandwidth for upload (Kbit/s)

connection_active_thr_kbps=20  # threshold in Kbit/s below which dl/ul is considered idle

# Logging toggles for various stats
output_processing_stats=1 # enable (1) or disable (0) output monitoring lines showing processing stats
output_load_stats=1       # enable (1) or disable (0) output monitoring lines showing achieved loads
output_reflector_stats=1  # enable (1) or disable (0) output monitoring lines showing reflector stats
output_summary_stats=1    # enable (1) or disable (0) output monitoring lines showing summary stats

# *** OVERRIDES ***

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.
reflectors=(
"165.21.83.88" "165.21.100.88"  # Singtel
"8.8.8.8" "8.8.4.4"  # Google
)

no_pingers=4
reflector_ping_interval_s=0.05
#randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors on startup

# classify a delay with an increase of 5ms, and maximally punish the shaper rate at a delay of 10ms.
dl_owd_delta_thr_ms=5.0 # (milliseconds)
ul_owd_delta_thr_ms=5.0 # (milliseconds)

dl_avg_owd_delta_thr_ms=10.0 # (milliseconds)
ul_avg_owd_delta_thr_ms=10.0 # (milliseconds)

# ** Take care with these settings to ensure you won't run into OOM issues on your router ***
# every write the cumulative write time and bytes associated with each log line are checked
# and if either exceeds the configured values below, the log file is rotated
log_to_file=1              # enable (1) or disable (0) output logging to file (/tmp/cake-autorate.log)
log_file_max_time_mins=10  # maximum time between log file rotations
log_file_max_size_KB=8000  # maximum KB (i.e. bytes/1024) worth of log lines between log file rotations

[moeller0]

I defer to @lynxthecat and other's that actually use cake-autorate in earnest...

[lynxthecat]

Perhaps try:

dl_owd_delta_thr_ms=2.5 # (milliseconds)
ul_owd_delta_thr_ms=2.5 # (milliseconds)

dl_avg_owd_delta_thr_ms=5.0 # (milliseconds)
ul_avg_owd_delta_thr_ms=5.0 # (milliseconds)

bufferbloat_detection_window=4   # number of samples to retain in detection window
bufferbloat_detection_thr=2      # number of delayed samples for bufferbloat detection

For setting the base rates, it is a matter of personal preference. But I recommend thinking of the base rates as best set to safe rates where you will never or at least mostly not experience any latency increase on connection saturation at those rates. You don't want cake-autorate to keep setting the shaper rates back to a dangerous rate that might incur latency spikes on high load. Rather you want cake-autorate to carefully allow for bandwidth excursions from that area of safety. And once the load drops, cake-autorate should bring the shaper rates back down from such excursions to the safe rates. Hope this makes sense.

[mcuee]

Now there seems to be a problem to capture the download side. Strange.

Configure file

root@OpenWrt:~/cake-autorate# cat config.primary.sh
#!/usr/bin/env bash

# *** INSTANCE-SPECIFIC CONFIGURATION OPTIONS ***
#
# cake-autorate will run one instance per config file present in the /root/cake-autorate
# directory in the form: config.instance.sh. Thus multiple instances of cake-autorate
# can be established by setting up appropriate config files like config.primary.sh and
# config.secondary.sh for the respective first and second instances of cake-autorate.

### For multihomed setups, it is the responsibility of the user to ensure that the probes
### sent by this instance of cake-autorate actually travel through these interfaces.
### See ping_extra_args and ping_prefix_string

dl_if=ifb4eth0 # download interface
ul_if=eth0     # upload interface

# Set either of the below to 0 to adjust one direction only
# or alternatively set both to 0 to simply use cake-autorate to monitor a connection
adjust_dl_shaper_rate=1 # enable (1) or disable (0) actually changing the dl shaper rate
adjust_ul_shaper_rate=1 # enable (1) or disable (0) actually changing the ul shaper rate

min_dl_shaper_rate_kbps=5000  # minimum bandwidth for download (Kbit/s)
base_dl_shaper_rate_kbps=400000 # steady state bandwidth for download (Kbit/s)
max_dl_shaper_rate_kbps=950000  # maximum bandwidth for download (Kbit/s)

min_ul_shaper_rate_kbps=5000  # minimum bandwidth for upload (Kbit/s)
base_ul_shaper_rate_kbps=200000 # steady state bandwidth for upload (KBit/s)
max_ul_shaper_rate_kbps=800000  # maximum bandwidth for upload (Kbit/s)

connection_active_thr_kbps=20  # threshold in Kbit/s below which dl/ul is considered idle

# Logging toggles for various stats
output_processing_stats=1 # enable (1) or disable (0) output monitoring lines showing processing stats
output_load_stats=1       # enable (1) or disable (0) output monitoring lines showing achieved loads
output_reflector_stats=1  # enable (1) or disable (0) output monitoring lines showing reflector stats
output_summary_stats=1    # enable (1) or disable (0) output monitoring lines showing summary stats

# *** OVERRIDES ***

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.

### See defaults.sh for additional configuration options
### that can be set in this configuration file to override the defaults.
### Place any such overrides below this line.
reflectors=(
"165.21.83.88" "165.21.100.88"  # Singtel
"8.8.8.8" "8.8.4.4"  # Google
)

no_pingers=4
reflector_ping_interval_s=0.05
#randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors on startup

# classify a delay with an increase of 5ms, and maximally punish the shaper rate at a delay of 10ms.
dl_owd_delta_thr_ms=2.5 # (milliseconds)
ul_owd_delta_thr_ms=2.5 # (milliseconds)

dl_avg_owd_delta_thr_ms=5.0 # (milliseconds)
ul_avg_owd_delta_thr_ms=5.0 # (milliseconds)

bufferbloat_detection_window=4   # number of samples to retain in detection window
bufferbloat_detection_thr=2      # number of delayed samples for bufferbloat detection

# ** Take care with these settings to ensure you won't run into OOM issues on your router ***
# every write the cumulative write time and bytes associated with each log line are checked
# and if either exceeds the configured values below, the log file is rotated
log_to_file=1              # enable (1) or disable (0) output logging to file (/tmp/cake-autorate.log)
log_file_max_time_mins=10  # maximum time between log file rotations
log_file_max_size_KB=32000  # maximum KB (i.e. bytes/1024) worth of log lines between log file rotations

Runing OOkla SpeedTest from the wireless client.

PS C:\work\speedtest\ookla-speedtest-1.2.0-win64> .\speedtest.exe -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     3.12 ms   (jitter: 0.54ms, low: 2.62ms, high: 3.69ms)
    Download:   738.75 Mbps (data used: 669.6 MB)
                 10.68 ms   (jitter: 5.07ms, low: 3.28ms, high: 50.29ms)
      Upload:   565.70 Mbps (data used: 609.0 MB)
                 29.49 ms   (jitter: 10.45ms, low: 5.26ms, high: 101.76ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/f8c31fe0-e578-4dfd-9ab4-ab6ac8997252

Log file generated. cake-autorate.primary_2024_04_18_22_27_45.log.gz

Analysis output

MINGW64 /c/work/speedtest/cake-autorate
$ octave -qf --eval 'fn_parse_autorate_log("./*primary*log.gz", "./output.png")'
INFO: C:\work\speedtest\cake-autorate
INFO: Processing log file: ./*primary*log.gz
INFO: Trying to save plot as: ./output.png
INFO: Parsing log file: C:\work\speedtest\cake-autorate\cake-autorate.primary_2024_04_18_22_27_45.log
INFO: might take a while...
INFO: Processed line: 1000
INFO: Processed line: 2000
INFO: Processed line: 3000
INFO: Processed line: 4000
INFO: Processed line: 5000
INFO: Processed line: 6000
INFO: Saving parsed data file as: C:\work\speedtest\cake-autorate\cake-autorate.primary_2024_04_18_22_27_45.log.mat
INFO: Empty x_range_sec specified, plotting the whole sample timestamp range (0 - 37.1386).
Selected DATA sample indices: 1  2972
Selected LOAD sample indices: 1  185
INFO: Adjusted y-limits based on ADJ_DELAY_THR_factor: -9800  9940
INFO: Grand adjusted y-limits based on OWD_DELTA_QUANTILE_factor and ADJ_DELAY_THR_factor: -35070  35070
INFO: Writing plot as: .\output.rawCDFs.png
INFO: Writing plot as: .\output.deltaCDFs.png
Samples per reflector:
ReflectorID: 165.21.100.88; N: 402
ReflectorID: 165.21.83.88; N: 402
ReflectorID: 8.8.4.4; N: 402
ReflectorID: 8.8.8.8; N: 401
DL: maximum 95.000%-ile delta delay over all 4 reflectors: 10.560 ms.
DL: maximum 99.000%-ile delta delay over all 4 reflectors: 13.580 ms.
DL: maximum 99.500%-ile delta delay over all 4 reflectors: 14.450 ms.
DL: maximum 99.900%-ile delta delay over all 4 reflectors: 18.715 ms.
DL: maximum 99.950%-ile delta delay over all 4 reflectors: 18.715 ms.
DL: maximum 99.990%-ile delta delay over all 4 reflectors: 18.715 ms.
DL: maximum 99.999%-ile delta delay over all 4 reflectors: 18.715 ms.
UL: maximum 95.000%-ile delta delay over all 4 reflectors: 10.560 ms.
UL: maximum 99.000%-ile delta delay over all 4 reflectors: 13.580 ms.
UL: maximum 99.500%-ile delta delay over all 4 reflectors: 14.450 ms.
UL: maximum 99.900%-ile delta delay over all 4 reflectors: 18.715 ms.
UL: maximum 99.950%-ile delta delay over all 4 reflectors: 18.715 ms.
UL: maximum 99.990%-ile delta delay over all 4 reflectors: 18.715 ms.
UL: maximum 99.999%-ile delta delay over all 4 reflectors: 18.715 ms.
hold is now on for specified axes
hold is now on for specified axes
INFO: Writing plot as: .\output.timecourse.png
INFO: fn_parse_autorate_log took: 135.5146 seconds.

[moeller0]

I guess posting the output of tc -s qdisc might help to see what is going on...

[mcuee]

I guess posting the output of tc -s qdisc might help to see what is going on...

Sorry for the false alarm. I accidentally start another OpenWRT VM (older clone of the main OpenWRT VM) and the thing is not running correctly with the two VMs running in parallel..

[mcuee]

I guess posting the output of tc -s qdisc might help to see what is going on...

Sorry for the false alarm. I accidentally start another OpenWRT VM (older clone of the main OpenWRT VM) and the thing is not running correctly with the two VMs running in parallel..

Hmm, still the same results after I shut down the second VM.

root@OpenWrt:~# cat /etc/config/sqm

config queue 'eth1'
        option enabled '1'
        option interface 'eth0'
        option download '950000'
        option upload '700000'
        option qdisc 'cake'
        option script 'piece_of_cake.qos'
        option linklayer 'ethernet'
        option debug_logging '0'
        option verbosity '5'
        option overhead '44'

root@OpenWrt:~# tc -s qdisc
qdisc noqueue 0: dev lo root refcnt 2
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
qdisc fq_codel 0: dev eth0 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 890563919 bytes 127401 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 27252 drop_overlimit 0 new_flow_count 69 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 904043848 bytes 149665 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 211 drop_overlimit 0 new_flow_count 9 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc noqueue 0: dev br-lan root refcnt 2
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
qdisc noqueue 0: dev wg_lan root refcnt 2
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 70949 bytes 511 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 746 bytes 7 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc cake 8017: dev ifb4eth0 root refcnt 2 bandwidth 400Mbit besteffort triple-isolate nonat wash no-ack-filter split-gso rtt 100ms noatm overhead 44
 Sent 196 bytes 2 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
 memory used: 768b of 15140Kb
 capacity estimate: 950Mbit
 min/max network layer size:           84 /      84
 min/max overhead-adjusted size:      128 /     128
 average network hdr offset:            0

                  Tin 0
  thresh        400Mbit
  target            5ms
  interval        100ms
  pk_delay          1us
  av_delay          0us
  sp_delay          0us
  backlog            0b
  pkts                2
  bytes             196
  way_inds            0
  way_miss            2
  way_cols            0
  drops               0
  marks               0
  ack_drop            0
  sp_flows            2
  bk_flows            0
  un_flows            0
  max_len            98
  quantum          1514

root@OpenWrt:~# tc -d qdisc
qdisc noqueue 0: dev lo root refcnt 2
qdisc fq_codel 0: dev eth0 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc noqueue 0: dev br-lan root refcnt 2
qdisc noqueue 0: dev wg_lan root refcnt 2
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc cake 8017: dev ifb4eth0 root refcnt 2 bandwidth 400Mbit besteffort triple-isolate nonat wash no-ack-filter split-gso rtt 100ms noatm overhead 44

[mcuee]

After reboot.

root@OpenWrt:~# cat /etc/config/sqm

config queue 'eth1'
        option enabled '1'
        option interface 'eth0'
        option download '950000'
        option upload '700000'
        option qdisc 'cake'
        option script 'piece_of_cake.qos'
        option linklayer 'ethernet'
        option debug_logging '0'
        option verbosity '5'
        option overhead '44'

root@OpenWrt:~# tc -d qdisc
qdisc noqueue 0: dev lo root refcnt 2
qdisc fq_codel 0: dev eth0 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc noqueue 0: dev br-lan root refcnt 2
qdisc noqueue 0: dev wg_lan root refcnt 2
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
qdisc cake 8017: dev ifb4eth0 root refcnt 2 bandwidth 950Mbit besteffort triple-isolate nonat wash no-ack-filter split-gso rtt 100ms noatm overhead 44

root@OpenWrt:~# tc -s qdisc
qdisc noqueue 0: dev lo root refcnt 2
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
qdisc fq_codel 0: dev eth0 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 542086 bytes 4336 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 160 drop_overlimit 0 new_flow_count 2 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc fq_codel 0: dev eth1 root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 231268 bytes 909 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 172 drop_overlimit 0 new_flow_count 1 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc fq_codel 0: dev ifb-dns root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc noqueue 0: dev br-lan root refcnt 2
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
qdisc noqueue 0: dev wg_lan root refcnt 2
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
qdisc fq_codel 0: dev tailscale0 root refcnt 2 limit 10240p flows 1024 quantum 1500 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 21867 bytes 134 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc fq_codel 0: dev ztyqbuckbd root refcnt 2 limit 10240p flows 1024 quantum 1514 target 5ms interval 100ms memory_limit 32Mb ecn drop_batch 64
 Sent 746 bytes 7 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
  maxpacket 0 drop_overlimit 0 new_flow_count 0 ecn_mark 0
  new_flows_len 0 old_flows_len 0
qdisc cake 8017: dev ifb4eth0 root refcnt 2 bandwidth 950Mbit besteffort triple-isolate nonat wash no-ack-filter split-gso rtt 100ms noatm overhead 44
 Sent 196 bytes 2 pkt (dropped 0, overlimits 0 requeues 0)
 backlog 0b 0p requeues 0
 memory used: 768b of 15140Kb
 capacity estimate: 950Mbit
 min/max network layer size:           84 /      84
 min/max overhead-adjusted size:      128 /     128
 average network hdr offset:            0

                  Tin 0
  thresh        950Mbit
  target            5ms
  interval        100ms
  pk_delay          1us
  av_delay          0us
  sp_delay          0us
  backlog            0b
  pkts                2
  bytes             196
  way_inds            0
  way_miss            2
  way_cols            0
  drops               0
  marks               0
  ack_drop            0
  sp_flows            2
  bk_flows            0
  un_flows            0
  max_len            98
  quantum          1514

OOkla SpeedTest:

PS C:\work\speedtest\ookla-speedtest-1.2.0-win64> .\speedtest.exe -s 13623

   Speedtest by Ookla

      Server: Singtel - Singapore (id: 13623)
         ISP: Singtel Fibre
Idle Latency:     3.15 ms   (jitter: 0.59ms, low: 2.59ms, high: 3.53ms)
    Download:   753.19 Mbps (data used: 803.1 MB)
                 10.31 ms   (jitter: 4.51ms, low: 3.07ms, high: 20.71ms)
      Upload:   733.39 Mbps (data used: 1.3 GB)
                 24.99 ms   (jitter: 9.89ms, low: 4.22ms, high: 80.27ms)
 Packet Loss:     0.0%
  Result URL: https://www.speedtest.net/result/c/20bce34f-766c-4c77-932e-bb18f7c0ad28

Log file: cake-autorate.primary_2024_04_18_23_46_33.log.gz

Output:

[moeller0]

Something is wrong with your native sqm/cake set-up, we only see a single cake instance in tc -s qdisc the expected cake instance on eth0 is missing...