WIP: profile on macos

sysprog21 · Jan 26, 2025 · fbf1f0c · fbf1f0c
1 parent 1f9c6a8
commit fbf1f0c
Show file tree

Hide file tree

Showing 57 changed files with 3,587 additions and 6 deletions.
diff --git a/Makefile b/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
@@ -99,6 +101,7 @@ ext4.img:
 
 check: $(BIN) minimal.dtb $(KERNEL_DATA) $(INITRD_DATA) $(DISKIMG_FILE)
 	@$(call notice, Ready to launch Linux kernel. Please be patient.)
+	@echo $(Q)./$(BIN) -k $(KERNEL_DATA) -c $(SMP) -b minimal.dtb -i $(INITRD_DATA) -n $(NETDEV) $(OPTS)
 	$(Q)./$(BIN) -k $(KERNEL_DATA) -c $(SMP) -b minimal.dtb -i $(INITRD_DATA) -n $(NETDEV) $(OPTS)
 
 build-image:

diff --git a/analyze.sh b/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."
diff --git a/auto_test.sh b/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!"
diff --git a/gmon.out b/gmon.out
diff --git a/mac_analyze.sh 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/mac_log/emulator_SMP_1.log b/mac_log/emulator_SMP_1.log
@@ -0,0 +1,95 @@
+  CC	riscv.o
+  CC	ram.o
+  CC	utils.o
+  CC	plic.o
+  CC	uart.o
+  CC	main.o
+  CC	aclint.o
+  CC	virtio-blk.o
+  LD	semu
+ DTC	minimal.dtb
+[32;01mReady to launch Linux kernel. Please be patient.[0m
+@./semu -k Image -c 1 -b minimal.dtb -i rootfs.cpio -n tap -d ext4.img
+[    0.000000] Linux version 6.1.99 (jserv@node1) (riscv32-buildroot-linux-gnu-gcc.br_real (Buildroot 2024.02.4) 12.3.0, GNU ld (GNU Binutils) 2.41) #1 SMP Thu Jul 18 13:04:10 CST 2024
+[    0.000000] Machine model: semu
+[    0.000000] earlycon: ns16550 at MMIO 0xf4000000 (options '')
+[    0.000000] printk: bootconsole [ns16550] enabled
+[    0.000000] Zone ranges:
+[    0.000000]   Normal   [mem 0x0000000000000000-0x000000001fffffff]
+[    0.000000] Movable zone start for each node
+[    0.000000] Early memory node ranges
+[    0.000000]   node   0: [mem 0x0000000000000000-0x000000001fffffff]
+[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000001fffffff]
+[    0.000000] SBI specification v2.0 detected
+[    0.000000] SBI implementation ID=0x999 Version=0x1
+[    0.000000] SBI TIME extension detected
+[    0.000000] SBI IPI extension detected
+[    0.000000] SBI RFENCE extension detected
+[    0.000000] SBI SRST extension detected
+[    0.000000] SBI HSM extension detected
+[    0.000000] riscv: base ISA extensions aim
+[    0.000000] riscv: ELF capabilities aim
+[    0.000000] percpu: Embedded 10 pages/cpu s11604 r8192 d21164 u40960
+[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 130048
+[    0.000000] Kernel command line: earlycon console=ttyS0
+[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
+[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes, linear)
+[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
+[    0.000000] Memory: 506428K/524288K available (3578K kernel code, 345K rwdata, 873K rodata, 185K init, 140K bss, 17860K reserved, 0K cma-reserved)
+[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
+[    0.000000] rcu: Hierarchical RCU implementation.
+[    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=32 to nr_cpu_ids=1.
+[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
+[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
+[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
+[    0.000000] riscv-intc: 32 local interrupts mapped
+[    0.000000] plic: interrupt-controller@0: mapped 31 interrupts with 1 handlers for 1 contexts.
+[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
+[    0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [0]
+[    0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0xefdb196da, max_idle_ns: 440795204367 ns
+[    0.000000] sched_clock: 64 bits at 65MHz, resolution 15ns, wraps every 2199023255550ns
+[    0.000017] Console: colour dummy device 80x25
+[    0.000022] Calibrating delay loop (skipped), value calculated using timer frequency.. 130.00 BogoMIPS (lpj=260000)
+[    0.000027] pid_max: default: 32768 minimum: 301
+[    0.000043] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
+[    0.000048] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
+[    0.000154] ASID allocator disabled (0 bits)
+[    0.000164] rcu: Hierarchical SRCU implementation.
+[    0.000167] rcu: 	Max phase no-delay instances is 1000.
+[    0.000191] smp: Bringing up secondary CPUs ...
+[    0.000193] smp: Brought up 1 node, 1 CPU
+[    0.000225] devtmpfs: initialized
+[    0.000323] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
+[    0.000328] futex hash table entries: 256 (order: 2, 16384 bytes, linear)
+[    0.000442] NET: Registered PF_NETLINK/PF_ROUTE protocol family
+[    0.000527] platform soc@F0000000: Fixed dependency cycle(s) with /soc@F0000000/interrupt-controller@0
+[    0.001222] clocksource: Switched to clocksource riscv_clocksource
+[    0.002111] NET: Registered PF_INET protocol family
+[    0.002139] IP idents hash table entries: 8192 (order: 4, 65536 bytes, linear)
+[    0.002417] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
+[    0.002423] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
+[    0.002427] TCP established hash table entries: 4096 (order: 2, 16384 bytes, linear)
+[    0.002439] TCP bind hash table entries: 4096 (order: 4, 65536 bytes, linear)
+[    0.002456] TCP: Hash tables configured (established 4096 bind 4096)
+[    0.002464] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)
+[    0.002469] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)
+[    0.002485] NET: Registered PF_UNIX/PF_LOCAL protocol family
+[    0.002559] Unpacking initramfs...
+[    0.032861] Freeing initrd memory: 8188K
+[    0.032883] workingset: timestamp_bits=30 max_order=17 bucket_order=0
+[    0.038732] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
+[    0.038862] printk: console [ttyS0] disabled
+[    0.038867] f4000000.serial: ttyS0 at MMIO 0xf4000000 (irq = 1, base_baud = 312500) is a 16550
+[    0.038873] printk: console [ttyS0] enabled
+[    0.038873] printk: console [ttyS0] enabled
+[    0.038878] printk: bootconsole [ns16550] disabled
+[    0.038878] printk: bootconsole [ns16550] disabled
+[    0.038916] virtio_blk virtio0: 1/0/0 default/read/poll queues
+[    0.038959] virtio_blk virtio0: [vda] 4800 512-byte logical blocks (2.46 MB/2.34 MiB)
+[    0.039098] clk: Disabling unused clocks
+[    0.039148] Freeing unused kernel image (initmem) memory: 180K
+[    0.039152] Kernel memory protection not selected by kernel config.
+[    0.039157] Run /init as init process
+[1;31m[SEMU LOG]: Use mach_absolute_time[0m
+[1;31m[SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource[0m
+[1;31m[SEMU LOG]: ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001[0m