[coreboot-gerrit] Patch set updated for coreboot: 3c93ea0 Poor man's ftrace from akaros

[Ronald G. Minnich]

Ronald G. Minnich ([e-mail]) just uploaded a new patch set to gerrit, which you can find at http://review.coreboot.org/7116

-gerrit

commit 3c93ea01cb09e52b56098dda7135b893d23d64a1
Author: Ronald G. Minnich 
Date:   Sat Oct 18 06:09:24 2014 +0000

Poor man's ftrace from akaros

This is the
    poor man's ftrace from Akaros
    (just search for that term)

To use:
    suppose you want to trace all file entry and exit in some piece of code, e.g.
    cbfs.

Just:
    spatch --in-place --sp-file scripts/spatch/poor-ftrace.coci src/lib/cbfs*.c
    Build as usual.

When you run, you'll see function calls, and they will be spaced in
    according to their call depth, e.g.:
    a
    	b
    		c
    	b
    		d
    	b
    a

Sadly, in pre-ram stage, this indenting is not possible.
    Instead, we print ENTER on entry and EXIT on exit.
    It's usable.

It's incredibly useful for debugging. We have been able to very quickly zero in on
    bugs in Akaros with this code. I print at BIOS_EMERG so you're sure
    to take it out when done (just git checkout the files you're tracing or
    reverse the spatch.)

For example, on riscv, I know it's dying, I don't know where.

spatch --sp-file util/spatch/poor-ftrace.cocci src/arch/riscv/*.c src/lib/cbfs.c

I get this:

Find fallback
    cbfs_load_stage() in src/lib/cbfs.c
    	init_default_cbfs_media() in src/arch/riscv/rom_media.c
    	---- init_default_cbfs_media()
    	init_rom_media_cbfs() in src/arch/riscv/rom_media.c

And I know where to start.

You do need spatch installed.

Change-Id: I69c3c20d30ebd666c0e859cea906a3fd5a094441
    Signed-off-by: Ronald G. Minnich 
---
 src/console/printk.c          | 42 ++++++++++++++++++++++++++++++++++++++++++
 src/include/console/console.h |  6 ++++++
 util/spatch/poor-ftrace.cocci | 18 ++++++++++++++++++
 3 files changed, 66 insertions(+)

diff --git a/src/console/printk.c b/src/console/printk.c
index b6777e1..4597007 100644
--- a/src/console/printk.c
+++ b/src/console/printk.c
@@ -12,6 +12,7 @@
 #include <smp/node.h>
 #include <stddef.h>
 #include <trace.h>
+#include <stdlib.h>

DECLARE_SPIN_LOCK(console_lock)

@@ -62,3 +63,44 @@ void do_vtxprintf(const char *fmt, va_list args)
    console_tx_flush();
 }
 #endif /* CONFIG_CHROMEOS */
+
+#ifdef __PRE_RAM__
+/* sadly, pretty printing the call depth in pre-ram is not an option. How sad! */
+
+void __print_func_entry(const char *func, const char *file)
+{
+	printk(BIOS_EMERG, "ENTER %s() in %s\n", func, file);
+}
+/* for tracing. You can call these on func entry and exit.
+ * Or, better, you can use the spatch in utils to add
+ * such tracing.
+ */
+void __print_func_exit(const char *func, const char *file)
+{
+	printk(BIOS_EMERG, "EXIT ---- %s()\n", func);
+}
+
+#else
+int tab_depth = 0;
+
+void __print_func_entry(const char *func, const char *file)
+{
+	char tentabs[] = "\t\t\t\t\t\t\t\t\t\t"; // ten tabs and a \0
+	char *ourtabs = &tentabs[10 - MIN(tab_depth, 10)];
+	printk(BIOS_EMERG, "%s%s() in %s\n", ourtabs, func, file);
+	tab_depth++;
+}
+/* for tracing. You can call these on func entry and exit.
+ * Or, better, you can use the spatch in utils to add
+ * such tracing.
+ */
+void __print_func_exit(const char *func, const char *file)
+{
+	char tentabs[] = "\t\t\t\t\t\t\t\t\t\t"; // ten tabs and a \0
+	char *ourtabs;
+	tab_depth--;
+	ourtabs = &tentabs[10 - MIN(tab_depth, 10)];
+	printk(BIOS_EMERG, "%s---- %s()\n", ourtabs, func);
+}
+
+#endif
diff --git a/src/include/console/console.h b/src/include/console/console.h
index 9e98bfc..d5ec2f3 100644
--- a/src/include/console/console.h
+++ b/src/include/console/console.h
@@ -75,6 +75,12 @@ static inline void do_vtxprintf(const char *fmt, va_list args) {};
  */
 #include <console/early_print.h>

+/* for the poor man's ftrace. */
+void __print_func_entry(const char *func, const char *file);
+void __print_func_exit(const char *func, const char *file);
+#define print_func_entry() __print_func_entry(__FUNCTION__, __FILE__)
+#define print_func_exit() __print_func_exit(__FUNCTION__, __FILE__)
+
 #else /* __ROMCC__ */

#include "arch/x86/lib/romcc_console.c"
diff --git a/util/spatch/poor-ftrace.cocci b/util/spatch/poor-ftrace.cocci
new file mode 100644
index 0000000..3754374
--- /dev/null
+++ b/util/spatch/poor-ftrace.cocci
@@ -0,0 +1,18 @@
+// prints entry/exit when entering/leaving a function
+
+// for example, spatch with:
+// $ for i in kern/src/ns/ kern/src/net kern/drivers/; do \
+//       spatch --sp-file scripts/spatch/poor-ftrace.cocci  --in-place $i; done
+// if you have functions you want to ignore, add them to the blacklist in
+// kern/src/kdebug.c
+@@
+type t;
+function f;
+@@
+t f(...) {
++print_func_entry();
+<...
++print_func_exit();
+return ...;
+...>
+}