[RFC] tracing execution flow - coreboot

30 Aug 2011


      Hi,
Sorry about the email quality I'm too tired to re-check it again.
I had an idea to hijack the gprof for fun. I compiled the coreboot with -pg 
option (and  enabled stack frames) resulting that each called function has a 
"mcount" funtion called in prolog for gprof. However we do not use libc and 
gprof but we can use this for:
1) to show where whole execution flow goes
2) real time tracing (if console is RAM)
3) stack size checking
So far I have a proof of concept which is attached. It adds for ramstage -pg 
option and then implements the mcount function which looks into the frame 
pointer and prints to serial console who is it and who is the caller. This 
function then calls C function gprof which just print stack size and that 
information
Also, I protect the recursive usage of mcount during the gprof call via in_pg. 
Which is also triggered to remove sprintf and printf bits from logs.
It produces something like this:
Stage: loading fallback/coreboot_ram @ 0x100000 (606208 bytes), entry @ 0x100000
Stage: done loading.
Jumping to image.
~0x00107139(0x00100099)1638316
~0x00108599(0x00107146)1638304
~0x00107da5(0x0010714b)1638296
~0x001070fe(0x00107dbe)1638288
~0x00108599(0x00107157)1638304
~0x00107d3c(0x00107186)1638264
coreboot-4.0-1681-gd6a736e-dirty Mon Aug 29 22:56:18 CEST 2011 booting...
~0x00108599(0x00107190)1638304
~0x0011157d(0x001071a1)1638320
~0x00109a7a(0x001071a6)1638304
~0x00107d3c(0x00109a86)1638264
Enumerating buses...
No timing info so far. I annotate this log with a help of gdb and script tp:
Check fallback/romstage
Check fallback/coreboot_ram
Stage: loading fallback/coreboot_ram @ 0x100000 (606208 bytes), entry @ 0x100000
Stage: done loading.
Jumping to image.
~0x00107139(0x00100099)1638316~0x107139 is in hardwaremain (src/boot 
/hardwaremain.c:57). FROM 0x100099 is at src/arch/x86/lib/c_start.S:85.
~0x00108599(0x00107146)1638304~0x108599 is in post_code 
(src/arch/x86/include/arch/io.h:46). FROM 0x107146 is in hardwaremain 
(src/boot/hardwaremain.c:63).
~0x00107da5(0x0010714b)1638296~0x107da5 is in console_init 
(src/console/console.c:42). FROM 0x10714b is in hardwaremain 
(src/boot/hardwaremain.c:65).
~0x001070fe(0x00107dbe)1638288~0x1070fe is in uart_init 
(src/arch/x86/include/arch/io.h:46). FROM 0x107dbe is in console_init 
(src/console/console.c:44).
~0x00108599(0x00107157)1638304~0x108599 is in post_code 
(src/arch/x86/include/arch/io.h:46). FROM 0x107157 is in hardwaremain 
(src/boot/hardwaremain.c:67).
~0x00107d3c(0x00107186)1638264~0x107d3c is in do_printk 
(src/console/printk.c:25). FROM 0x107186 is in hardwaremain 
(src/boot/hardwaremain.c:71).
coreboot-4.0-1681-gd6a736e-dirty Mon Aug 29 22:56:18 CEST 2011 booting...
Or some nice bits:
Adding high table area
~0x0010dc84(0x0010e23d)463340~0x10dc84 is in lb_add_memory_range 
(src/arch/x86/boot/coreboot_table.c:417). FROM 0x10e23d is in 
write_coreboot_table (src/arch/x86/boot/coreboot_table.c:495).
~0x00113a60(0x0010dd65)463304~0x113a60 is in memmove (src/lib/memmove.c:3). FROM 
0x10dd65 is in lb_add_memory_range (src/arch/x86/boot/coreboot_table.c:383).
~0x00113a60(0x0010dd65)463304~0x113a60 is in memmove (src/lib/memmove.c:3). FROM 
0x10dd65 is in lb_add_memory_range (src/arch/x86/boot/coreboot_table.c:383).
~0x0010d96a(0x0010dea1)463296~0x10d96a is in lb_memory_range 
(src/arch/x86/boot/coreboot_table.c:252). FROM 0x10dea1 is in 
lb_add_memory_range (src/arch/x86/boot/coreboot_table.c:420).
~0x0010d9fa(0x0010e23d)463324~0x10d9fa is in lb_cleanup_memory_ranges 
(src/arch/x86/boot/coreboot_table.c:317). FROM 0x10e23d is in 
write_coreboot_table (src/arch/x86/boot/coreboot_table.c
P#1 freq 1000 [MHz] voltage 1100 [mV] TDP 21000 [mW]
~0x00110384(0x00116dcd)463164~0x110384 is in acpigen_write_processor 
(src/arch/x86/boot/acpigen.c:259). FROM 0x116dcd is in 
amd_model_fxx_generate_powernow (src/cpu/amd/model_fxx/powernow_a
cpi.c:44).
~0x0010fd74(0x001103ab)463148~0x10fd74 is in acpigen_write_len_f 
(src/arch/x86/boot/acpigen.c:40). FROM 0x1103ab is in acpigen_write_processor 
(src/arch/x86/boot/acpigen.c:271).
~0x0010853f(0x001103c4)463128~0x10853f is in sprintf 
(src/console/vsprintf.c:58). FROM 0x1103c4 is in acpigen_write_processor 
(src/arch/x86/boot/acpigen.c:272).
~0x0010fe6b(0x001103cc)463100~0x10fe6b is in acpigen_emit_namestring 
(src/arch/x86/boot/acpigen.c:203). FROM 0x1103cc is in acpigen_write_processor 
(src/arch/x86/boot/acpigen.c:70).
~0x0010fb66(0x0010ff03)463048~0x10fb66 is in acpigen_emit_simple_namestring 
(src/arch/x86/boot/acpigen.c:156). FROM 0x10ff03 is in acpigen_emit_namestring 
(src/arch/x86/boot/acpigen.c:174).
~0x0010fb66(0x0010ff14)463048~0x10fb66 is in acpigen_emit_simple_namestring 
(src/arch/x86/boot/acpigen.c:156). FROM 0x10ff14 is in acpigen_emit_namestring 
(src/arch/x86/boot/acpigen.c:234).
~0x0010fbcf(0x00116dd8)463236~0x10fbcf is in acpigen_write_empty_PCT 
(src/arch/x86/boot/acpigen.c:283). FROM 0x116dd8 is in 
amd_model_fxx_generate_powernow (src/cpu/amd/model_fxx/powernow_a
It looks like a fun, especially if one can image that the log is printed to raw 
memory and TSC info is used.
The whole log is on assembler.cz/alog.txt.gz which answeres a questions about 
execution flows ;)
I bit changed the annotate script at the end, because it took ages to execute ;) 
Good method is to just grep all lines with the info to one file, sort -u ask for 
the rest and just grep in the results for matching lines and intermix with 
original log. Instead of doing 30000 lines it did only few hundreds.
If there is someone with more time it would be great to integrate this somehow.
Thanks
Rudolf