Skip to content

Commit fbf1f0c

Browse files
Mes0903Mes0903
committed
WIP: profile on macos
1 parent 1f9c6a8 commit fbf1f0c

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

57 files changed

+3587
-6
lines changed

‎Makefile

+3
Original file line numberDiff line numberDiff line change
@@ -77,6 +77,8 @@ DTC ?= dtc
7777
E :=
7878
S := $E $E
7979

80+
LDFLAGS := -pg
81+
8082
SMP ?= 1
8183
CFLAGS += -D SEMU_BOOT_TARGET_TIME=10
8284
.PHONY: riscv-harts.dtsi
@@ -99,6 +101,7 @@ ext4.img:
99101

100102
check: $(BIN) minimal.dtb $(KERNEL_DATA) $(INITRD_DATA) $(DISKIMG_FILE)
101103
@$(call notice, Ready to launch Linux kernel. Please be patient.)
104+
@echo $(Q)./$(BIN) -k $(KERNEL_DATA) -c $(SMP) -b minimal.dtb -i $(INITRD_DATA) -n $(NETDEV) $(OPTS)
102105
$(Q)./$(BIN) -k $(KERNEL_DATA) -c $(SMP) -b minimal.dtb -i $(INITRD_DATA) -n $(NETDEV) $(OPTS)
103106

104107
build-image:

‎analyze.sh

+124
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,124 @@
1+
#!/usr/bin/env bash
2+
#
3+
# parse_results.sh:
4+
# Parse "emulator_SMP_{N}.log" and "gprof_SMP_{N}.log" for each N=1..32
5+
# to extract:
6+
# - predict_sec
7+
# - real_boot_time
8+
# - times (calls)
9+
# - semu_timer_clocksource percentage
10+
# - ns_per_call
11+
# - real_ns_per_call (calculated)
12+
# - scale_factor
13+
#
14+
# Output a summary line for each SMP=N in tab-delimited format.
15+
16+
LOGDIR="logs" # or wherever your logs are
17+
OUTFILE="results_summary.txt"
18+
19+
echo -e "SMP\treal_boot_time\ttimes\t\tns_per_call\tpredict_sec\tscale_factor\tpercentage\treal_ns_per_call" > "$OUTFILE"
20+
21+
for N in $(seq 1 32); do
22+
EMU_LOG="$LOGDIR/emulator_SMP_${N}.log"
23+
GPROF_LOG="$LOGDIR/gprof_SMP_${N}.log"
24+
25+
# Check that the files exist
26+
if [[ ! -f "$EMU_LOG" ]]; then
27+
echo "Warning: $EMU_LOG not found, skipping"
28+
continue
29+
fi
30+
if [[ ! -f "$GPROF_LOG" ]]; then
31+
echo "Warning: $GPROF_LOG not found, skipping"
32+
continue
33+
fi
34+
35+
# Initialize variables we want to parse
36+
predict_sec=""
37+
real_boot_time=""
38+
times_called=""
39+
ns_per_call=""
40+
scale_factor=""
41+
percentage=""
42+
real_ns_per_call=""
43+
44+
# 1) Parse from emulator_SMP_{N}.log:
45+
# We look for lines:
46+
# "[SEMU LOG]: Boot time: 7.82979 seconds, called 233068043 times semu_timer_clocksource"
47+
# next line: "ns_per_call = 5.10756, predict_sec = 10.21511, scale_factor = 0.97894"
48+
# We can do it with grep + sed or awk or a while-read approach
49+
50+
# Extract the "Boot time" line
51+
# e.g. "Boot time: 7.82979 seconds, called 233068043 times semu_timer_clocksource"
52+
# We'll parse the "7.82979" as real_boot_time, "233068043" as times_called
53+
line_boot_time="$(grep -Eo '\[SEMU LOG\]: Boot time: [^,]*, called [^ ]* times semu_timerclocksource.*' "$EMU_LOG")"
54+
# Alternatively you might want a simpler approach:
55+
# Let's do a grep for "Boot time:" and read the line with everything
56+
if [[ -z "$line_boot_time" ]]; then
57+
# Possibly there's an ANSI color code. Let's remove them with sed
58+
line_boot_time="$(grep 'Boot time:' "$EMU_LOG" | sed 's/\x1b\[[0-9;]*m//g')"
59+
fi
60+
61+
# Now parse it. Example format:
62+
# Boot time: 7.82979 seconds, called 233068043 times semu_timer_clocksource
63+
# We can use sed or awk:
64+
if [[ -n "$line_boot_time" ]]; then
65+
# Remove ANSI codes again if needed:
66+
no_ansi="$(echo "$line_boot_time" | sed 's/\x1b\[[0-9;]*m//g')"
67+
# Extract e.g. 7.82979 and 233068043
68+
real_boot_time="$(echo "$no_ansi" | sed -E 's/.*Boot time: ([0-9.]+) seconds, called ([0-9]+) times.*/\1/')"
69+
times_called="$(echo "$no_ansi" | sed -E 's/.*Boot time: ([0-9.]+) seconds, called ([0-9]+) times.*/\2/')"
70+
fi
71+
72+
# Next line with "ns_per_call = 5.10756, predict_sec = 10.21511, scale_factor = 0.97894"
73+
# We'll grep and parse similarly
74+
line_ns_call="$(grep -Eo 'ns_per_call = [^,]*, predict_sec = [^,]*, scale_factor = [^ ]*' "$EMU_LOG" | sed 's/\x1b\[[0-9;]*m//g')"
75+
if [[ -n "$line_ns_call" ]]; then
76+
# Example: "ns_per_call = 5.10756, predict_sec = 10.21511, scale_factor = 0.97894"
77+
ns_per_call="$(echo "$line_ns_call" | sed -E 's/.*ns_per_call = ([0-9.]+), predict_sec = ([0-9.]+), scale_factor = ([0-9.]+)/\1/')"
78+
predict_sec="$(echo "$line_ns_call" | sed -E 's/.*ns_per_call = ([0-9.]+), predict_sec = ([0-9.]+), scale_factor = ([0-9.]+)/\2/')"
79+
scale_factor="$(echo "$line_ns_call" | sed -E 's/.*ns_per_call = ([0-9.]+), predict_sec = ([0-9.]+), scale_factor = ([0-9.]+)/\3/')"
80+
fi
81+
82+
# 2) From gprof_SMP_{N}.log:
83+
# We search for the line that includes "semu_timer_clocksource" in the "Flat profile:" section
84+
# Example: "47.74 3.07 3.07 ... semu_timer_clocksource"
85+
# We'll parse the first field as the percentage
86+
# We'll do something like:
87+
line_gprof="$(grep -E '[0-9]+\.[0-9]+[[:space:]]+[0-9]+\.[0-9]+[[:space:]]+[0-9]+\.[0-9]+.*semu_timer_clocksource' "$GPROF_LOG")"
88+
# fallback if the spacing is different, or just search for 'semu_timer_clocksource'
89+
if [[ -z "$line_gprof" ]]; then
90+
line_gprof="$(grep 'semu_timer_clocksource' "$GPROF_LOG")"
91+
fi
92+
93+
# e.g.: " 47.74 3.07 3.07 semu_timer_clocksource"
94+
# The first column is 47.74. We'll parse that:
95+
if [[ -n "$line_gprof" ]]; then
96+
# remove leading spaces
97+
no_space="$(echo "$line_gprof" | sed 's/^[[:space:]]*//')"
98+
# e.g. "47.74 3.07 ...
99+
# let's cut by spaces
100+
percentage="$(echo "$no_space" | awk '{print $1}')"
101+
fi
102+
103+
# 3) Compute real_ns_per_call
104+
# real_ns_per_call = real_boot_time * (percentage/100) * 1e9 / times_called
105+
# Check if the fields are not empty
106+
if [[ -n "$real_boot_time" && -n "$percentage" && -n "$times_called" ]]; then
107+
real_ns_per_call="$(awk -v rbt="$real_boot_time" -v pct="$percentage" -v calls="$times_called" '
108+
BEGIN {
109+
# real_boot_time * (percentage/100) * 1e9 / times
110+
if (calls == 0) {
111+
print 0
112+
} else {
113+
val = rbt * (pct/100.0) * 1e9 / calls
114+
printf("%.5f", val)
115+
}
116+
}')"
117+
fi
118+
119+
# 4) Print in tab-delimited format
120+
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"
121+
122+
done
123+
124+
echo "Data parsed and saved to $OUTFILE."

‎auto_test.sh

+27
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
#!/usr/bin/env bash
2+
3+
# Create a directory to store logs (optional)
4+
mkdir -p logs
5+
6+
for N in $(seq 1 32); do
7+
echo "============================================="
8+
echo "Starting experiment with SMP=$N"
9+
echo "============================================="
10+
11+
# 2) Build and run checks with SMP=N, capturing emulator output
12+
# The 'tee' command copies output to the terminal AND a log file
13+
echo "Building and running 'make check SMP=$N'..."
14+
make check SMP=$N 2>&1 | tee "logs/emulator_SMP_${N}.log"
15+
16+
# 3) After the emulator run, record gprof output
17+
# We assume 'gprof ./semu' uses data from 'gmon.out'
18+
echo "Running gprof for SMP=$N..."
19+
gprof ./semu > "logs/gprof_SMP_${N}.log" 2>&1
20+
21+
echo "Done with SMP=$N. Logs saved:"
22+
echo " - logs/emulator_SMP_${N}.log"
23+
echo " - logs/gprof_SMP_${N}.log"
24+
echo
25+
done
26+
27+
echo "All experiments complete!"

‎gmon.out

15.5 KB
Binary file not shown.

‎mac_analyze.sh

+75
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,75 @@
1+
#!/usr/bin/env bash
2+
#
3+
# parse_results_macos.sh
4+
#
5+
# Parses log files of the form: emulator_SMP_{N}.log
6+
# Each log ends with lines like:
7+
# [SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource
8+
# [SEMU LOG]: ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001
9+
#
10+
# We output a table with columns:
11+
# 1) SMP
12+
# 2) real_boot_time
13+
# 3) times_called
14+
# 4) ns_per_call
15+
# 5) predict_sec
16+
# 6) scale_factor
17+
#
18+
# We do not parse total_clocksource_ns or percentage, as they do not appear in this log snippet.
19+
20+
LOGDIR="mac_log" # Directory containing emulator_SMP_{N}.log
21+
OUTFILE="results_summary.txt"
22+
23+
# Print a header:
24+
echo -e "SMP\treal_boot_time\ttimes\t\tns_per_call\tpredict_sec\tscale_factor" > "$OUTFILE"
25+
26+
# Iterate from SMP=1..32 (adjust if needed)
27+
for N in $(seq 1 32); do
28+
FILE="$LOGDIR/emulator_SMP_${N}.log"
29+
30+
if [[ ! -f "$FILE" ]]; then
31+
echo "Skipping N=$N, file not found: $FILE"
32+
continue
33+
fi
34+
35+
# Initialize variables
36+
real_boot_time=""
37+
times_called=""
38+
ns_per_call=""
39+
predict_sec=""
40+
scale_factor=""
41+
42+
# 1) Parse the "Real boot time" line:
43+
# Example:
44+
# [SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource
45+
line_boot="$(grep 'Real boot time:' "$FILE")"
46+
if [[ -n "$line_boot" ]]; then
47+
# Remove ANSI color codes, if any
48+
line_no_ansi="$(echo "$line_boot" | sed 's/\x1b\[[0-9;]*m//g')"
49+
# e.g. "[SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource"
50+
# We'll extract:
51+
# real_boot_time = 43.63820
52+
# times = 220128512
53+
real_boot_time="$(echo "$line_no_ansi" | sed -E 's/.*Real boot time: ([0-9.]+) seconds, called ([0-9]+) .*/\1/')"
54+
times_called="$(echo "$line_no_ansi" | sed -E 's/.*Real boot time: ([0-9.]+) seconds, called ([0-9]+) .*/\2/')"
55+
fi
56+
57+
# 2) Parse the "ns_per_call" line:
58+
# Example:
59+
# [SEMU LOG]: ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001
60+
line_ns="$(grep 'ns_per_call =' "$FILE")"
61+
if [[ -n "$line_ns" ]]; then
62+
# Also remove ANSI codes
63+
ns_no_ansi="$(echo "$line_ns" | sed 's/\x1b\[[0-9;]*m//g')"
64+
# e.g. "ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001"
65+
# We'll extract them
66+
ns_per_call="$(echo "$ns_no_ansi" | sed -E 's/.*ns_per_call = ([0-9.]+).*/\1/')"
67+
predict_sec="$(echo "$ns_no_ansi" | sed -E 's/.*predict_sec = ([0-9.]+).*/\1/')"
68+
scale_factor="$(echo "$ns_no_ansi" | sed -E 's/.*scale_factor = ([0-9.]+).*/\1/')"
69+
fi
70+
71+
# 3) Print a line with the data
72+
echo -e "${N}\t${real_boot_time}\t${times_called}\t${ns_per_call}\t${predict_sec}\t${scale_factor}" >> "$OUTFILE"
73+
done
74+
75+
echo "Done. Results saved to ${OUTFILE}."

‎mac_log/emulator_SMP_1.log

+95
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,95 @@
1+
CC riscv.o
2+
CC ram.o
3+
CC utils.o
4+
CC plic.o
5+
CC uart.o
6+
CC main.o
7+
CC aclint.o
8+
CC virtio-blk.o
9+
LD semu
10+
DTC minimal.dtb
11+
Ready to launch Linux kernel. Please be patient.
12+
@./semu -k Image -c 1 -b minimal.dtb -i rootfs.cpio -n tap -d ext4.img
13+
[ 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
14+
[ 0.000000] Machine model: semu
15+
[ 0.000000] earlycon: ns16550 at MMIO 0xf4000000 (options '')
16+
[ 0.000000] printk: bootconsole [ns16550] enabled
17+
[ 0.000000] Zone ranges:
18+
[ 0.000000] Normal [mem 0x0000000000000000-0x000000001fffffff]
19+
[ 0.000000] Movable zone start for each node
20+
[ 0.000000] Early memory node ranges
21+
[ 0.000000] node 0: [mem 0x0000000000000000-0x000000001fffffff]
22+
[ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000001fffffff]
23+
[ 0.000000] SBI specification v2.0 detected
24+
[ 0.000000] SBI implementation ID=0x999 Version=0x1
25+
[ 0.000000] SBI TIME extension detected
26+
[ 0.000000] SBI IPI extension detected
27+
[ 0.000000] SBI RFENCE extension detected
28+
[ 0.000000] SBI SRST extension detected
29+
[ 0.000000] SBI HSM extension detected
30+
[ 0.000000] riscv: base ISA extensions aim
31+
[ 0.000000] riscv: ELF capabilities aim
32+
[ 0.000000] percpu: Embedded 10 pages/cpu s11604 r8192 d21164 u40960
33+
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 130048
34+
[ 0.000000] Kernel command line: earlycon console=ttyS0
35+
[ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
36+
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes, linear)
37+
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
38+
[ 0.000000] Memory: 506428K/524288K available (3578K kernel code, 345K rwdata, 873K rodata, 185K init, 140K bss, 17860K reserved, 0K cma-reserved)
39+
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
40+
[ 0.000000] rcu: Hierarchical RCU implementation.
41+
[ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=32 to nr_cpu_ids=1.
42+
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
43+
[ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
44+
[ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
45+
[ 0.000000] riscv-intc: 32 local interrupts mapped
46+
[ 0.000000] plic: interrupt-controller@0: mapped 31 interrupts with 1 handlers for 1 contexts.
47+
[ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
48+
[ 0.000000] riscv-timer: riscv_timer_init_dt: Registering clocksource cpuid [0] hartid [0]
49+
[ 0.000000] clocksource: riscv_clocksource: mask: 0xffffffffffffffff max_cycles: 0xefdb196da, max_idle_ns: 440795204367 ns
50+
[ 0.000000] sched_clock: 64 bits at 65MHz, resolution 15ns, wraps every 2199023255550ns
51+
[ 0.000017] Console: colour dummy device 80x25
52+
[ 0.000022] Calibrating delay loop (skipped), value calculated using timer frequency.. 130.00 BogoMIPS (lpj=260000)
53+
[ 0.000027] pid_max: default: 32768 minimum: 301
54+
[ 0.000043] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
55+
[ 0.000048] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
56+
[ 0.000154] ASID allocator disabled (0 bits)
57+
[ 0.000164] rcu: Hierarchical SRCU implementation.
58+
[ 0.000167] rcu: Max phase no-delay instances is 1000.
59+
[ 0.000191] smp: Bringing up secondary CPUs ...
60+
[ 0.000193] smp: Brought up 1 node, 1 CPU
61+
[ 0.000225] devtmpfs: initialized
62+
[ 0.000323] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
63+
[ 0.000328] futex hash table entries: 256 (order: 2, 16384 bytes, linear)
64+
[ 0.000442] NET: Registered PF_NETLINK/PF_ROUTE protocol family
65+
[ 0.000527] platform soc@F0000000: Fixed dependency cycle(s) with /soc@F0000000/interrupt-controller@0
66+
[ 0.001222] clocksource: Switched to clocksource riscv_clocksource
67+
[ 0.002111] NET: Registered PF_INET protocol family
68+
[ 0.002139] IP idents hash table entries: 8192 (order: 4, 65536 bytes, linear)
69+
[ 0.002417] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
70+
[ 0.002423] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
71+
[ 0.002427] TCP established hash table entries: 4096 (order: 2, 16384 bytes, linear)
72+
[ 0.002439] TCP bind hash table entries: 4096 (order: 4, 65536 bytes, linear)
73+
[ 0.002456] TCP: Hash tables configured (established 4096 bind 4096)
74+
[ 0.002464] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)
75+
[ 0.002469] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)
76+
[ 0.002485] NET: Registered PF_UNIX/PF_LOCAL protocol family
77+
[ 0.002559] Unpacking initramfs...
78+
[ 0.032861] Freeing initrd memory: 8188K
79+
[ 0.032883] workingset: timestamp_bits=30 max_order=17 bucket_order=0
80+
[ 0.038732] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
81+
[ 0.038862] printk: console [ttyS0] disabled
82+
[ 0.038867] f4000000.serial: ttyS0 at MMIO 0xf4000000 (irq = 1, base_baud = 312500) is a 16550
83+
[ 0.038873] printk: console [ttyS0] enabled
84+
[ 0.038873] printk: console [ttyS0] enabled
85+
[ 0.038878] printk: bootconsole [ns16550] disabled
86+
[ 0.038878] printk: bootconsole [ns16550] disabled
87+
[ 0.038916] virtio_blk virtio0: 1/0/0 default/read/poll queues
88+
[ 0.038959] virtio_blk virtio0: [vda] 4800 512-byte logical blocks (2.46 MB/2.34 MiB)
89+
[ 0.039098] clk: Disabling unused clocks
90+
[ 0.039148] Freeing unused kernel image (initmem) memory: 180K
91+
[ 0.039152] Kernel memory protection not selected by kernel config.
92+
[ 0.039157] Run /init as init process
93+
[SEMU LOG]: Use mach_absolute_time
94+
[SEMU LOG]: Real boot time: 43.63820 seconds, called 220128512 times semu_timer_clocksource
95+
[SEMU LOG]: ns_per_call = 4.46425, predict_sec = 8.92851, scale_factor = 1.12001

0 commit comments

Comments
 (0)