Improve controller

ANALYSIS.md

@@ -5,6 +5,16 @@ bandwidth settings based on traffic load and round-trip time
 measurements. See the main [README](./README.md) page for more details
 of the algorithm.
 
+## Viewing a simple summary of key statistics on the command line
+
+A simple summary of the key statistics can be generated on the 
+command line so long as `output_reflector_stats` is enabled
+using e.g.:
+
+```bash
+tail -f /var/log/cake-autorate.primary.log | grep -e SUMMARY
+```
+
 ## Exporting a Log File
 
 Extract a compressed log file from a running cake-autorate instance

CHANGELOG.md

@@ -7,6 +7,22 @@ more about cake-autorate. This is the history of changes.
 
 <!-- Zep7RkGZ52|NEW ENTRY MARKER, DO NOT REMOVE -->
 
+## 2023-07-29 - Version 3.1.0
+
+- Removed consulting the achieved rate when setting the new shaper 
+rate on detection of bufferbloat. Whilst the achieved transfer rate
+on bufferbloat detection can give insight into the connection capacity,
+leveraging this effectively proved troublesome.
+- Introduced scaling of shaper rate reduction on bufferbloat based on
+the average OWD delta taken across the bufferbloat detection window
+as a portion of a user configurable average OWD delta threshold.
+- Amended existing DATA log lines for more consistency and to incorporate 
+the average OWD deltas and compensated thresholds.
+- Introduced new SUMMARY log lines to offer a simple way to see a 
+summary of key statistics using: `grep -e SUMMARY`.
+- Utilities that read from log file(s) will need to be updated to 
+take into account the changes to the logging. 
+
 ## 2023-07-08 - Version 3.0.0
 
 - Version 3.0.0 of cake-autorate is the culmination of dozens of

INSTALLATION.md

@@ -86,6 +86,7 @@ required tools. To use it:
     |      `output_processing_stats` | If non-zero, log the results of every iteration through the process                                                                                                                                                                                   |
     |            `output_load_stats` | If non-zero, log the log the measured achieved rates of upload and download                                                                                                                                                                           |
     |       `output_reflector_stats` | If non-zero, log the statistics generated in respect of reflector health monitoring                                                                                                                                                                   |
+    |         `output_summary_stats` | If non-zero, log a summary with the key statistics                                                                                                                                                                                |
     |          `output_cake_changes` | If non-zero, log when changes are made to CAKE settings via `tc` - this shows when cake-autorate is adjusting the shaper                                                                                                                              |
     |                        `debug` | If non-zero, debug lines will be output                                                                                                                                                                                                               |
     | `log_DEBUG_messages_to_syslog` | If non-zero, log lines will also get sent to the system log                                                                                                                                                                                           |

cake-autorate.sh

@@ -157,7 +157,7 @@ print_headers()
 {
 	log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}"
 
-	header="DATA_HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; RTT_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_EWMA_US; DL_OWD_DELTA_US; DL_ADJ_DELAY_THR; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_EWMA_US; UL_OWD_DELTA_US; UL_ADJ_DELAY_THR; SUM_DL_DELAYS; SUM_UL_DELAYS; DL_LOAD_CONDITION; UL_LOAD_CONDITION; CAKE_DL_RATE_KBPS; CAKE_UL_RATE_KBPS"
+	header="DATA_HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_LOAD_PERCENT; UL_LOAD_PERCENT; ICMP_TIMESTAMP; REFLECTOR; SEQUENCE; DL_OWD_BASELINE; DL_OWD_US; DL_OWD_DELTA_EWMA_US; DL_OWD_DELTA_US; DL_ADJ_DELAY_THR; UL_OWD_BASELINE; UL_OWD_US; UL_OWD_DELTA_EWMA_US; UL_OWD_DELTA_US; UL_ADJ_DELAY_THR; DL_SUM_DELAYS; DL_AVG_OWD_DELTA_US; DL_ADJ_OWD_DELTA_THR_US; UL_SUM_DELAYS; UL_AVG_OWD_DELTA; UL_ADJ_OWD_DELTA_THR_US; DL_LOAD_CONDITION; UL_LOAD_CONDITION; CAKE_DL_RATE_KBPS; CAKE_UL_RATE_KBPS"
  	((log_to_file)) && printf '%s\n' "${header}" >> "${log_file_path}"
  	((terminal)) && printf '%s\n' "${header}"
 
@@ -168,6 +168,10 @@ print_headers()
 	header="REFLECTOR_HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; REFLECTOR; MIN_SUM_OWD_BASELINES_US; SUM_OWD_BASELINES_US; SUM_OWD_BASELINES_DELTA_US; SUM_OWD_BASELINES_DELTA_THR_US; MIN_DL_DELTA_EWMA_US; DL_DELTA_EWMA_US; DL_DELTA_EWMA_DELTA_US; DL_DELTA_EWMA_DELTA_THR; MIN_UL_DELTA_EWMA_US; UL_DELTA_EWMA_US; UL_DELTA_EWMA_DELTA_US; UL_DELTA_EWMA_DELTA_THR"
  	((log_to_file)) && printf '%s\n' "${header}" >> "${log_file_path}"
  	((terminal)) && printf '%s\n' "${header}"
+
+	header="SUMMARY_HEADER; LOG_DATETIME; LOG_TIMESTAMP; DL_ACHIEVED_RATE_KBPS; UL_ACHIEVED_RATE_KBPS; DL_SUM_DELAYS; UL_SUM_DELAYS; DL_AVG_OWD_DELTA_US; UL_AVG_OWD_DELTA_US; DL_LOAD_CONDITION; UL_LOAD_CONDITION; CAKE_DL_RATE_KBPS; CAKE_UL_RATE_KBPS"
+ 	((log_to_file)) && printf '%s\n' "${header}" >> "${log_file_path}"
+ 	((terminal)) && printf '%s\n' "${header}"
 }
 
 # MAINTAIN_LOG_FILE + HELPER FUNCTIONS
@@ -374,9 +378,18 @@ update_shaper_rate()
 		*bb*)
 			if (( t_start_us > (t_last_bufferbloat_us["${direction}"]+bufferbloat_refractory_period_us) ))
 			then
-				adjusted_achieved_rate_kbps=$(( (achieved_rate_kbps["${direction}"]*achieved_rate_adjust_down_bufferbloat)/1000 )) 
-				adjusted_shaper_rate_kbps=$(( (shaper_rate_kbps["${direction}"]*shaper_rate_adjust_down_bufferbloat)/1000 )) 
-				shaper_rate_kbps["${direction}"]=$(( adjusted_achieved_rate_kbps > min_shaper_rate_kbps["${direction}"] && adjusted_achieved_rate_kbps < adjusted_shaper_rate_kbps ? adjusted_achieved_rate_kbps : adjusted_shaper_rate_kbps ))
+				if (( avg_owd_delta_thr_us["${direction}"] == 0 ))
+				then
+					shaper_rate_adjust_down_bufferbloat_factor=1000
+				elif (( avg_owd_delta_us["${direction}"] > 0 ))
+				then
+					shaper_rate_adjust_down_bufferbloat_factor=$(( (1000*avg_owd_delta_us["${direction}"])/compensated_avg_owd_delta_thr_us["${direction}"] ))
+					(( shaper_rate_adjust_down_bufferbloat_factor > 1000 )) && shaper_rate_adjust_down_bufferbloat_factor=1000
+				else
+					shaper_rate_adjust_down_bufferbloat_factor=0
+				fi
+				shaper_rate_adjust_down_bufferbloat=$(( 1000000-shaper_rate_adjust_down_bufferbloat_factor*(1000-shaper_rate_max_adjust_down_bufferbloat) ))
+				shaper_rate_kbps["${direction}"]=$(( (shaper_rate_kbps["${direction}"]*shaper_rate_adjust_down_bufferbloat)/1000000 )) 
 				t_last_bufferbloat_us["${direction}"]="${EPOCHREALTIME/./}"
 			fi
 			;;
@@ -1543,12 +1556,14 @@ update_max_wire_packet_compensation()
 	# Compensate for delays imposed by active traffic shaper
 	# This will serve to increase the delay thr at rates below around 12Mbit/s
 
-	# compensated OWD delay thresholds in microseconds
-	compensated_dl_delay_thr_us=$(( dl_delay_thr_us + (1000*dl_max_wire_packet_size_bits)/shaper_rate_kbps[dl] ))
-	compensated_ul_delay_thr_us=$(( ul_delay_thr_us + (1000*ul_max_wire_packet_size_bits)/shaper_rate_kbps[ul] ))
+	dl_compensation_us=$(( (1000*dl_max_wire_packet_size_bits)/shaper_rate_kbps[dl] ))
+	ul_compensation_us=$(( (1000*ul_max_wire_packet_size_bits)/shaper_rate_kbps[ul] ))
 
-	printf "SET_VAR compensated_dl_delay_thr_us %s\n" "${compensated_dl_delay_thr_us}" >&"${maintain_pingers_fd}"
-	printf "SET_VAR compensated_dl_delay_thr_us %s\n" "${compensated_dl_delay_thr_us}" >&"${maintain_pingers_fd}"
+	compensated_owd_delta_thr_us[dl]=$(( dl_owd_delta_thr_us + dl_compensation_us ))
+	compensated_owd_delta_thr_us[ul]=$(( ul_owd_delta_thr_us + ul_compensation_us ))
+
+	compensated_avg_owd_delta_thr_us[dl]=$(( dl_avg_owd_delta_thr_us + dl_compensation_us ))
+	compensated_avg_owd_delta_thr_us[ul]=$(( ul_avg_owd_delta_thr_us + ul_compensation_us ))
 
 	max_wire_packet_rtt_us=$(( (1000*dl_max_wire_packet_size_bits)/shaper_rate_kbps[dl] + (1000*ul_max_wire_packet_size_bits)/shaper_rate_kbps[ul] ))
 
@@ -1926,13 +1941,14 @@ verify_ifs_up
 
 # Convert human readable parameters to values that work with integer arithmetic
 
-printf -v dl_delay_thr_us %.0f "${dl_delay_thr_ms}e3"
-printf -v ul_delay_thr_us %.0f "${ul_delay_thr_ms}e3"
+printf -v dl_owd_delta_thr_us %.0f "${dl_owd_delta_thr_ms}e3"
+printf -v ul_owd_delta_thr_us %.0f "${ul_owd_delta_thr_ms}e3"
+printf -v dl_avg_owd_delta_thr_us %.0f "${dl_avg_owd_delta_thr_ms}e3"
+printf -v ul_avg_owd_delta_thr_us %.0f "${ul_avg_owd_delta_thr_ms}e3"
 printf -v alpha_baseline_increase %.0f "${alpha_baseline_increase}e6"
 printf -v alpha_baseline_decrease %.0f "${alpha_baseline_decrease}e6"   
 printf -v alpha_delta_ewma %.0f "${alpha_delta_ewma}e6"   
-printf -v achieved_rate_adjust_down_bufferbloat %.0f "${achieved_rate_adjust_down_bufferbloat}e3"
-printf -v shaper_rate_adjust_down_bufferbloat %.0f "${shaper_rate_adjust_down_bufferbloat}e3"
+printf -v shaper_rate_max_adjust_down_bufferbloat %.0f "${shaper_rate_max_adjust_down_bufferbloat}e3"
 printf -v shaper_rate_adjust_up_load_high %.0f "${shaper_rate_adjust_up_load_high}e3"
 printf -v shaper_rate_adjust_down_load_low %.0f "${shaper_rate_adjust_down_load_low}e3"
 printf -v shaper_rate_adjust_up_load_low %.0f "${shaper_rate_adjust_up_load_low}e3"
@@ -1976,6 +1992,10 @@ declare -A min_shaper_rate_kbps
 declare -A max_shaper_rate_kbps
 declare -A interface
 declare -A adjust_shaper_rate
+declare -A avg_owd_delta_us
+declare -A avg_owd_delta_thr_us
+declare -A compensated_owd_delta_thr_us
+declare -A compensated_avg_owd_delta_thr_us
 
 base_shaper_rate_kbps[dl]="${base_dl_shaper_rate_kbps}"
 base_shaper_rate_kbps[ul]="${base_ul_shaper_rate_kbps}"
@@ -2003,6 +2023,12 @@ ul_max_wire_packet_size_bits=0
 get_max_wire_packet_size_bits "${dl_if}" dl_max_wire_packet_size_bits  
 get_max_wire_packet_size_bits "${ul_if}" ul_max_wire_packet_size_bits
 
+avg_owd_delta_us[dl]=0
+avg_owd_delta_us[ul]=0
+
+avg_owd_delta_thr_us[dl]="${dl_avg_owd_delta_thr_us}"
+avg_owd_delta_thr_us[ul]="${ul_avg_owd_delta_thr_us}"
+
 set_shaper_rate "dl"
 set_shaper_rate "ul"
 
@@ -2023,10 +2049,14 @@ reflectors_last_timestamp_us="${EPOCHREALTIME/./}"
 
 mapfile -t dl_delays < <(for ((i=1; i <= bufferbloat_detection_window; i++)); do echo 0; done)
 mapfile -t ul_delays < <(for ((i=1; i <= bufferbloat_detection_window; i++)); do echo 0; done)
+mapfile -t dl_owd_deltas_us < <(for ((i=1; i <= bufferbloat_detection_window; i++)); do echo 0; done)
+mapfile -t ul_owd_deltas_us < <(for ((i=1; i <= bufferbloat_detection_window; i++)); do echo 0; done)
 
 delays_idx=0
 sum_dl_delays=0
 sum_ul_delays=0
+sum_dl_owd_deltas_us=0
+sum_ul_owd_deltas_us=0
 
 if ((debug))
 then
@@ -2142,18 +2172,32 @@ do
 					continue
 				fi
 
-				# Keep track of number of delays across detection window
+				# Keep track of delays across detection window
+
 				# .. for download:
 				(( dl_delays[delays_idx] )) && ((sum_dl_delays--))
-				dl_delays[delays_idx]=$(( dl_owd_delta_us > compensated_dl_delay_thr_us ? 1 : 0 ))
+				dl_delays[delays_idx]=$(( dl_owd_delta_us > compensated_owd_delta_thr_us[dl] ? 1 : 0 ))
 				((dl_delays[delays_idx])) && ((sum_dl_delays++))
+
+				(( sum_dl_owd_deltas_us -= dl_owd_deltas_us[delays_idx] ))
+				(( dl_owd_deltas_us[delays_idx] = dl_owd_delta_us ))
+				(( sum_dl_owd_deltas_us += dl_owd_delta_us ))
+
 				# .. for upload
 				(( ul_delays[delays_idx] )) && ((sum_ul_delays--))
-				ul_delays[delays_idx]=$(( ul_owd_delta_us > compensated_ul_delay_thr_us ? 1 : 0 ))
+				ul_delays[delays_idx]=$(( ul_owd_delta_us > compensated_owd_delta_thr_us[ul] ? 1 : 0 ))
 				((ul_delays[delays_idx])) && ((sum_ul_delays++))
+
+				(( sum_ul_owd_deltas_us -= ul_owd_deltas_us[delays_idx] ))
+				(( ul_owd_deltas_us[delays_idx] = ul_owd_delta_us ))
+				(( sum_ul_owd_deltas_us += ul_owd_delta_us ))
+
 				# .. and move index on	
 				(( delays_idx=(delays_idx+1)%bufferbloat_detection_window ))
 
+				(( avg_owd_delta_us[dl] = sum_dl_owd_deltas_us / bufferbloat_detection_window ))
+				(( avg_owd_delta_us[ul] = sum_ul_owd_deltas_us / bufferbloat_detection_window ))
+
 				bufferbloat_detected[dl]=$(( sum_dl_delays >= bufferbloat_detection_thr ? 1 : 0 ))
 				bufferbloat_detected[ul]=$(( sum_ul_delays >= bufferbloat_detection_thr ? 1 : 0 ))
 
@@ -2171,10 +2215,16 @@ do
 
 				if (( output_processing_stats ))
 				then 
-					printf -v processing_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${achieved_rate_kbps[dl]}" "${achieved_rate_kbps[ul]}" "${load_percent[dl]}" "${load_percent[ul]}" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${compensated_dl_delay_thr_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" "${compensated_ul_delay_thr_us}" "${sum_dl_delays}" "${sum_ul_delays}" "${load_condition[dl]}" "${load_condition[ul]}" "${shaper_rate_kbps[dl]}" "${shaper_rate_kbps[ul]}"
+					printf -v processing_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${achieved_rate_kbps[dl]}" "${achieved_rate_kbps[ul]}" "${load_percent[dl]}" "${load_percent[ul]}" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${compensated_owd_delta_thr_us[dl]}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" "${compensated_owd_delta_thr_us[ul]}" "${sum_dl_delays}" "${avg_owd_delta_us[dl]}" "${compensated_avg_owd_delta_thr_us[dl]}" "${sum_ul_delays}" "${avg_owd_delta_us[ul]}" "${compensated_avg_owd_delta_thr_us[ul]}" "${load_condition[dl]}" "${load_condition[ul]}" "${shaper_rate_kbps[dl]}" "${shaper_rate_kbps[ul]}"
 					log_msg "DATA" "${processing_stats}"
 				fi
 
+				if (( output_summary_stats ))
+				then
+					printf -v summary_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${achieved_rate_kbps[dl]}" "${achieved_rate_kbps[ul]}" "${sum_dl_delays}" "${sum_ul_delays}" "${avg_owd_delta_us[dl]}" "${avg_owd_delta_us[ul]}" "${load_condition[dl]}" "${load_condition[ul]}" "${shaper_rate_kbps[dl]}" "${shaper_rate_kbps[ul]}"
+					log_msg "SUMMARY" "${summary_stats}"
+				fi
+
 				# If base rate is sustained, increment sustained base rate timer (and break out of processing loop if enough time passes)
 				if (( enable_sleep_function ))
 				then

defaults.sh

@@ -18,6 +18,7 @@
 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
 output_cake_changes=0     	# enable (1) or disable (0) output monitoring lines showing cake bandwidth changes
 debug=1 		  	# enable (1) or disable (0) out of debug lines
 
@@ -75,11 +76,16 @@ randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors o
 no_pingers=6 # number of pingers to maintain
 reflector_ping_interval_s=0.3 # (seconds, e.g. 0.2s or 2s)
 
-# delay threshold in ms is the extent of OWD increase to classify as a delay
+# owd delta threshold in ms is the extent of OWD increase to classify as a delay
 # these are automatically adjusted based on maximum on the wire packet size
 # (adjustment significant at sub 12Mbit/s rates, else negligible)
-dl_delay_thr_ms=30.0 # (milliseconds)
-ul_delay_thr_ms=30.0 # (milliseconds)
+dl_owd_delta_thr_ms=30.0 # (milliseconds)
+ul_owd_delta_thr_ms=30.0 # (milliseconds)
+
+# average owd delta threshold in ms at which maximum adjust_down_bufferbloat is applied
+# set value(s) to 0 to disable and always apply maximum adjust_down_bufferbloat
+dl_avg_owd_delta_thr_ms=60.0 # (milliseconds)
+ul_avg_owd_delta_thr_ms=60.0 # (milliseconds)
 
 # 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
@@ -158,14 +164,13 @@ alpha_baseline_decrease=0.9  # how rapidly baseline RTT is allowed to decrease
 alpha_delta_ewma=0.095
 
 # rate adjustment parameters
-# bufferbloat adjustment works with the lower of the adjusted achieved rate and adjusted shaper rate
-# to exploit that transfer rates during bufferbloat provide an indication of line capacity
+# shaper rate is adjusted by a maximum of shaper_rate_max_adjust_down_bufferbloat on detection of bufferbloat
+# and this is scaled by the average delta owd / average owd delta threshold
 # otherwise shaper rate is adjusted up on load high, and down on load idle or low
-achieved_rate_adjust_down_bufferbloat=0.9 # how rapidly to reduce achieved rate upon detection of bufferbloat
-shaper_rate_adjust_down_bufferbloat=0.9   # how rapidly to reduce shaper rate upon detection of bufferbloat
-shaper_rate_adjust_up_load_high=1.01      # how rapidly to increase shaper rate upon high load detected
-shaper_rate_adjust_down_load_low=0.99     # how rapidly to return down to base shaper rate upon idle or low load detected
-shaper_rate_adjust_up_load_low=1.01       # how rapidly to return up to base shaper rate upon idle or low load detected
+shaper_rate_max_adjust_down_bufferbloat=0.75	# how rapidly to reduce shaper rate upon detection of bufferbloat
+shaper_rate_adjust_up_load_high=1.01		# how rapidly to increase shaper rate upon high load detected
+shaper_rate_adjust_down_load_low=0.99		# how rapidly to return down to base shaper rate upon idle or low load detected
+shaper_rate_adjust_up_load_low=1.01		# how rapidly to return up to base shaper rate upon idle or low load detected
 
 # the load is categoried as low if < high_load_thr and high if > high_load_thr relative to the current shaper rate
 high_load_thr=0.75   # % of currently set bandwidth for detecting high load