fixed valgrind profiling script to automatically generate a callgrind report after profiling is complete

Co-authored-by: Copilot <copilot@github.com>

Author: marc-casavant

src/tests/multi-server/scripts/profiling/start_valgrind_profiling.sh

@@ -4,6 +4,13 @@
 
 # Clear any stale marker from a previous run
 rm -f /etc/prof-results/.profiling_complete
+rm -f /etc/prof-results/start_valgrind_profiling.log
+
+exec > /etc/prof-results/start_valgrind_profiling.log 2>&1
+
+# Ignore SIGTERM — freeradius broadcasts it to the process group on shutdown,
+# which would otherwise kill this script before it can touch .profiling_complete
+trap '' SIGTERM
 
 # Load proto_load config to get packet settings
 source /etc/freeradius/proto_load_config.env
@@ -26,16 +33,26 @@ valgrind \
   --keep-debuginfo=yes \
   --instr-atstart=no \
   freeradius -f -l stdout -S resources.talloc_skip_cleanup=yes 2>&1 | \
-  tee /tmp/fr.log &
+  tee /etc/prof-results/freeradius_profiling.log &
+VALGRIND_PID=$!
 
-# Wait for server ready
-until grep -q "Ready to process requests" /tmp/fr.log; do
-  sleep 0.1
+# Wait for server ready (bail out if freeradius fails to start under valgrind)
+STARTUP_TIMEOUT=300
+STARTUP_ELAPSED=0
+until grep -q "Ready to process requests" /etc/prof-results/freeradius_profiling.log; do
+  sleep 1
+  STARTUP_ELAPSED=$(( STARTUP_ELAPSED + 1 ))
+  if [ ${STARTUP_ELAPSED} -ge ${STARTUP_TIMEOUT} ]; then
+    echo "ERROR: freeradius did not become ready within ${STARTUP_TIMEOUT}s, aborting"
+    kill -SIGKILL ${VALGRIND_PID} 2>/dev/null
+    exit 1
+  fi
 done
 
 # Enable instrumentation. callgrind_control auto-detects the running callgrind
 # instance and prints "PID <n>: freeradius ..." — capture that to get the PID
 # we need later for the graceful shutdown signal.
+echo "INFO: enabling callgrind instrumentation"
 CTRL_OUT=$(callgrind_control --instr=on)
 printf '%s\n' "$CTRL_OUT"
 FR_PID=$(printf '%s\n' "$CTRL_OUT" | grep -oP 'PID \K\d+(?=: freeradius)' | head -1)
@@ -44,9 +61,27 @@ echo "Freeradius PID: ${FR_PID}"
 # Wait for approximate send duration
 sleep ${SEND_DURATION}
 
+# Stop instrumentation before shutdown so valgrind only flushes already-collected data
+echo "INFO: disabling callgrind instrumentation"
+CTRL_OUT=$(callgrind_control --instr=off 2>/dev/null || true)
+printf '%s\n' "$CTRL_OUT"
+
 # Graceful shutdown (equivalent to Ctrl+C)
-kill -SIGINT ${FR_PID}
-wait
+if [ -z "${FR_PID}" ]; then
+  echo "WARNING: could not determine freeradius PID from callgrind_control output, sending SIGINT to valgrind pipeline instead"
+  kill -SIGINT ${VALGRIND_PID} 2>/dev/null || true
+else
+  echo "INFO: killing freeradius process ${FR_PID} with SIGINT for graceful shutdown"
+  kill -SIGINT ${FR_PID}
+fi
+
+# Give valgrind time to write callgrind output after freeradius exits
+echo "INFO: sleeping for 5s"
+sleep 5
 
 # Signal that valgrind has finished writing all profiling data
+echo "INFO: Profiling complete at $(date)"
 touch /etc/prof-results/.profiling_complete
+
+# Restore stdout/stderr so subsequent commands in the parent shell
+exec > /dev/null 2>&1

src/tests/multi-server/tests/prof-accept/short.ci.test.yml

@@ -13,6 +13,7 @@ loadgen:
   repeat: "no"
 
 # Test framework
-test_timeout: 165
-test_state1_verify_timeout: 130
-test_state2_verify_timeout: 5
+# state_1 must cover: valgrind startup (slow under callgrind) + SEND_DURATION sleep (30s) + callgrind dump write
+test_timeout: 125
+test_state1_verify_timeout: 120
+test_state2_verify_timeout: 30

src/tests/multi-server/tests/prof-accept/template.yml.j2

@@ -30,32 +30,17 @@ states:
               {%- endfor %}
               printf "  NUM_MESSAGES:     %s\n" "$TEST_LOADGEN_NUM_MESSAGES"
 
-              # No profiling
-              #exec freeradius -f -l stdout
-
               source /etc/freeradius/start_valgrind_profiling.sh
 
-            detach: true
-        - execute_command:
-            command: |
               # Block until valgrind finishes writing all profiling data.
               # start_valgrind_profiling.sh touches this file after `wait` returns.
-              until [ -f /etc/prof-results/.profiling_complete ]; do sleep 5; done
+              #until [ -f /etc/prof-results/.profiling_complete ]; do sleep 5; done
               rm -f /etc/prof-results/.profiling_complete
+
+              echo "INFO: running callgrind_annotate to generate report" | tee -a /etc/prof-results/start_valgrind_profiling.log
+              callgrind_annotate $(find /etc/prof-results -name "callgrind.out.*" -size +0c | sort) > /etc/prof-results/callgrind_report.txt
+
+            detach: true
     verify:
       timeout: {{ test_state1_verify_timeout }}
       trigger_mode: unordered
-  state_2:
-    description: >
-      Generate Valgrind/callgrind profiling report
-    host:
-      profiling-server:
-        actions:
-        - execute_command:
-            command: |
-              # Generate report from non-empty callgrind.out.* output files
-              cd /etc/prof-results
-              callgrind_annotate $(find . -name "callgrind.out.*" -size +0c | sort) > callgrind_report.txt
-    verify:
-      timeout: {{ test_state2_verify_timeout }}
-      trigger_mode: unordered