Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
From:   Joe Damato <jdamato@fastly.com>
To:     netdev@vger.kernel.org
Cc:     kuba@kernel.org, davem@davemloft.net, edumazet@google.com,
        linux-kernel@vger.kernel.org, Joe Damato <jdamato@fastly.com>
Subject: [net-next PATCH] net: core: Add napi_complete_done tracepoint
Date:   Mon, 10 Oct 2022 11:21:34 -0700
Message-Id: <1665426094-88160-1-git-send-email-jdamato@fastly.com>
Precedence: bulk

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