tracing: Fix duration calculation bug (rettime - calltime) on ARM architecture

This issue is reproducible on the QEMU vexpress-a9 platform with the following steps:

Step 1: Launch the QEMU vexpress-a9 VM

~# qemu-system-arm -M vexpress-a9 -smp 1 -m 256 -kernel zImage -dtb \
	vexpress-v2p-ca9.dtb -drive file=rootfs.ext2,if=sd,format=raw \
	-append "console=ttyAMA0,115200 rootwait" -net nic,model=lan9118 \
	-net user -serial stdio

Step 2: Capture and view the trace with trace-cmd

~# trace-cmd record -p function_graph -g do_open_execat \
	--max-graph-depth 1 dd if=/dev/zero of=/tmp/1.bin \
	bs=1M count=1

~# trace-cmd report

Step 3: Observed behavior

Before:

dd-89 ... 5.764026: funcgraph_entry: $ 2757369004 us | do_open_execat()
dd-89 ... 5.765222: funcgraph_entry: $ 2034790547 us | do_open_execat();

After:

dd-91 ... 891.945577: funcgraph_entry: ! 185.542 us | do_open_execat();
dd-91 ... 891.946840: funcgraph_entry: + 98.625 us | do_open_execat();

Signed-off-by jempty.liang <[email protected]>

---
 include/linux/ftrace.h               |  2 ++
 kernel/trace/trace_entries.h         |  8 ++++----
 kernel/trace/trace_functions_graph.c | 19 +++++++++----------
 3 files changed, 15 insertions(+), 14 deletions(-)

include/linux/ftrace.h +2 -0

index a3a8989e3268..52727a342273 100644
@@ -1191,6 +1191,8 @@ struct ftrace_graph_ret {
 	int depth;
 	/* Number of functions that overran the depth limit for current task */
 	unsigned int overrun;
+	unsigned long long calltime;
+	unsigned long long rettime;
 } __packed;
 
 struct fgraph_ops;

kernel/trace/trace_entries.h +4 -4

index f6a8d29c0d76..362a757e65a2 100644
@@ -127,8 +127,8 @@ FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
 		__field_packed(	unsigned long,	ret,		retval	)
 		__field_packed(	unsigned int,	ret,		depth	)
 		__field_packed(	unsigned int,	ret,		overrun	)
-		__field(unsigned long long,	calltime		)
-		__field(unsigned long long,	rettime			)
+		__field_packed(unsigned long long,	ret,	calltime)
+		__field_packed(unsigned long long,	ret,	rettime)
 	),
 
 	F_printk("<-- %ps (%u) (start: %llx  end: %llx) over: %u retval: %lx",

@@ -149,8 +149,8 @@ FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
 		__field_packed(	unsigned long,	ret,		func	)
 		__field_packed(	unsigned int,	ret,		depth	)
 		__field_packed(	unsigned int,	ret,		overrun	)
-		__field(unsigned long long,	calltime		)
-		__field(unsigned long long,	rettime			)
+		__field_packed(unsigned long long,	ret,	calltime)
+		__field_packed(unsigned long long,	ret,	rettime)
 	),
 
 	F_printk("<-- %ps (%u) (start: %llx  end: %llx) over: %u",

kernel/trace/trace_functions_graph.c +0 -0

index 1de6f1573621..5798aeb31f05 100644

kernel/trace/trace_functions_graph.c +3 -4

@@ -346,8 +348,8 @@ void __trace_graph_return(struct trace_array *tr,
 		return;
 	entry	= ring_buffer_event_data(event);
 	entry->ret				= *trace;
-	entry->calltime				= calltime;
-	entry->rettime				= rettime;
+	entry->ret.calltime				= calltime;
+	entry->ret.rettime				= rettime;
 	trace_buffer_unlock_commit_nostack(buffer, event);
 }
 

@@ -372,10 +374,9 @@ void trace_graph_return(struct ftrace_graph_ret *trace,
 	struct trace_array *tr = gops->private;
 	struct fgraph_times *ftimes;
 	unsigned int trace_ctx;
-	u64 calltime, rettime;
 	int size;
 
-	rettime = trace_clock_local();
+	trace->rettime = trace_clock_local();
 
 	ftrace_graph_addr_finish(gops, trace);
 

kernel/trace/trace_functions_graph.c +1 -1

 }
 
 static void trace_graph_thresh_return(struct ftrace_graph_ret *trace,

@@ -956,7 +957,7 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 
 	graph_ret = &ret_entry->ret;
 	call = &entry->graph_ent;
-	duration = ret_entry->rettime - ret_entry->calltime;
+	duration = graph_ret->rettime - graph_ret->calltime;
 
 	if (data) {
 		struct fgraph_cpu_data *cpu_data;

Quoted 4 lines · On Fri, 30 Jan 2026 01:57:40 +0000 "jempty.liang" <[email protected]> wrote:

This issue is reproducible on the QEMU vexpress-a9 platform with the following steps:

Step 1: Launch the QEMU vexpress-a9 VM

How is this unique to arm? I'm not able to duplicate this on x86, but the code here is all generic code. What's different?

Quoted 6 lines

~# qemu-system-arm -M vexpress-a9 -smp 1 -m 256 -kernel zImage -dtb \
	vexpress-v2p-ca9.dtb -drive file=rootfs.ext2,if=sd,format=raw \
	-append "console=ttyAMA0,115200 rootwait" -net nic,model=lan9118 \
	-net user -serial stdio

Quoted 6 lines

Step 2: Capture and view the trace with trace-cmd

~# trace-cmd record -p function_graph -g do_open_execat \
	--max-graph-depth 1 dd if=/dev/zero of=/tmp/1.bin \
	bs=1M count=1

~# trace-cmd report

Note, you are using trace-cmd that records the raw data directly thus some of the updates to the prints below wouldn't affect this.

Quoted 5 lines

Step 3: Observed behavior

Before:

Quoted 7 lines

dd-89 ... 5.764026: funcgraph_entry: $ 2757369004 us | do_open_execat()
dd-89 ... 5.765222: funcgraph_entry: $ 2034790547 us | do_open_execat();

After:

dd-91 ... 891.945577: funcgraph_entry: ! 185.542 us | do_open_execat();
dd-91 ... 891.946840: funcgraph_entry: + 98.625 us | do_open_execat();

You show what the wrong output is and the correct output, but you don't mention what was the bug and how this fixes it. From the change log, it looks like you just tried something and it worked, but do not know why it worked.

I'd like to know what the bug was and how this fixes it. It's not obvious.

Quoted 52 lines

Signed-off-by jempty.liang <[email protected]>

---
 include/linux/ftrace.h               |  2 ++
 kernel/trace/trace_entries.h         |  8 ++++----
 kernel/trace/trace_functions_graph.c | 19 +++++++++----------
 3 files changed, 15 insertions(+), 14 deletions(-)

include/linux/ftrace.h +2 -0

index a3a8989e3268..52727a342273 100644
@@ -1191,6 +1191,8 @@ struct ftrace_graph_ret {
 	int depth;
 	/* Number of functions that overran the depth limit for current task */
 	unsigned int overrun;
+	unsigned long long calltime;
+	unsigned long long rettime;
 } __packed;
 
 struct fgraph_ops;

kernel/trace/trace_entries.h +4 -4

index f6a8d29c0d76..362a757e65a2 100644
@@ -127,8 +127,8 @@ FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
 		__field_packed(	unsigned long,	ret,		retval	)
 		__field_packed(	unsigned int,	ret,		depth	)
 		__field_packed(	unsigned int,	ret,		overrun	)
-		__field(unsigned long long,	calltime		)
-		__field(unsigned long long,	rettime			)
+		__field_packed(unsigned long long,	ret,	calltime)
+		__field_packed(unsigned long long,	ret,	rettime)
 	),
 
 	F_printk("<-- %ps (%u) (start: %llx  end: %llx) over: %u retval: %lx",

@@ -149,8 +149,8 @@ FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
 		__field_packed(	unsigned long,	ret,		func	)
 		__field_packed(	unsigned int,	ret,		depth	)
 		__field_packed(	unsigned int,	ret,		overrun	)
-		__field(unsigned long long,	calltime		)
-		__field(unsigned long long,	rettime			)
+		__field_packed(unsigned long long,	ret,	calltime)
+		__field_packed(unsigned long long,	ret,	rettime)
 	),
 
 	F_printk("<-- %ps (%u) (start: %llx  end: %llx) over: %u",

kernel/trace/trace_functions_graph.c +0 -0

index 1de6f1573621..5798aeb31f05 100644

kernel/trace/trace_functions_graph.c __trace_graph_function(struct trace_array *tr, · line 321

Quoted 5 lines

kernel/trace/trace_functions_graph.c +2 -0

@@ -317,6 +317,8 @@ __trace_graph_function(struct trace_array *tr,
 	struct ftrace_graph_ret ret = {
 		.func     = ip,
 		.depth    = 0,
+		.calltime = time,
+		.rettime = time,

If you assign here, then you should change the line below this code.

kernel/trace/trace_functions_graph.c __trace_graph_function(struct trace_array *tr, · line 324

Quoted 3 lines

kernel/trace/trace_functions_graph.c +0 -0

 	};
 
 	__trace_graph_entry(tr, &ent, trace_ctx);

The next line is this:

	__trace_graph_return(tr, &ret, trace_ctx, time, time);

Where that function has:

	entry->ret				= *trace;
	entry->ret.calltime				= calltime;
	entry->ret.rettime				= rettime;

That is, ret is assigned "*trace" which includes the calltime and rettime, and now it's doing more work to override it with the current data?

Quoted 30 lines

kernel/trace/trace_functions_graph.c +4 -5

@@ -346,8 +348,8 @@ void __trace_graph_return(struct trace_array *tr,
 		return;
 	entry	= ring_buffer_event_data(event);
 	entry->ret				= *trace;
-	entry->calltime				= calltime;
-	entry->rettime				= rettime;
+	entry->ret.calltime				= calltime;
+	entry->ret.rettime				= rettime;
 	trace_buffer_unlock_commit_nostack(buffer, event);
 }
 

@@ -372,10 +374,9 @@ void trace_graph_return(struct ftrace_graph_ret *trace,
 	struct trace_array *tr = gops->private;
 	struct fgraph_times *ftimes;
 	unsigned int trace_ctx;
-	u64 calltime, rettime;
 	int size;
 
-	rettime = trace_clock_local();
+	trace->rettime = trace_clock_local();
 
 	ftrace_graph_addr_finish(gops, trace);
 

@@ -390,10 +391,10 @@ void trace_graph_return(struct ftrace_graph_ret *trace,
 
 	handle_nosleeptime(tr, trace, ftimes, size);
 
-	calltime = ftimes->calltime;
+	trace->calltime = ftimes->calltime;
 

kernel/trace/trace_functions_graph.c void trace_graph_return(struct ftrace_graph_ret *trace, · line 397

Quoted 3 lines

kernel/trace/trace_functions_graph.c +1 -1

 	trace_ctx = tracing_gen_ctx();
-	__trace_graph_return(tr, trace, trace_ctx, calltime, rettime);
+	__trace_graph_return(tr, trace, trace_ctx, trace->calltime, trace->rettime);

And here again, the passed in calltime and rettime is just being overwritten.

Quoted 19 lines

kernel/trace/trace_functions_graph.c +1 -4

 }
 
 static void trace_graph_thresh_return(struct ftrace_graph_ret *trace,

@@ -956,7 +957,7 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 
 	graph_ret = &ret_entry->ret;
 	call = &entry->graph_ent;
-	duration = ret_entry->rettime - ret_entry->calltime;
+	duration = graph_ret->rettime - graph_ret->calltime;
 
 	if (data) {
 		struct fgraph_cpu_data *cpu_data;

@@ -1280,9 +1281,7 @@ print_graph_return(struct ftrace_graph_ret_entry *retentry, struct trace_seq *s,
 		   u32 flags)
 {
 	struct ftrace_graph_ret *trace = &retentry->ret;
-	u64 calltime = retentry->calltime;
-	u64 rettime = retentry->rettime;
-	unsigned long long duration = rettime - calltime;

kernel/trace/trace_functions_graph.c print_graph_return(struct ftrace_graph_ret_entry *retentry, struct trace_seq *s, · line 1287

Quoted 4 lines

kernel/trace/trace_functions_graph.c +1 -0

+	unsigned long long duration = trace->rettime - trace->calltime;
 	struct fgraph_data *data = iter->private;
 	struct trace_array *tr = iter->tr;
 	unsigned long func;

Now moving rettime and calltime into ftrace_graph_ret may be a nice cleanup, but you are saying this is a fix. What was the bug, and what did this fix?

-- Steve

Quoted 4 lines

How is this unique to arm? I'm not able to duplicate this on x86, but the code here is all generic code. What's different?

You're right, this bug is only reproducible on ARM.

Quoted 7 lines

You show what the wrong output is and the correct output, but you don't mention what was the bug and how this fixes it. From the change log, it looks like you just tried something and it worked, but do not know why it worked.

Quoted 3 lines

I'd like to know what the bug was and how this fixes it. It's not obvious.

Before the patch, do_open_execat had an abnormal execution duration of 2757369004 us (over 1 second); the patch resolves this and restores the function to a normal duration range.