WIP: profiling for ns_per_call

Author: Mes0903

Makefile

@@ -77,6 +77,8 @@ DTC ?= dtc
 E :=
 S := $E $E
 
+LDFLAGS := -pg
+
 SMP ?= 1
 CFLAGS += -D SEMU_BOOT_TARGET_TIME=10
 .PHONY: riscv-harts.dtsi

analyze.sh

@@ -0,0 +1,124 @@
+#!/usr/bin/env bash
+#
+# parse_results.sh:
+#   Parse "emulator_SMP_{N}.log" and "gprof_SMP_{N}.log" for each N=1..32
+#   to extract:
+#     - predict_sec
+#     - real_boot_time
+#     - times (calls)
+#     - semu_timer_clocksource percentage
+#     - ns_per_call
+#     - real_ns_per_call (calculated)
+#     - scale_factor
+#
+#   Output a summary line for each SMP=N in tab-delimited format.
+
+LOGDIR="logs"   # or wherever your logs are
+OUTFILE="results_summary.txt"
+
+echo -e "SMP\treal_boot_time\ttimes\t\tns_per_call\tpredict_sec\tscale_factor\tpercentage\treal_ns_per_call" > "$OUTFILE"
+
+for N in $(seq 1 32); do
+    EMU_LOG="$LOGDIR/emulator_SMP_${N}.log"
+    GPROF_LOG="$LOGDIR/gprof_SMP_${N}.log"
+
+    # Check that the files exist
+    if [[ ! -f "$EMU_LOG" ]]; then
+        echo "Warning: $EMU_LOG not found, skipping"
+        continue
+    fi
+    if [[ ! -f "$GPROF_LOG" ]]; then
+        echo "Warning: $GPROF_LOG not found, skipping"
+        continue
+    fi
+
+    # Initialize variables we want to parse
+    predict_sec=""
+    real_boot_time=""
+    times_called=""
+    ns_per_call=""
+    scale_factor=""
+    percentage=""
+    real_ns_per_call=""
+
+    # 1) Parse from emulator_SMP_{N}.log:
+    #    We look for lines:
+    #    "[SEMU LOG]: Boot time: 7.82979 seconds, called 233068043 times semu_timer_clocksource"
+    #    next line: "ns_per_call = 5.10756, predict_sec = 10.21511, scale_factor = 0.97894"
+    #    We can do it with grep + sed or awk or a while-read approach
+
+    # Extract the "Boot time" line
+    # e.g. "Boot time: 7.82979 seconds, called 233068043 times semu_timer_clocksource"
+    # We'll parse the "7.82979" as real_boot_time, "233068043" as times_called
+    line_boot_time="$(grep -Eo '\[SEMU LOG\]: Boot time: [^,]*, called [^ ]* times semu_timerclocksource.*' "$EMU_LOG")"
+    # Alternatively you might want a simpler approach:
+    # Let's do a grep for "Boot time:" and read the line with everything
+    if [[ -z "$line_boot_time" ]]; then
+        # Possibly there's an ANSI color code. Let's remove them with sed
+        line_boot_time="$(grep 'Boot time:' "$EMU_LOG" | sed 's/\x1b\[[0-9;]*m//g')"
+    fi
+
+    # Now parse it. Example format:
+    # Boot time: 7.82979 seconds, called 233068043 times semu_timer_clocksource
+    # We can use sed or awk:
+    if [[ -n "$line_boot_time" ]]; then
+        # Remove ANSI codes again if needed:
+        no_ansi="$(echo "$line_boot_time" | sed 's/\x1b\[[0-9;]*m//g')"
+        # Extract e.g. 7.82979 and 233068043
+        real_boot_time="$(echo "$no_ansi" | sed -E 's/.*Boot time: ([0-9.]+) seconds, called ([0-9]+) times.*/\1/')"
+        times_called="$(echo "$no_ansi" | sed -E 's/.*Boot time: ([0-9.]+) seconds, called ([0-9]+) times.*/\2/')"
+    fi
+
+    # Next line with "ns_per_call = 5.10756, predict_sec = 10.21511, scale_factor = 0.97894"
+    # We'll grep and parse similarly
+    line_ns_call="$(grep -Eo 'ns_per_call = [^,]*, predict_sec = [^,]*, scale_factor = [^ ]*' "$EMU_LOG" | sed 's/\x1b\[[0-9;]*m//g')"
+    if [[ -n "$line_ns_call" ]]; then
+        # Example: "ns_per_call = 5.10756, predict_sec = 10.21511, scale_factor = 0.97894"
+        ns_per_call="$(echo "$line_ns_call" | sed -E 's/.*ns_per_call = ([0-9.]+), predict_sec = ([0-9.]+), scale_factor = ([0-9.]+)/\1/')"
+        predict_sec="$(echo "$line_ns_call" | sed -E 's/.*ns_per_call = ([0-9.]+), predict_sec = ([0-9.]+), scale_factor = ([0-9.]+)/\2/')"
+        scale_factor="$(echo "$line_ns_call" | sed -E 's/.*ns_per_call = ([0-9.]+), predict_sec = ([0-9.]+), scale_factor = ([0-9.]+)/\3/')"
+    fi
+
+    # 2) From gprof_SMP_{N}.log:
+    #    We search for the line that includes "semu_timer_clocksource" in the "Flat profile:" section
+    #    Example: "47.74  3.07  3.07   ... semu_timer_clocksource"
+    #    We'll parse the first field as the percentage
+    # We'll do something like:
+    line_gprof="$(grep -E '[0-9]+\.[0-9]+[[:space:]]+[0-9]+\.[0-9]+[[:space:]]+[0-9]+\.[0-9]+.*semu_timer_clocksource' "$GPROF_LOG")"
+    # fallback if the spacing is different, or just search for 'semu_timer_clocksource'
+    if [[ -z "$line_gprof" ]]; then
+        line_gprof="$(grep 'semu_timer_clocksource' "$GPROF_LOG")"
+    fi
+
+    # e.g.: " 47.74   3.07     3.07     semu_timer_clocksource"
+    # The first column is 47.74. We'll parse that:
+    if [[ -n "$line_gprof" ]]; then
+        # remove leading spaces
+        no_space="$(echo "$line_gprof" | sed 's/^[[:space:]]*//')"
+        # e.g. "47.74   3.07  ...
+        # let's cut by spaces
+        percentage="$(echo "$no_space" | awk '{print $1}')"
+    fi
+
+    # 3) Compute real_ns_per_call
+    #    real_ns_per_call = real_boot_time * (percentage/100) * 1e9 / times_called
+    # Check if the fields are not empty
+    if [[ -n "$real_boot_time" && -n "$percentage" && -n "$times_called" ]]; then
+        real_ns_per_call="$(awk -v rbt="$real_boot_time" -v pct="$percentage" -v calls="$times_called" '
+            BEGIN {
+                # real_boot_time * (percentage/100) * 1e9 / times
+                if (calls == 0) {
+                    print 0
+                } else {
+                    val = rbt * (pct/100.0) * 1e9 / calls
+                    printf("%.5f", val)
+                }
+            }')"
+    fi
+
+    # 4) Print in tab-delimited format
+    echo -e "${N}\t${real_boot_time}\t${times_called}\t${ns_per_call}\t${predict_sec}\t${scale_factor}\t${percentage}\t${real_ns_per_call}" >> "$OUTFILE"
+
+done
+
+echo "Data parsed and saved to $OUTFILE."

auto_test.sh

@@ -0,0 +1,27 @@
+#!/usr/bin/env bash
+
+# Create a directory to store logs (optional)
+mkdir -p logs
+
+for N in $(seq 1 32); do
+    echo "============================================="
+    echo "Starting experiment with SMP=$N"
+    echo "============================================="
+
+    # 2) Build and run checks with SMP=N, capturing emulator output
+    #    The 'tee' command copies output to the terminal AND a log file
+    echo "Building and running 'make check SMP=$N'..."
+    make check SMP=$N 2>&1 | tee "logs/emulator_SMP_${N}.log"
+
+    # 3) After the emulator run, record gprof output
+    #    We assume 'gprof ./semu' uses data from 'gmon.out'
+    echo "Running gprof for SMP=$N..."
+    gprof ./semu > "logs/gprof_SMP_${N}.log" 2>&1
+
+    echo "Done with SMP=$N. Logs saved:"
+    echo "  - logs/emulator_SMP_${N}.log"
+    echo "  - logs/gprof_SMP_${N}.log"
+    echo
+done
+
+echo "All experiments complete!"

mac_analyze.sh

@@ -0,0 +1,75 @@
+#!/usr/bin/env bash
+#
+# parse_results_macos.sh
+#
+# Parses log files of the form: emulator_SMP_{N}.log
+# Each log ends with lines like:
+#   [SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource
+#   [SEMU LOG]: ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001
+#
+# We output a table with columns:
+#   1) SMP
+#   2) real_boot_time
+#   3) times_called
+#   4) ns_per_call
+#   5) predict_sec
+#   6) scale_factor
+#
+# We do not parse total_clocksource_ns or percentage, as they do not appear in this log snippet.
+
+LOGDIR="mac_log"      # Directory containing emulator_SMP_{N}.log
+OUTFILE="results_summary.txt"
+
+# Print a header:
+echo -e "SMP\treal_boot_time\ttimes\t\tns_per_call\tpredict_sec\tscale_factor" > "$OUTFILE"
+
+# Iterate from SMP=1..32 (adjust if needed)
+for N in $(seq 1 32); do
+    FILE="$LOGDIR/emulator_SMP_${N}.log"
+
+    if [[ ! -f "$FILE" ]]; then
+        echo "Skipping N=$N, file not found: $FILE"
+        continue
+    fi
+
+    # Initialize variables
+    real_boot_time=""
+    times_called=""
+    ns_per_call=""
+    predict_sec=""
+    scale_factor=""
+
+    # 1) Parse the "Real boot time" line:
+    # Example:
+    #   [SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource
+    line_boot="$(grep 'Real boot time:' "$FILE")"
+    if [[ -n "$line_boot" ]]; then
+        # Remove ANSI color codes, if any
+        line_no_ansi="$(echo "$line_boot" | sed 's/\x1b\[[0-9;]*m//g')"
+        # e.g. "[SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource"
+        # We'll extract:
+        #   real_boot_time = 43.63820
+        #   times = 220128512
+        real_boot_time="$(echo "$line_no_ansi" | sed -E 's/.*Real boot time: ([0-9.]+) seconds, called ([0-9]+) .*/\1/')"
+        times_called="$(echo "$line_no_ansi"    | sed -E 's/.*Real boot time: ([0-9.]+) seconds, called ([0-9]+) .*/\2/')"
+    fi
+
+    # 2) Parse the "ns_per_call" line:
+    # Example:
+    #   [SEMU LOG]: ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001
+    line_ns="$(grep 'ns_per_call =' "$FILE")"
+    if [[ -n "$line_ns" ]]; then
+        # Also remove ANSI codes
+        ns_no_ansi="$(echo "$line_ns" | sed 's/\x1b\[[0-9;]*m//g')"
+        # e.g. "ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001"
+        # We'll extract them
+        ns_per_call="$(echo "$ns_no_ansi"  | sed -E 's/.*ns_per_call = ([0-9.]+).*/\1/')"
+        predict_sec="$(echo "$ns_no_ansi"  | sed -E 's/.*predict_sec = ([0-9.]+).*/\1/')"
+        scale_factor="$(echo "$ns_no_ansi" | sed -E 's/.*scale_factor = ([0-9.]+).*/\1/')"
+    fi
+
+    # 3) Print a line with the data
+    echo -e "${N}\t${real_boot_time}\t${times_called}\t${ns_per_call}\t${predict_sec}\t${scale_factor}" >> "$OUTFILE"
+done
+
+echo "Done. Results saved to ${OUTFILE}."

main.c

@@ -677,7 +677,17 @@ static int semu_start(int argc, char **argv)
     return 0;
 }
 
+#include <time.h>
+#ifdef CLOCK_MONOTONIC_COARSE
+#define CLOCKID CLOCK_MONOTONIC_COARSE
+#else
+#define CLOCKID CLOCK_REALTIME_COARSE
+#endif
+
+extern struct timespec boot_begin;
+
 int main(int argc, char **argv)
 {
+    clock_gettime(CLOCK_REALTIME, &boot_begin);
     return semu_start(argc, argv);
 }

statistic/README

@@ -0,0 +1,5 @@
+1: 13th Gen Intel(R) Core(TM) i7-13700
+2: Intel(R) Xeon(R) CPU E5-2640 v4 @ 2.40GHz
+3: Intel(R) Core(TM) i7-1065G7 CPU @ 1.30GHz
+4: arm (ThunderX2-99xx)
+5: mag