ftrace: support very early function tracing

Hi Steve,

I updated the patch with all the fixes except for update timestamp part.

I used ftrace_export as you suggested, but I don't know how to hook to ringbuffer to update the timestamp, I used the same way as before to update the time_delta in function ftrace_vearly_export_write.

static u64 export_delta __initdata;

static void __init ftrace_vearly_export_write(const void *buf, unsigned int len)

{
        struct ring_buffer_event *event;
        const u32 *entry = buf;

        event = container_of(entry, struct ring_buffer_event, array[0]);
        event->time_delta = export_delta;
}

Do I have to add a hook somewhere in the kernel/trace/ringbuffer.c ? And then call it from ftrace_vearly_export_write ?

PATCH v2
--------------------------------------------------------------------

The very early tracing will start from the beginning of start_kernel() and will stop at ftrace_init().

start_kernel()
{
ftrace_early_init() <--- start very early tracing
...
(calls)
...
ftrace_init() <--- stop very early tracing
early_trace_init(); <--- fill ring buffer, start function tracer if on
...
}

Currently, the events are saved in a temporary static buffer, which they will be copied to the ring buffer when it will be allocated.

For the timestamp, we use rdtsc for x86, and sched_clock for the other archs.

Currently dynamic tracing is not implemented with live patching, we use ftrace_filter and ftrace_notrace to find which functions to be filtered (traced / not traced), then during the callback from mcount hook, we do binary search lookup to decide which function to be save or not.

Signed-off-by Abderrahmane Benbachir <[email protected]>

Cc Steven Rostedt <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Mathieu Desnoyers <[email protected]>

Cc [email protected]

---
 arch/x86/Kconfig            |   1 +
 arch/x86/kernel/ftrace_32.S |  73 ++++++++++
 arch/x86/kernel/ftrace_64.S |  14 ++
 include/linux/ftrace.h      |  16 ++-
 init/main.c                 |   1 +
 kernel/trace/Kconfig        |  42 ++++++
 kernel/trace/ftrace.c       | 341 +++++++++++++++++++++++++++++++++++++++++++-
 kernel/trace/trace.c        |   3 +
 8 files changed, 487 insertions(+), 4 deletions(-)

arch/x86/Kconfig +1 -0

index 971feac13506..03da741c088b 100644
@@ -137,6 +137,7 @@ config X86
 	select HAVE_FENTRY			if X86_64 || DYNAMIC_FTRACE
 	select HAVE_FTRACE_MCOUNT_RECORD
 	select HAVE_FUNCTION_GRAPH_TRACER
+	select HAVE_VERY_EARLY_FTRACE
 	select HAVE_FUNCTION_TRACER
 	select HAVE_GCC_PLUGINS
 	select HAVE_HW_BREAKPOINT

arch/x86/kernel/ftrace_32.S +44 -0

index 722a145b4139..5d93037872b2 100644
@@ -29,8 +29,81 @@ EXPORT_SYMBOL(mcount)
 # define MCOUNT_FRAME			0	/* using frame = false */
 #endif
 
+.macro save_mcount_regs
+#ifdef USING_FRAME_POINTER
+# ifdef CC_USING_FENTRY
+	/*
+	 * Frame pointers are of ip followed by bp.
+	 * Since fentry is an immediate jump, we are left with
+	 * parent-ip, function-ip. We need to add a frame with
+	 * parent-ip followed by ebp.
+	 */
+	pushl	4(%esp)				/* parent ip */
+	pushl	%ebp
+	movl	%esp, %ebp
+	pushl	2*4(%esp)			/* function ip */
+# endif
+	/* For mcount, the function ip is directly above */
+	pushl	%ebp
+	movl	%esp, %ebp
+#endif
+	pushl	%eax
+	pushl	%ecx
+	pushl	%edx
+	pushl	$0				/* Pass NULL as regs pointer */
+
+#ifdef USING_FRAME_POINTER
+	/* Load parent ebp into edx */
+	movl	4*4(%esp), %edx
+#else
+	/* There's no frame pointer, load the appropriate stack addr instead */
+	lea	4*4(%esp), %edx
+#endif
+
+	movl	(MCOUNT_FRAME+4)*4(%esp), %eax	/* load the rip */
+	/* Get the parent ip */
+	movl	4(%edx), %edx			/* edx has ebp */
+
+	movl	function_trace_op, %ecx
+	subl	$MCOUNT_INSN_SIZE, %eax
+	.endm
+
+.macro restore_mcount_regs
+	addl	$4, %esp			/* skip NULL pointer */
+	popl	%edx
+	popl	%ecx
+	popl	%eax

arch/x86/kernel/ftrace_32.S +19 -0

+
 ENTRY(function_hook)
+#ifdef CONFIG_VERY_EARLY_FUNCTION_TRACER
+	cmpl	$__PAGE_OFFSET, %esp
+	jb	vearly_stub			/* Paging not enabled yet? */
+
+	cmpl	$ftrace_stub, ftrace_vearly_trace_function
+	jnz vearly_trace
+
+vearly_stub:
 	ret
+
+vearly_trace:
+	save_mcount_regs
+	call	*ftrace_vearly_trace_function
+	restore_mcount_regs
+
+	jmp vearly_stub
+#else
+	ret
+#endif
 END(function_hook)
 
 ENTRY(ftrace_caller)

arch/x86/kernel/ftrace_64.S +14 -0

index 1dfac634bbf7..35f73a9dbbd2 100644
@@ -146,7 +146,21 @@ EXPORT_SYMBOL(mcount)
 #ifdef CONFIG_DYNAMIC_FTRACE
 
 ENTRY(function_hook)
+#ifdef CONFIG_VERY_EARLY_FUNCTION_TRACER
+	cmpq $ftrace_stub, ftrace_vearly_trace_function
+	jnz vearly_trace
+
+vearly_stub:
 	retq
+
+vearly_trace:
+	save_mcount_regs
+	call *ftrace_vearly_trace_function
+	restore_mcount_regs
+	jmp vearly_stub
+#else
+	retq
+#endif
 END(function_hook)
 
 ENTRY(ftrace_caller)

include/linux/ftrace.h +15 -1

index 2e028854bac7..c3f2ba246fc9 100644
@@ -272,6 +272,16 @@ static inline void ftrace_kill(void) { }
 static inline void ftrace_free_init_mem(void) { }
 #endif /* CONFIG_FUNCTION_TRACER */
 
+#ifdef CONFIG_VERY_EARLY_FUNCTION_TRACER
+extern void ftrace_early_init(char *command_line);
+extern void ftrace_early_shutdown(void);
+extern void ftrace_early_fill_ringbuffer(void *data);
+#else
+static inline void ftrace_early_init(char *command_line) { }
+static inline void ftrace_early_shutdown(void) { }
+static inline void ftrace_early_fill_ringbuffer(void *data) { }
+#endif
+
 #ifdef CONFIG_STACK_TRACER
 
 #define STACK_TRACE_ENTRIES 500

@@ -476,6 +486,10 @@ unsigned long ftrace_get_addr_curr(struct dyn_ftrace *rec);
 
 extern ftrace_func_t ftrace_trace_function;
 
+#if defined(CONFIG_VERY_EARLY_FUNCTION_TRACER) && defined(CONFIG_DYNAMIC_FTRACE)
+extern ftrace_func_t ftrace_vearly_trace_function;
+#endif
+
 int ftrace_regex_open(struct ftrace_ops *ops, int flag,
 		  struct inode *inode, struct file *file);
 ssize_t ftrace_filter_write(struct file *file, const char __user *ubuf,

@@ -757,7 +771,7 @@ static inline unsigned long get_lock_parent_ip(void)
 #ifdef CONFIG_FTRACE_MCOUNT_RECORD
 extern void ftrace_init(void);
 #else
-static inline void ftrace_init(void) { }
+static inline void ftrace_init(void) { ftrace_early_shutdown(); }
 #endif
 
 /*

init/main.c +1 -0

index 0ee9c6866ada..c794292b18ef 100644
@@ -511,6 +511,7 @@ asmlinkage __visible void __init start_kernel(void)
 	char *command_line;
 	char *after_dashes;
 
+	ftrace_early_init(boot_command_line);
 	set_task_stack_end_magic(&init_task);
 	smp_setup_processor_id();
 	debug_objects_early_init();

kernel/trace/Kconfig +5 -0

index 434c840e2d82..0e1a9662bb2f 100644
@@ -19,6 +19,11 @@ config HAVE_FUNCTION_TRACER
 	help
 	  See Documentation/trace/ftrace-design.txt
 
+config HAVE_VERY_EARLY_FTRACE
+	bool
+	help
+	  See Documentation/trace/ftrace-design.txt
+
 config HAVE_FUNCTION_GRAPH_TRACER
 	bool
 	help

kernel/trace/Kconfig +4 -0

+	default 19
+	help
+	  Select the size of the buffer to be used for storing function calls at
+	  very early stage.

kernel/trace/Kconfig +5 -0

+	  Examples:
+	    19 => 512 KB
+	    18 => 256 KB
+	    17 => 128 KB
+
 config FUNCTION_GRAPH_TRACER
 	bool "Kernel Function Graph Tracer"
 	depends on HAVE_FUNCTION_GRAPH_TRACER

kernel/trace/ftrace.c +0 -0

index 8319e09e15b9..5e1b53662bbb 100644

kernel/trace/ftrace.c +23 -2

 #include <trace/events/sched.h>
 
 #include <asm/sections.h>

@@ -65,6 +65,8 @@
 #define FTRACE_HASH_MAX_BITS 12
 
 #ifdef CONFIG_DYNAMIC_FTRACE
+extern unsigned long __start_mcount_loc[];
+extern unsigned long __stop_mcount_loc[];
 #define INIT_OPS_HASH(opsname)	\
 	.func_hash		= &opsname.local_hash,			\
 	.local_hash.regex_lock	= __MUTEX_INITIALIZER(opsname.local_hash.regex_lock),

@@ -5912,11 +5914,11 @@ void __init ftrace_free_init_mem(void)
 
 void __init ftrace_init(void)
 {
-	extern unsigned long __start_mcount_loc[];
-	extern unsigned long __stop_mcount_loc[];
 	unsigned long count, flags;
 	int ret;
 
+	ftrace_early_shutdown();
+
 	local_irq_save(flags);
 	ret = ftrace_dyn_arch_init();
 	local_irq_restore(flags);

@@ -6882,3 +6884,336 @@ void ftrace_graph_exit_task(struct task_struct *t)
 	kfree(ret_stack);
 }
 #endif
+
+
+#ifdef CONFIG_VERY_EARLY_FUNCTION_TRACER
+
+#define VEARLY_BUF_LEN ((1 << CONFIG_VERY_EARLY_BUF_SHIFT) / \
+					sizeof(struct ftrace_vearly_entry))
+/*
+ * In very early stage :
+ *  - only CPU0 is running in early, there is no need to store it
+ *  - tsc counter is used in x86, otherwise we use sched_clock
+ */
+struct ftrace_vearly_entry {
+	unsigned long ip;
+	unsigned long parent_ip;
+	unsigned long long clock;
+};
+static struct ftrace_vearly_entry ftrace_vearly_entries[VEARLY_BUF_LEN] __initdata;
+static const unsigned long VERY_EARLY_BUF_LEN __initconst = VEARLY_BUF_LEN;
+static struct trace_export ftrace_vearly_export __initdata;

kernel/trace/ftrace.c +181 -0

+
+
+#ifdef CONFIG_DYNAMIC_FTRACE
+#define VEARLY_FILTER_SIZE ((1 << CONFIG_VERY_EARLY_FILTER_SHIFT) / \
+					sizeof(unsigned long))
+struct ftrace_vearly_filtering {
+	unsigned long list[VEARLY_FILTER_SIZE];
+	char buf[COMMAND_LINE_SIZE];
+	int size;
+};
+static const unsigned long FILTER_SIZE __initconst = VEARLY_FILTER_SIZE;
+static struct ftrace_vearly_filtering ftrace_data_notrace __initdata;
+static struct ftrace_vearly_filtering ftrace_data_filter __initdata;
+
+static __init int
+ftrace_vearly_match_record(unsigned long ip, struct ftrace_glob *func_g)
+{
+	char str[KSYM_SYMBOL_LEN];
+	char *modname;
+
+	kallsyms_lookup(ip, NULL, NULL, &modname, str);
+	return ftrace_match(str, func_g);
+}
+
+static __init int ftrace_vearly_filter_has_addr(unsigned long addr,
+	unsigned long *filter, int *size)
+{
+	int i;
+
+	for (i = 0; i < *size; i++) {
+		if (filter[i] == addr)
+			return 1;
+	}
+	return 0;
+}
+
+static __init void
+ftrace_vearly_regex(char *func, unsigned long *filter, int *size)
+{
+	struct ftrace_glob func_g = { .type = MATCH_FULL };
+	unsigned long *start = __start_mcount_loc;
+	unsigned long *end = __stop_mcount_loc;
+	unsigned long count;
+	unsigned long addr;
+	unsigned long *p;
+	int clear_filter = 0;
+
+	count = end - start;
+
+	if (!count)
+		return;
+
+	if (func) {
+		func_g.type = filter_parse_regex(func, strlen(func), &func_g.search,
+						 &clear_filter);
+		func_g.len = strlen(func_g.search);
+	}
+
+	p = start;
+	while (p < end) {
+		addr = ftrace_call_adjust(*p++);
+		if (!addr)
+			continue;
+
+		if ((*size) > FILTER_SIZE)
+			return;
+
+		if (ftrace_vearly_match_record(addr, &func_g)) {
+			if (!ftrace_vearly_filter_has_addr(addr, filter, size))
+				filter[(*size)++] = addr;
+		}
+	}
+}
+
+static int __init ftrace_addr_compare(const void *a, const void *b)
+{
+	if (*(unsigned long *)a > *(unsigned long *)b)
+		return 1;
+	if (*(unsigned long *)a < *(unsigned long *)b)
+		return -1;
+
+	return 0;
+}
+
+static void __init ftrace_addr_swap(void *a, void *b, int size)
+{
+	unsigned long t = *(unsigned long *)a;
+	*(unsigned long *)a = *(unsigned long *)b;
+	*(unsigned long *)b = t;
+}
+
+static __init int set_ftrace_vearly_filtering(void *data, char *str)
+{
+	struct ftrace_vearly_filtering *ftrace_data = data;
+	char *func;
+	char *buf;
+
+	if (!ftrace_data)
+		return 0;
+	buf = ftrace_data->buf;
+	strlcpy(buf, str, COMMAND_LINE_SIZE);
+
+	while (buf) {
+		func = strsep(&buf, ",");
+		ftrace_vearly_regex(func, ftrace_data->list, &ftrace_data->size);
+	}
+	/* sort filter to use binary search on it */
+	sort(ftrace_data->list, ftrace_data->size,
+		sizeof(unsigned long), ftrace_addr_compare, ftrace_addr_swap);
+
+	return 1;
+}
+
+#define ftrace_vearly_bsearch_addr(addr, data) bsearch(&addr, data.list,\
+	data.size, sizeof(unsigned long), ftrace_addr_compare)
+
+#endif /* CONFIG_DYNAMIC_FTRACE */
+
+
+static __init void
+ftrace_function_vearly_trace_call(unsigned long ip, unsigned long parent_ip,
+			struct ftrace_ops *op, struct pt_regs *regs)
+{
+	struct ftrace_vearly_entry *entry;
+
+#ifdef CONFIG_DYNAMIC_FTRACE
+	if (ftrace_data_notrace.size &&
+			ftrace_vearly_bsearch_addr(ip, ftrace_data_notrace))
+		return;
+
+	if (ftrace_data_filter.size &&
+			!ftrace_vearly_bsearch_addr(ip, ftrace_data_filter))
+		return;
+#endif
+
+	if (vearly_entries_count >= VERY_EARLY_BUF_LEN) {
+		/* stop tracing when buffer is full */
+		ftrace_vearly_disable();
+		return;
+	}
+
+	entry = &ftrace_vearly_entries[vearly_entries_count++];
+	entry->ip = ip;
+	entry->parent_ip = parent_ip;
+#ifdef CONFIG_X86_TSC
+	entry->clock = rdtsc();
+#else
+	entry->clock = trace_clock_local();
+#endif
+}
+
+/*
+ * ns = cycles * (10^6 / cpu_khz)
+ */
+static u64 __init cycles_to_ns(u64 cycles, u64 khz)
+{
+	u64 ns = cycles;
+	u64 dividend, divisor = 0;
+	const u64 constant = 1000000;
+
+	if (khz > constant) {
+		// ns /= (khz / constant);
+		dividend = khz;
+		divisor = constant;
+		do_div(dividend, divisor);
+		do_div(ns, dividend);
+	} else {
+		dividend = constant;
+		divisor = khz;
+		do_div(dividend, divisor);
+		ns *= dividend;
+	}
+	return ns;
+}
+
+/**
+ * delta btw the current and previous event, used in ftrace export to
+ * update entry time delta
+ */
+static u64 export_delta __initdata;
+/**

kernel/trace/ftrace.c +7 -0

+
+void __init ftrace_early_fill_ringbuffer(void *data)
+{
+	struct ftrace_vearly_entry *entry;
+	struct trace_array *tr = data;
+	unsigned long cpu_khz;
+	u64 ns, prev_ns = 0;

kernel/trace/ftrace.c +19 -0

+}
+
+static __init int set_ftrace_vearly_enable(void *data, char *str)
+{
+	ftrace_vearly_enabled = 1;
+	return 1;
+}
+/*
+ * this will be used as __setup_param
+ */
+struct ftrace_vearly_obs_param {
+	int (*setup_func)(void *, char*);
+	const char *str;
+	void *data;
+};
+static struct ftrace_vearly_obs_param ftrace_vearly_params[] __initdata = {
+	{ .str = "ftrace_vearly", .setup_func = set_ftrace_vearly_enable },
+#ifdef CONFIG_DYNAMIC_FTRACE
+	{

kernel/trace/ftrace.c +51 -0

+};
+
+static int __init ftrace_do_very_early_param(char *param, char *val,
+				 const char *unused, void *arg)
+{
+	int size = ARRAY_SIZE(ftrace_vearly_params);
+	struct ftrace_vearly_obs_param *p;
+	int i;
+
+	for (i = 0; i < size; i++) {
+		p = &ftrace_vearly_params[i];
+		if (strcmp(param, p->str) == 0) {
+			p->setup_func(p->data, val);
+			return 0;
+		}
+	}
+	return 0;
+}
+
+void __init ftrace_early_init(char *command_line)
+{
+	/* proceed only if 'ftrace_vearly' exist */
+	if (!strstr(command_line, "ftrace_vearly"))
+		return;
+
+	strlcpy(tmp_cmdline, command_line, COMMAND_LINE_SIZE);
+	parse_args("ftrace vearly options", tmp_cmdline, NULL, 0, 0, 0, NULL,
+		ftrace_do_very_early_param);
+
+	if (ftrace_vearly_enabled)
+		ftrace_vearly_trace_function = ftrace_function_vearly_trace_call;
+}
+
+void __init ftrace_early_shutdown(void)
+{
+	if (!ftrace_vearly_enabled)
+		return;
+
+	ftrace_vearly_disable();
+
+#ifdef CONFIG_DYNAMIC_FTRACE
+	pr_info("ftrace: vearly %u entries, notrace=%d, filter=%d",
+		vearly_entries_count,
+		ftrace_data_notrace.size,
+		ftrace_data_filter.size);
+#else
+	pr_info("ftrace: vearly %u recorded entries", vearly_entries_count);
+#endif
+}
+
+#endif /* CONFIG_VERY_EARLY_FUNCTION_TRACER */

kernel/trace/trace.c +3 -0

index 752e5daf0896..c097b97b3025 100644
@@ -8364,6 +8364,9 @@ __init static int tracer_alloc_buffers(void)
 	/* Function tracing may start here (via kernel command line) */
 	init_function_trace();
 
+	/* Pre-fill the ring buffer with very early events */
+	ftrace_early_fill_ringbuffer(&global_trace);
+
 	/* All seems OK, enable tracing */
 	tracing_disabled = 0;
 

Quoted 9 lines

kernel/trace/ftrace.c +8 -0

+#ifdef CONFIG_X86_TSC
+	entry->clock = rdtsc();
+#else
+	entry->clock = trace_clock_local();
+#endif
 
+#ifdef CONFIG_X86_TSC
+	cpu_khz = native_calibrate_cpu();
+#endif

kernel/trace/ftrace.c void ftrace_graph_exit_task(struct task_struct *t) · line 7133

Quoted 5 lines

kernel/trace/ftrace.c +5 -0

+#ifdef CONFIG_X86_TSC
+		ns = cycles_to_ns(entry->clock, cpu_khz);
+#else
+		ns = entry->clock;
+#endif

Quoted 9 lines · Steven Rostedt

Quoted 9 lines

kernel/trace/ftrace.c +8 -0

+#ifdef CONFIG_X86_TSC
+	entry->clock = rdtsc();
+#else
+	entry->clock = trace_clock_local();
+#endif  
 
+#ifdef CONFIG_X86_TSC
+	cpu_khz = native_calibrate_cpu();
+#endif  

Quoted 5 lines

kernel/trace/ftrace.c void ftrace_graph_exit_task(struct task_struct *t) · line 7133

Quoted 5 lines

kernel/trace/ftrace.c +5 -0

+#ifdef CONFIG_X86_TSC
+		ns = cycles_to_ns(entry->clock, cpu_khz);
+#else
+		ns = entry->clock;
+#endif  

Yeah, no, not going to happen...

Quoted 11 lines · On Wed, 8 Nov 2017 09:10:58 +0100 Peter Zijlstra <[email protected]> wrote:

Quoted 9 lines · Steven Rostedt

Quoted 9 lines

kernel/trace/ftrace.c +8 -0

+#ifdef CONFIG_X86_TSC
+	entry->clock = rdtsc();
+#else
+	entry->clock = trace_clock_local();
+#endif  
 
+#ifdef CONFIG_X86_TSC
+	cpu_khz = native_calibrate_cpu();
+#endif  

Quoted 7 lines

Quoted 5 lines

kernel/trace/ftrace.c void ftrace_graph_exit_task(struct task_struct *t) · line 7133

Quoted 5 lines

kernel/trace/ftrace.c +5 -0

+#ifdef CONFIG_X86_TSC
+		ns = cycles_to_ns(entry->clock, cpu_khz);
+#else
+		ns = entry->clock;
+#endif  

Yeah, no, not going to happen...

Agreed.

Depends on how early you need things; ideally you'd be able to use the

stuff from here:

https://lkml.kernel.org/r/[email protected]

That is, fix the normal time sources to work earlier instead of building parallel infrastructure.

Quoted 1 line · On Wed, 8 Nov 2017 20:07:27 +0100 Peter Zijlstra <[email protected]> wrote:

Depends on how early you need things; ideally you'd be able to use the

Well, he starts tracing at the entry of start_kernel(), would this handle that?

	ring_buffer_set_clock(tr->trace_buffer.buffer,
				early_trace_clock);

Then have:

static u64 early_timestamp __initdata;

static __init u64 early_trace_clock(void)

{
	return early_timestamp;
}

Then we can have:

kernel/trace/ftrace.c void ftrace_graph_exit_task(struct task_struct *t) · line 7133

Quoted 9 lines

kernel/trace/ftrace.c +9 -0

+	preempt_disable_notrace();
+	for (i = 0; i < vearly_entries_count; i++) {
+		entry = &ftrace_vearly_entries[i];
+
+#ifdef CONFIG_X86_TSC
+		ns = cycles_to_ns(entry->clock, cpu_khz);
+#else
+		ns = entry->clock;
+#endif

		early_timestamp = ns;

kernel/trace/ftrace.c void ftrace_graph_exit_task(struct task_struct *t) · line 7136

Quoted 1 line

kernel/trace/ftrace.c +1 -0

+		trace_function(tr, entry->ip, entry->parent_ip, 0, 0);

And it will fill the entries properly, and you don't need to worry about delta's or anything.

Review

Quoted 2 lines

(quoted diff) +2 -0

+	}
+	preempt_enable_notrace();

	/* Set the default clock back */
	ring_buffer_set_clock(tr->trace_buffer.buffer,
			trace_local_clock);

Quoted 9 lines

kernel/trace/ftrace.c +9 -0

+static struct ftrace_vearly_obs_param ftrace_vearly_params[] __initdata = {
+	{ .str = "ftrace_vearly", .setup_func = set_ftrace_vearly_enable },
+#ifdef CONFIG_DYNAMIC_FTRACE
+	{
+		.str = "ftrace_notrace",
+		.data = &ftrace_data_notrace,
+		.setup_func = set_ftrace_vearly_filtering,
+	},
+	{

kernel/trace/ftrace.c void ftrace_graph_exit_task(struct task_struct *t) · line 7168

Quoted 5 lines

kernel/trace/ftrace.c +5 -0

+		.str = "ftrace_filter",
+		.data = &ftrace_data_filter,
+		.setup_func = set_ftrace_vearly_filtering,
+	},
+#endif

Hmm, wouldn't this actually still be able to work even if DYNAMIC_FTRACE was not set?

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

function tracing starts here <<<<<<<<<<<<<<<<<<<<<<<<<<

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

function tracing starts here <<<<<<<<<<<<<<<<<<<<<<<<<<

I implemented the ring_buffer_set_clock solution and I have some questions.

void __init ftrace_early_fill_ringbuffer(void *data) {
...

	ring_buffer_set_clock(tr->trace_buffer.buffer, early_trace_clock);
	preempt_disable_notrace();
	for (i = 0; i < vearly_entries_count; i++) {
		entry = &ftrace_vearly_entries[i];

		early_timestamp = entry->clock;

		trace_function(tr, entry->ip, entry->parent_ip, 0, 0);
	}
	preempt_enable_notrace();

         /* TODO: should set the previous clock */
	ring_buffer_set_clock(tr->trace_buffer.buffer, trace_clock_local);

I need also to save the current clock before calling "ring_buffer_set_clock()", is there
a way to get the current clock or to set the clock from tr->clock_id ?

There is one thing happening when using the trace_clock_local instead of rdtsc.

I added different kernel params to trigger the issue :

When using entry->clock = trace_clock_local():

kernel param "ftrace_vearly ftrace_filter=*_init"

[    0.312179]   <idle>-0       0dp..    0us : boot_cpu_init <-start_kernel
...
[    0.320280]   <idle>-0       0dp..    0us : numa_init <-x86_numa_init
[    0.320673]   <idle>-0       0dp..    0us : dummy_numa_init <-numa_init
[    0.321082]   <idle>-0       0dp..    6us : paging_init <-setup_arch
[    0.321471]   <idle>-0       0dp..    9us : sparse_init <-paging_init
[    0.321867]   <idle>-0       0dp.. 1174us : zone_sizes_init <-paging_init
[    0.322283]   <idle>-0       0dp.. 1201us : lruvec_init  
<-free_area_init_node
[    0.322714]   <idle>-0       0dp.. 1524us : acpi_boot_init <-setup_arch
[    0.323120]   <idle>-0       0dp.. 1595us : sfi_init <-setup_arch
[    0.323500]   <idle>-0       0dp.. 1601us : kvm_guest_init <-setup_arch
[    0.323904]   <idle>-0       0dp.. 1623us : mcheck_init <-setup_arch
[    0.324293]   <idle>-0       0dp.. 1623us : mcheck_intel_therm_init  
<-mcheck_init
[    0.324772]   <idle>-0       0dp.. 1724us : boot_cpu_state_init  
<-start_kernel
[    0.325259]   <idle>-0       0dp.. 1724us : kvm_guest_cpu_init  
<-kvm_smp_prepare_boot_cpu
[    0.325789]   <idle>-0       0dp.. 1733us : kvm_spinlock_init  
<-kvm_smp_prepare_boot_cpu
[    0.326300]   <idle>-0       0dp.. 1733us :  
build_all_zonelists_init <-build_all_zonelists
[    0.326820]   <idle>-0       0dp.. 1738us : page_alloc_init <-start_kernel
[    0.327252]   <idle>-0       0dp.. 1906us : jump_label_init <-start_kernel
[    0.327673]   <idle>-0       0dp.. 4913us : pidhash_init <-start_kernel
[    0.328076]   <idle>-0       0dp.. 4917us : trap_init <-start_kernel
[    0.328466]   <idle>-0       0dp.. 4927us : kvm_apf_trap_init <-trap_init
[    0.328877]   <idle>-0       0dp.. 4928us : mem_init <-start_kernel
[    0.329263]   <idle>-0       0dp.. 4930us : gart_iommu_hole_init  
<-pci_iommu_alloc
[    0.329745]   <idle>-0       0dp.. 5129us : kmem_cache_init <-start_kernel
[    0.330162]   <idle>-0       0dp.. 5300us : vmalloc_init <-start_kernel

kernel param "ftrace=function ftrace_vearly ftrace_filter=*_init"

[    0.315455]   <idle>-0       0dp.. 18446744073666366us :  
boot_cpu_init <-start_kernel
...
[    0.338102]   <idle>-0       0dp.. 18446744073671436us : trap_init  
<-start_kernel
[    0.338584]   <idle>-0       0dp.. 18446744073671446us :  
kvm_apf_trap_init <-trap_init
[    0.339089]   <idle>-0       0dp.. 18446744073671447us : mem_init  
<-start_kernel
[    0.339564]   <idle>-0       0dp.. 18446744073671449us :  
gart_iommu_hole_init <-pci_iommu_alloc
[    0.340111]   <idle>-0       0dp.. 18446744073671635us :  
kmem_cache_init <-start_kernel
[    0.340622]   <idle>-0       0dp.. 18446744073671775us :  

vmalloc_init <-start_kernel

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

function tracing starts here <<<<<<<<<<<<<<<<<<<<<<<<<<

[    0.341119]   <idle>-0       0dp.1 48004us : sched_init <-start_kernel
[    0.341520]   <idle>-0       0dp.1 48005us : wait_bit_init <-sched_init
[    0.341926]   <idle>-0       0dp.1 48007us : hrtimer_init  
<-init_rt_bandwidth
[    0.342359]   <idle>-0       0dp.1 48007us : __hrtimer_init <-hrtimer_init
[    0.342779]   <idle>-0       0dp.1 48007us : cpudl_init <-init_rootdomain
[    0.343196]   <idle>-0       0dp.1 48008us : cpupri_init <-init_rootdomain
[    0.343618]   <idle>-0       0dp.1 48014us : autogroup_init <-sched_init

When using entry->clock = rdtsc() [working well]:

kernel param "ftrace=function ftrace_vearly ftrace_filter=*_init"

[    0.314067]   <idle>-0       0dp.. 154207us : boot_cpu_init <-start_kernel
...
[    0.333397]   <idle>-0       0dp.. 180362us : mem_init <-start_kernel
[    0.333806]   <idle>-0       0dp.. 180365us : gart_iommu_hole_init  
<-pci_iommu_alloc
[    0.334330]   <idle>-0       0dp.. 180652us : kmem_cache_init  
<-start_kernel
[    0.334760]   <idle>-0       0dp.. 180810us : vmalloc_init <-start_kernel

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

function tracing starts here <<<<<<<<<<<<<<<<<<<<<<<<<<

[    0.335225]   <idle>-0       0dp.1 180810us : sched_init <-start_kernel
[    0.335626]   <idle>-0       0dp.1 180810us : wait_bit_init <-sched_init
[    0.336015]   <idle>-0       0dp.1 180810us : hrtimer_init  
<-init_rt_bandwidth
[    0.336500]   <idle>-0       0dp.1 180810us : __hrtimer_init <-hrtimer_init
[    0.336981]   <idle>-0       0dp.1 180810us : cpudl_init <-init_rootdomain
[    0.337381]   <idle>-0       0dp.1 180810us : cpupri_init <-init_rootdomain