diff --git a/.gitignore b/.gitignore index b56a9aa8..f1d4d5d3 100644 --- a/.gitignore +++ b/.gitignore @@ -11,3 +11,8 @@ rootfs.cpio # intermediate riscv-harts.dtsi + +# testing +statistic +test.* +utils_bak.c \ No newline at end of file diff --git a/Makefile b/Makefile index 24980d4c..e0f088cc 100644 --- a/Makefile +++ b/Makefile @@ -1,7 +1,7 @@ include mk/common.mk CC ?= gcc -CFLAGS := -O2 -g -Wall -Wextra +CFLAGS := -O2 -g -Wall -Wextra -pg CFLAGS += -include common.h # clock frequency @@ -78,6 +78,7 @@ E := S := $E $E SMP ?= 1 +CFLAGS += -D SEMU_BOOT_TARGET_TIME=10 .PHONY: riscv-harts.dtsi riscv-harts.dtsi: $(Q)python3 scripts/gen-hart-dts.py $@ $(SMP) $(CLOCK_FREQ) diff --git a/auto_test.sh b/auto_test.sh new file mode 100755 index 00000000..c84a45ac --- /dev/null +++ b/auto_test.sh @@ -0,0 +1,19 @@ +#!/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 "=============================================" + + echo "Building and running 'make check SMP=$N'..." + make check SMP=$N 2>&1 | tee "logs/emulator_SMP_${N}.log" + + echo "Done with SMP=$N. Logs saved:" + echo " - logs/emulator_SMP_${N}.log" + echo +done + +echo "All experiments complete!" diff --git a/mac_analyze.sh b/mac_analyze.sh new file mode 100644 index 00000000..b5fe2874 --- /dev/null +++ b/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}." diff --git a/main.c b/main.c index c6e81cb9..e1866d95 100644 --- a/main.c +++ b/main.c @@ -619,7 +619,7 @@ static int semu_start(int argc, char **argv) emu.disk = virtio_blk_init(&(emu.vblk), disk_file); #endif /* Set up ACLINT */ - semu_timer_init(&emu.mtimer.mtime, CLOCK_FREQ); + semu_timer_init(&emu.mtimer.mtime, CLOCK_FREQ, hart_count); emu.mtimer.mtimecmp = calloc(vm.n_hart, sizeof(uint64_t)); emu.mswi.msip = calloc(vm.n_hart, sizeof(uint32_t)); emu.sswi.ssip = calloc(vm.n_hart, sizeof(uint32_t)); @@ -677,7 +677,17 @@ static int semu_start(int argc, char **argv) return 0; } +#include +#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); } diff --git a/riscv.c b/riscv.c index c3fd394a..bd92f1f0 100644 --- a/riscv.c +++ b/riscv.c @@ -382,6 +382,14 @@ static void op_sret(hart_t *vm) vm->s_mode = vm->sstatus_spp; vm->sstatus_sie = vm->sstatus_spie; + /* After the booting process is complete, initrd will be loaded. At this + * point, the sytstem will switch to U mode for the first time. Therefore, + * by checking whether the switch to U mode has already occurred, we can + * determine if the boot process has been completed. + */ + if (!boot_complete && !vm->s_mode) + boot_complete = true; + /* Reset stack */ vm->sstatus_spp = false; vm->sstatus_spie = true; diff --git a/statistic/README b/statistic/README new file mode 100644 index 00000000..a729aa26 --- /dev/null +++ b/statistic/README @@ -0,0 +1,7 @@ +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: 13th Gen Intel(R) Core(TM) i9-13900H +5: arm (ThunderX2-99xx) +6: mag +7: M2 Pro Max diff --git a/statistic/analyze_results.sh b/statistic/analyze_results.sh new file mode 100755 index 00000000..f4e28a60 --- /dev/null +++ b/statistic/analyze_results.sh @@ -0,0 +1,101 @@ +#!/usr/bin/env bash +# +# parse_results_new.sh +# +# Parses new logs named "emulator_SMP_{N}.log" (N=1..32). Each log's final lines look like: +# +# [SEMU LOG]: Real boot time: 233.04606 seconds, called 3628365913 times semu_timer_clocksource +# [SEMU LOG]: ns_per_call = 6.26153, predict_sec = 225.41525, scale_factor = 0.04436 +# [SEMU LOG]: test_total_clocksource_ns = 92301869299, real_total_clocksource_ns = 46863590994, percentage = 0.20109 +# [SEMU LOG]: real_ns_per_call = 12.91589, diff_ns_per_call = 6.65436 +# +# We output results_summary.txt with 11 columns in tab-delimited format: +# 1) SMP +# 2) real_boot_time +# 3) times_called +# 4) ns_per_call +# 5) predict_sec +# 6) scale_factor +# 7) total_clocksource_ns +# 8) percentage +# 9) real_ns_per_call +# 10) diff_ns_per_call +# +# We specifically remove any ANSI color codes and ensure each line is a single line, so the output doesn't break. + +for TAG in $(seq 1 7); do + BASEDIR="profile-2" + LOGDIR="logs-${TAG}" # Directory containing the log files + OUTFILE="$BASEDIR/results_summary-${TAG}.txt" + + # Print header (11 columns) + echo -e "SMP real_boot_time times_called ns_per_call predict_sec scale_factor total_clocksource_ns percentage real_ns_per_call diff_ns_per_call" > "$OUTFILE" + + for N in $(seq 1 32); do + FILE="$BASEDIR/$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="" + total_clocksource_ns="" + percentage="" + real_ns_per_call="" + diff_ns_per_call="" + + # A helper function to grep for a specific pattern once, strip ANSI codes, unify line + grep_single_line() { + # Usage: grep_single_line "" + # We'll grep for this pattern, take only the first match, remove color codes, unify line + grep -m1 "$1" "$FILE" \ + | sed 's/\x1b\[[0-9;]*m//g' \ + | tr '\n' ' ' + } + + # 1) Real boot time line + # e.g. "[SEMU LOG]: Real boot time: 233.04606 seconds, called 3628365913 times semu_timer_clocksource" + line_boot="$(grep_single_line 'Real boot time:')" + if [[ -n "$line_boot" ]]; then + # extract real_boot_time, times_called + real_boot_time="$(echo "$line_boot" | sed -E 's/.*Real boot time: (-?[0-9.]+) seconds, called ([0-9]+) .*/\1/')" + times_called="$(echo "$line_boot" | sed -E 's/.*Real boot time: (-?[0-9.]+) seconds, called ([0-9]+) .*/\2/')" + fi + + # 2) ns_per_call line + # e.g.: "[SEMU LOG]: ns_per_call = 6.26153, predict_sec = 225.41525, scale_factor = 0.04436" + line_nscall="$(grep_single_line 'ns_per_call =')" + if [[ -n "$line_nscall" ]]; then + ns_per_call="$(echo "$line_nscall" | sed -E 's/.*ns_per_call = (-?[0-9.]+).*/\1/')" + predict_sec="$(echo "$line_nscall" | sed -E 's/.*predict_sec = (-?[0-9.]+).*/\1/')" + scale_factor="$(echo "$line_nscall" | sed -E 's/.*scale_factor = (-?[0-9.]+).*/\1/')" + fi + + # 3) total_clocksource_ns line + # e.g. "[SEMU LOG]: test_total_clocksource_ns = 92301869299, real_total_clocksource_ns = 46863590994, percentage = 0.20109" + line_totals="$(grep_single_line 'total_clocksource_ns =')" + if [[ -n "$line_totals" ]]; then + total_clocksource_ns="$(echo "$line_totals" | sed -E 's/.*total_clocksource_ns = ([0-9]+).*/\1/')" + percentage="$(echo "$line_totals" | sed -E 's/.*percentage = (-?[0-9.]+).*/\1/')" + fi + + # 4) real_ns_per_call line + # e.g. "[SEMU LOG]: real_ns_per_call = 12.91589, diff_ns_per_call = 6.65436" + line_realns="$(grep_single_line 'real_ns_per_call =')" + if [[ -n "$line_realns" ]]; then + real_ns_per_call="$(echo "$line_realns" | sed -E 's/.*real_ns_per_call = (-?[0-9.]+).*/\1/')" + diff_ns_per_call="$(echo "$line_realns" | sed -E 's/.*diff_ns_per_call = (-?[0-9.]+).*/\1/')" + fi + + # Print a single line with 11 columns in tab-delimited format + echo -e "${N} ${real_boot_time} ${times_called} ${ns_per_call} ${predict_sec} ${scale_factor} ${total_clocksource_ns} ${percentage} ${real_ns_per_call} ${diff_ns_per_call}" >> "$OUTFILE" + done +done + +echo "Data parsed and saved to $OUTFILE." diff --git a/statistic/draw.sh b/statistic/draw.sh new file mode 100755 index 00000000..ff67ad80 --- /dev/null +++ b/statistic/draw.sh @@ -0,0 +1,81 @@ +#!/usr/bin/env bash +# +# plot_results.sh +# +# Generates 7 separate .png plots using gnuplot. Each plot corresponds +# to a particular data column (2..8) from the results_summary_{1..5}.txt files. +# The x-axis is SMP (column 1), and the y-axis is the chosen data column. +# +# The files are assumed to be: +# results_summary_1.txt +# results_summary_2.txt +# results_summary_3.txt +# results_summary_4.txt +# results_summary_5.txt +# +# Each file has at least these columns: +# 1) SMP +# 2) real_boot_time +# 3) times +# 4) ns_per_call +# 5) predict_sec +# 6) scale_factor +# 7) percentage +# 8) real_ns_per_call +# +# Usage: +# ./plot_results.sh +# It will produce 7 PNG images, e.g. real_boot_time.png, times.png, etc. + +# A small map from column index to a more descriptive name (for file titles). +declare -A COLTITLE=( + [2]="real_boot_time" + [3]="times" + [4]="ns_per_call" + [5]="predict_sec" + [6]="scale_factor" + [7]="percentage" + [8]="real_ns_per_call" +) + +# Check if gnuplot is installed +command -v gnuplot >/dev/null 2>&1 || { + echo "Error: gnuplot is not installed or not in PATH." + exit 1 +} + +# Loop over the data columns we want to plot +for col in 2 3 4 5 6 7 8; do + title="${COLTITLE[$col]}" + + echo "Generating plot for column $col -> $title" + + gnuplot -persist < - #include "utils.h" +#include +#include +#include #if defined(__APPLE__) #define HAVE_MACH_TIMER @@ -19,6 +20,14 @@ #endif #endif +bool boot_complete = false; +static double ticks_increment; +static double boot_ticks; + +/* for testing */ +uint64_t count = 0; +struct timespec boot_begin, boot_end; + /* Calculate "x * n / d" without unnecessary overflow or loss of precision. * * Reference: @@ -32,35 +41,122 @@ static inline uint64_t mult_frac(uint64_t x, uint64_t n, uint64_t d) return q * n + r * n / d; } -void semu_timer_init(semu_timer_t *timer, uint64_t freq) +/* High-precision time measurement: + * - POSIX systems: clock_gettime() for nanosecond precision + * - macOS: mach_absolute_time() with timebase conversion + * - Other platforms: time(0) with conversion to nanoseconds as fallback + * + * The platform-specific timing logic is now clearly separated: POSIX and macOS + * implementations provide high-precision measurements, while the fallback path + * uses time(0) for a coarser but portable approach. + */ +static inline uint64_t host_time_ns() { - timer->freq = freq; - semu_timer_rebase(timer, 0); +#if defined(HAVE_POSIX_TIMER) + struct timespec ts; + clock_gettime(CLOCKID, &ts); + return (uint64_t) ts.tv_sec * 1e9 + (uint64_t) ts.tv_nsec; + +#elif defined(HAVE_MACH_TIMER) + static mach_timebase_info_data_t ts = {0}; + if (ts.denom == 0) + (void) mach_timebase_info(&ts); + + uint64_t now = mach_absolute_time(); + /* convert to nanoseconds: (now * t.numer / t.denom) */ + return mult_frac(now, ts.numer, (uint64_t) ts.denom); + +#else + /* Fallback to non-HRT calls time(0) in seconds => convert to ns. */ + time_t now_sec = time(0); + return (uint64_t) now_sec * 1e9; +#endif +} + +/* The function that returns the "emulated time" in ticks. + * + * Before the boot completes, we scale time by 'scale_factor' for a "fake + * increments" approach. After boot completes, we switch to real time + * with an offset bridging so that there's no big jump. + */ +static uint64_t semu_timer_clocksource(semu_timer_t *timer) +{ + /* After boot process complete, the timer will switch to real time. Thus, + * there is an offset between the real time and the emulator time. + * + * After switching to real time, the correct way to update time is to + * calculate the increment of time. Then add it to the emulator time. + */ + static int64_t offset = 0; + static bool first_switch = true; + + if (!boot_complete) { + ++count; /* FOR TESTING */ + boot_ticks += ticks_increment; + return (uint64_t) boot_ticks; + } + + uint64_t now_ns = host_time_ns(); + uint64_t real_ticks = mult_frac(now_ns, timer->freq, 1e9); + + /* The boot is done => switch to real freq with an offset bridging. */ + if (first_switch) { + first_switch = false; + offset = (int64_t) (real_ticks - boot_ticks); + + /* FOR TESTING */ + clock_gettime(CLOCK_REALTIME, &boot_end); + + printf( + "\033[1;31m[SEMU LOG]: Boot complete, switch to real-time " + "timer\033[0m\n"); + + double boot_time = (boot_end.tv_sec - boot_begin.tv_sec) + + (boot_end.tv_nsec - boot_begin.tv_nsec) / 1.0e9; + + printf( + "\033[1;31m[SEMU LOG]: Boot time: %.5f seconds, called %ld " + "times semu_timer_clocksource\033[0m\n", + boot_time, count); + + printf( + "\033[1;31m[SEMU LOG]: timer->begin: %lu, " + "real_ticks: %lu, boot_ticks: %lu, offset: %ld\033[0m\n", + timer->begin, real_ticks, (uint64_t) boot_ticks, offset); + + exit(0); + } + return (uint64_t) ((int64_t) real_ticks - offset); } -static uint64_t semu_timer_clocksource(uint64_t freq) +void semu_timer_init(semu_timer_t *timer, uint64_t freq, int n_harts) { #if defined(HAVE_POSIX_TIMER) - struct timespec t; - clock_gettime(CLOCKID, &t); - return t.tv_sec * freq + mult_frac(t.tv_nsec, freq, 1e9); + printf("\033[1;31m[SEMU LOG]: Use clock_gettime\033[0m\n"); #elif defined(HAVE_MACH_TIMER) - static mach_timebase_info_data_t t; - if (t.denom == 0) - (void) mach_timebase_info(&t); - return mult_frac(mult_frac(mach_absolute_time(), t.numer, t.denom), freq, - 1e9); + printf("\033[1;31m[SEMU LOG]: Use mach_absolute_time\033[0m\n"); #else - return time(0) * freq; + printf("\033[1;31m[SEMU LOG]: Use time\033[0m\n"); #endif + + /* Measure how long each call to 'host_time_ns()' roughly takes, + * then use that to pick 'scale_factor'. For example, pass freq + * as the loop count or some large number to get a stable measure. + */ + // measure_bogomips_ns(freq, n_harts); + timer->freq = freq; + + timer->begin = mult_frac(host_time_ns(), timer->freq, 1e9); + boot_ticks = timer->begin; + ticks_increment = (SEMU_BOOT_TARGET_TIME * CLOCK_FREQ) / (2.0e8 * n_harts); } uint64_t semu_timer_get(semu_timer_t *timer) { - return semu_timer_clocksource(timer->freq) - timer->begin; + return semu_timer_clocksource(timer) - timer->begin; } void semu_timer_rebase(semu_timer_t *timer, uint64_t time) { - timer->begin = semu_timer_clocksource(timer->freq) - time; + timer->begin = semu_timer_clocksource(timer) - time; } diff --git a/utils.h b/utils.h index 6e03ea0f..6c49715d 100644 --- a/utils.h +++ b/utils.h @@ -1,13 +1,24 @@ #pragma once +#include #include +/* To suppress RCU CPU stall warnings, the emulator provides a scaled time to + * the Guest OS during the boot process. After the boot process is complete, the + * scaling is disabled to achieve a real-time timer. + * + * Since the Guest OS transitions to U mode for the first time when it loads the + * initial user-mode process, we use this transition to determine whether the + * boot process has completed. + */ +extern bool boot_complete; + /* TIMER */ typedef struct { uint64_t begin; uint64_t freq; } semu_timer_t; -void semu_timer_init(semu_timer_t *timer, uint64_t freq); +void semu_timer_init(semu_timer_t *timer, uint64_t freq, int n_harts); uint64_t semu_timer_get(semu_timer_t *timer); void semu_timer_rebase(semu_timer_t *timer, uint64_t time); \ No newline at end of file