[net-next PATCH] net: core: Add napi_complete_done tracepoint

[net-next PATCH] net: core: Add napi_complete_done tracepoint

[Joe Damato]

Add a tracepoint to help debug napi_complete_done. Users who set
defer_hard_irqs and the GRO timer can use this tracepoint to better
understand what impact these options have when their NIC driver calls
napi_complete_done.

perf trace can be used to enable the tracepoint and the output can be
examined to determine which settings should be adjusted.

$ sudo perf trace -e napi:napi_complete_done -a --call-graph=fp --libtraceevent_print

356.774 :0/0 napi:napi_complete_done(napi_complete_done on napi struct 0xffff88e052f02010 dev vlan100 irq_defers_remaining 2 timeout 20000 work_done 0 ret 0)
	napi_complete_done ([kernel.kallsyms])
	napi_complete_done ([kernel.kallsyms])
	i40e_napi_poll ([i40e])
	__napi_poll ([kernel.kallsyms])
	net_rx_action ([kernel.kallsyms])
	__do_softirq ([kernel.kallsyms])
	sysvec_apic_timer_interrupt ([kernel.kallsyms])
	asm_sysvec_apic_timer_interrupt ([kernel.kallsyms])
	intel_idle_irq ([kernel.kallsyms])
	cpuidle_enter_state ([kernel.kallsyms])
	cpuidle_enter ([kernel.kallsyms])
	do_idle ([kernel.kallsyms])
	cpu_startup_entry ([kernel.kallsyms])
	[0x243d98] ([kernel.kallsyms])
	secondary_startup_64_no_verify ([kernel.kallsyms])

Signed-off-by: Joe Damato <jdamato@fastly.com>
---
 include/trace/events/napi.h | 29 +++++++++++++++++++++++++++++
 net/core/dev.c              |  2 ++
 2 files changed, 31 insertions(+)

diff --git a/include/trace/events/napi.h b/include/trace/events/napi.h
index 6678cf8..e8473d3 100644
--- a/include/trace/events/napi.h
+++ b/include/trace/events/napi.h
@@ -11,6 +11,35 @@
 
 #define NO_DEV "(no_device)"
 
+TRACE_EVENT(napi_complete_done,
+	TP_PROTO(struct napi_struct *napi, int hard_irq_defer, unsigned long timeout,
+		int work_done, bool ret),
+
+	TP_ARGS(napi, hard_irq_defer, timeout, work_done, ret),
+
+	TP_STRUCT__entry(
+		__field(	struct napi_struct *,	napi)
+		__string(	dev_name,  napi->dev ? napi->dev->name : NO_DEV)
+		__field(	int,			hard_irq_defer)
+		__field(	unsigned long,		timeout)
+		__field(	int,			work_done)
+		__field(	int,			ret)
+	),
+
+	TP_fast_assign(
+		__entry->napi = napi;
+		__assign_str(dev_name, napi->dev ? napi->dev->name : NO_DEV);
+		__entry->hard_irq_defer = hard_irq_defer;
+		__entry->timeout = timeout;
+		__entry->work_done = work_done;
+		__entry->ret = ret;
+	),
+
+	TP_printk("napi_complete_done on napi struct %p dev %s irq_defers_remaining %d timeout %lu work_done %d ret %d",
+		__entry->napi, __get_str(dev_name), __entry->hard_irq_defer,
+		__entry->timeout, __entry->work_done, __entry->ret)
+);
+
 TRACE_EVENT(napi_poll,
 
 	TP_PROTO(struct napi_struct *napi, int work, int budget),
diff --git a/net/core/dev.c b/net/core/dev.c
index fa53830..e601f97 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -6091,6 +6091,8 @@ bool napi_complete_done(struct napi_struct *n, int work_done)
 	if (timeout)
 		hrtimer_start(&n->timer, ns_to_ktime(timeout),
 			      HRTIMER_MODE_REL_PINNED);
+
+	trace_napi_complete_done(n, n->defer_hard_irqs_count, timeout, work_done, ret);
 	return ret;
 }
 EXPORT_SYMBOL(napi_complete_done);
-- 
2.7.4

Re: [net-next PATCH] net: core: Add napi_complete_done tracepoint

[Jakub Kicinski]

On Mon, 10 Oct 2022 11:21:34 -0700 Joe Damato wrote:
> Add a tracepoint to help debug napi_complete_done. Users who set
> defer_hard_irqs and the GRO timer can use this tracepoint to better
> understand what impact these options have when their NIC driver calls
> napi_complete_done.
> 
> perf trace can be used to enable the tracepoint and the output can be
> examined to determine which settings should be adjusted.

Are you familiar with bpftrace, and it's ability to attach to kfunc 
and kretfunc? We mostly add tracepoints to static functions which get
inlined these days.

Re: [net-next PATCH] net: core: Add napi_complete_done tracepoint

[Joe Damato]

On Mon, Oct 10, 2022 at 05:58:24PM -0700, Jakub Kicinski wrote:
> On Mon, 10 Oct 2022 11:21:34 -0700 Joe Damato wrote:
> > Add a tracepoint to help debug napi_complete_done. Users who set
> > defer_hard_irqs and the GRO timer can use this tracepoint to better
> > understand what impact these options have when their NIC driver calls
> > napi_complete_done.
> > 
> > perf trace can be used to enable the tracepoint and the output can be
> > examined to determine which settings should be adjusted.
> 
> Are you familiar with bpftrace, and it's ability to attach to kfunc 
> and kretfunc? We mostly add tracepoints to static functions which get
> inlined these days.

Fair enough; I'll avoid sending patches like that in the future. It's been
helpful for me, but point taken. Sorry for the noise.