[RFC PATCH bpf-next 0/2] Eliminate IRQ Time from BPF Program Running Duration

[RFC PATCH bpf-next 0/2] Eliminate IRQ Time from BPF Program Running Duration

[Jianlin Lv]

From: Jianlin Lv <iecedge@gmail.com>

Motivation:
===========
This proposal aims to enhance the __bpf_prog_run function by eliminating
IRQ time from the BPF program running duration. When a BPF program is
attached to a kernel function running in user context, any interrupts that
occur can lead to the BPF program's execution duration including the time
spent in interrupt handling. This results in an observed increase in CPU
usage attributed to eBPF.

Design:
=======
The elimination of IRQ time is built upon enabling 
CONFIG_IRQ_TIME_ACCOUNTING. Before a BPF program runs in user context,
call irq_time_read to record current total IRQ time for the CPU. After the
BPF program execution, call irq_time_read again to record the total IRQ
time. The difference between these two readings gives the IRQ handling
time for this BPF call. Then subtract the IRQ handling time from the
total BPF processing duration.

Currently, the irq_time_read function is defined as static, preventing its
use by other modules. This proposal suggests exporting irq_time_read for
use by the BPF module.

TODOs:
======
- Support elimination of IRQ time for BPF trampoline.
- Add selftests to validate the functionality.

this mail is mainly to get feedback on the design and implementation
approach. TODO item will be added in subsequent updates once we gather
input on the proposal.

Jianlin Lv (2):
  Enhance BPF execution timing by excluding IRQ time
  Export irq_time_read for BPF module usage

 include/linux/filter.h | 24 ++++++++++++++++++++++--
 include/linux/sched.h  |  4 ++++
 kernel/sched/core.c    | 22 ++++++++++++++++++++++
 kernel/sched/sched.h   | 19 -------------------
 4 files changed, 48 insertions(+), 21 deletions(-)

-- 
2.34.1

[RFC PATCH bpf-next 1/2] Enhance BPF execution timing by excluding IRQ time

[Jianlin Lv]

From: Jianlin Lv <iecedge@gmail.com>

This commit excludes IRQ time from the total execution duration of BPF
programs. When CONFIG_IRQ_TIME_ACCOUNTING is enabled, IRQ time is
accounted for separately, offering a more accurate assessment of CPU
usage for BPF programs.

Signed-off-by: Jianlin Lv <iecedge@gmail.com>
---
 include/linux/filter.h | 24 ++++++++++++++++++++++--
 1 file changed, 22 insertions(+), 2 deletions(-)

diff --git a/include/linux/filter.h b/include/linux/filter.h
index f5cf4d35d83e..3e0f975176a6 100644
--- a/include/linux/filter.h
+++ b/include/linux/filter.h
@@ -703,12 +703,32 @@ static __always_inline u32 __bpf_prog_run(const struct bpf_prog *prog,
 	cant_migrate();
 	if (static_branch_unlikely(&bpf_stats_enabled_key)) {
 		struct bpf_prog_stats *stats;
-		u64 duration, start = sched_clock();
+		u64 duration, start, start_time, end_time, irq_delta;
 		unsigned long flags;
+		unsigned int cpu;
 
-		ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
+		#ifdef CONFIG_IRQ_TIME_ACCOUNTING
+		if (in_task()) {
+			cpu = get_cpu();
+			put_cpu();
+			start_time = irq_time_read(cpu);
+		}
+		#endif
 
+		start = sched_clock();
+		ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
 		duration = sched_clock() - start;
+
+		#ifdef CONFIG_IRQ_TIME_ACCOUNTING
+		if (in_task()) {
+			end_time = irq_time_read(cpu);
+			if (end_time > start_time) {
+				irq_delta = end_time - start_time;
+				duration -= irq_delta;
+			}
+		}
+		#endif
+
 		stats = this_cpu_ptr(prog->stats);
 		flags = u64_stats_update_begin_irqsave(&stats->syncp);
 		u64_stats_inc(&stats->cnt);
-- 
2.34.1

[RFC PATCH bpf-next 2/2] Export irq_time_read for BPF module usage

[Jianlin Lv]

From: Jianlin Lv <iecedge@gmail.com>

Move irq_time_read function to kernel/sched/core.c and export for
external use when CONFIG_IRQ_TIME_ACCOUNTING is enabled.

Signed-off-by: Jianlin Lv <iecedge@gmail.com>
---
 include/linux/sched.h |  4 ++++
 kernel/sched/core.c   | 22 ++++++++++++++++++++++
 kernel/sched/sched.h  | 19 -------------------
 3 files changed, 26 insertions(+), 19 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index f96ac1982893..3b83ac99b533 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -2281,4 +2281,8 @@ static __always_inline void alloc_tag_restore(struct alloc_tag *tag, struct allo
 #define alloc_tag_restore(_tag, _old)		do {} while (0)
 #endif
 
+#ifdef CONFIG_IRQ_TIME_ACCOUNTING
+extern inline u64 irq_time_read(int cpu);
+#endif
+
 #endif
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index cfaca3040b2f..c840d1ffdaca 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -10747,3 +10747,25 @@ void sched_enq_and_set_task(struct sched_enq_and_set_ctx *ctx)
 		set_next_task(rq, ctx->p);
 }
 #endif	/* CONFIG_SCHED_CLASS_EXT */
+
+#ifdef CONFIG_IRQ_TIME_ACCOUNTING
+/*
+ * Returns the irqtime minus the softirq time computed by ksoftirqd.
+ * Otherwise ksoftirqd's sum_exec_runtime is subtracted its own runtime
+ * and never move forward.
+ */
+inline u64 irq_time_read(int cpu)
+{
+	struct irqtime *irqtime = &per_cpu(cpu_irqtime, cpu);
+	unsigned int seq;
+	u64 total;
+
+	do {
+		seq = __u64_stats_fetch_begin(&irqtime->sync);
+		total = irqtime->total;
+	} while (__u64_stats_fetch_retry(&irqtime->sync, seq));
+
+	return total;
+}
+EXPORT_SYMBOL(irq_time_read);
+#endif /* CONFIG_IRQ_TIME_ACCOUNTING */
diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
index 47972f34ea70..d2fd3772114e 100644
--- a/kernel/sched/sched.h
+++ b/kernel/sched/sched.h
@@ -3209,25 +3209,6 @@ static inline int irqtime_enabled(void)
 	return sched_clock_irqtime;
 }
 
-/*
- * Returns the irqtime minus the softirq time computed by ksoftirqd.
- * Otherwise ksoftirqd's sum_exec_runtime is subtracted its own runtime
- * and never move forward.
- */
-static inline u64 irq_time_read(int cpu)
-{
-	struct irqtime *irqtime = &per_cpu(cpu_irqtime, cpu);
-	unsigned int seq;
-	u64 total;
-
-	do {
-		seq = __u64_stats_fetch_begin(&irqtime->sync);
-		total = irqtime->total;
-	} while (__u64_stats_fetch_retry(&irqtime->sync, seq));
-
-	return total;
-}
-
 #else
 
 static inline int irqtime_enabled(void)
-- 
2.34.1

Re: [RFC PATCH bpf-next 1/2] Enhance BPF execution timing by excluding IRQ time

[Peter Zijlstra]

On Tue, Apr 22, 2025 at 09:47:26PM +0800, Jianlin Lv wrote:
> From: Jianlin Lv <iecedge@gmail.com>
> 
> This commit excludes IRQ time from the total execution duration of BPF
> programs. When CONFIG_IRQ_TIME_ACCOUNTING is enabled, IRQ time is
> accounted for separately, offering a more accurate assessment of CPU
> usage for BPF programs.
> 
> Signed-off-by: Jianlin Lv <iecedge@gmail.com>
> ---
>  include/linux/filter.h | 24 ++++++++++++++++++++++--
>  1 file changed, 22 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/filter.h b/include/linux/filter.h
> index f5cf4d35d83e..3e0f975176a6 100644
> --- a/include/linux/filter.h
> +++ b/include/linux/filter.h
> @@ -703,12 +703,32 @@ static __always_inline u32 __bpf_prog_run(const struct bpf_prog *prog,
>  	cant_migrate();
>  	if (static_branch_unlikely(&bpf_stats_enabled_key)) {
>  		struct bpf_prog_stats *stats;
> -		u64 duration, start = sched_clock();
> +		u64 duration, start, start_time, end_time, irq_delta;
>  		unsigned long flags;
> +		unsigned int cpu;
>  
> -		ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
> +		#ifdef CONFIG_IRQ_TIME_ACCOUNTING
> +		if (in_task()) {
> +			cpu = get_cpu();
> +			put_cpu();
> +			start_time = irq_time_read(cpu);

This is all sorts of daft.. you don't need get_cpu()/put_cpu().

> +		}
> +		#endif
>  
> +		start = sched_clock();
> +		ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
>  		duration = sched_clock() - start;
> +
> +		#ifdef CONFIG_IRQ_TIME_ACCOUNTING
> +		if (in_task()) {
> +			end_time = irq_time_read(cpu);
> +			if (end_time > start_time) {
> +				irq_delta = end_time - start_time;
> +				duration -= irq_delta;
> +			}
> +		}
> +		#endif

This is really dodgy coding style. Please keep the preprocessor
directives at column 0.

What do you think about steal-time, do you want to remove that from your
BPF runtime too?

If so, perhaps expose the scheduler's clock_task, which does both things
already?

Re: [RFC PATCH bpf-next 2/2] Export irq_time_read for BPF module usage

[Peter Zijlstra]

On Tue, Apr 22, 2025 at 09:47:27PM +0800, Jianlin Lv wrote:
> From: Jianlin Lv <iecedge@gmail.com>
> 
> Move irq_time_read function to kernel/sched/core.c and export for
> external use when CONFIG_IRQ_TIME_ACCOUNTING is enabled.
> 
> Signed-off-by: Jianlin Lv <iecedge@gmail.com>
> ---
>  include/linux/sched.h |  4 ++++
>  kernel/sched/core.c   | 22 ++++++++++++++++++++++
>  kernel/sched/sched.h  | 19 -------------------
>  3 files changed, 26 insertions(+), 19 deletions(-)
> 
> diff --git a/include/linux/sched.h b/include/linux/sched.h
> index f96ac1982893..3b83ac99b533 100644
> --- a/include/linux/sched.h
> +++ b/include/linux/sched.h
> @@ -2281,4 +2281,8 @@ static __always_inline void alloc_tag_restore(struct alloc_tag *tag, struct allo
>  #define alloc_tag_restore(_tag, _old)		do {} while (0)
>  #endif
>  
> +#ifdef CONFIG_IRQ_TIME_ACCOUNTING
> +extern inline u64 irq_time_read(int cpu);
> +#endif
> +
>  #endif
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index cfaca3040b2f..c840d1ffdaca 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -10747,3 +10747,25 @@ void sched_enq_and_set_task(struct sched_enq_and_set_ctx *ctx)
>  		set_next_task(rq, ctx->p);
>  }
>  #endif	/* CONFIG_SCHED_CLASS_EXT */
> +
> +#ifdef CONFIG_IRQ_TIME_ACCOUNTING
> +/*
> + * Returns the irqtime minus the softirq time computed by ksoftirqd.
> + * Otherwise ksoftirqd's sum_exec_runtime is subtracted its own runtime
> + * and never move forward.
> + */
> +inline u64 irq_time_read(int cpu)
> +{
> +	struct irqtime *irqtime = &per_cpu(cpu_irqtime, cpu);
> +	unsigned int seq;
> +	u64 total;
> +
> +	do {
> +		seq = __u64_stats_fetch_begin(&irqtime->sync);
> +		total = irqtime->total;
> +	} while (__u64_stats_fetch_retry(&irqtime->sync, seq));
> +
> +	return total;
> +}
> +EXPORT_SYMBOL(irq_time_read);

_GPL(), but as I've argued in the earlier email, I don't think you want
this. I think you want access to clock_task instead.

Re: [RFC PATCH bpf-next 1/2] Enhance BPF execution timing by excluding IRQ time

[Alexei Starovoitov]

On Tue, Apr 22, 2025 at 6:47 AM Jianlin Lv <iecedge@gmail.com> wrote:
>
> From: Jianlin Lv <iecedge@gmail.com>
>
> This commit excludes IRQ time from the total execution duration of BPF
> programs. When CONFIG_IRQ_TIME_ACCOUNTING is enabled, IRQ time is
> accounted for separately, offering a more accurate assessment of CPU
> usage for BPF programs.
>
> Signed-off-by: Jianlin Lv <iecedge@gmail.com>
> ---
>  include/linux/filter.h | 24 ++++++++++++++++++++++--
>  1 file changed, 22 insertions(+), 2 deletions(-)
>
> diff --git a/include/linux/filter.h b/include/linux/filter.h
> index f5cf4d35d83e..3e0f975176a6 100644
> --- a/include/linux/filter.h
> +++ b/include/linux/filter.h
> @@ -703,12 +703,32 @@ static __always_inline u32 __bpf_prog_run(const struct bpf_prog *prog,
>         cant_migrate();
>         if (static_branch_unlikely(&bpf_stats_enabled_key)) {
>                 struct bpf_prog_stats *stats;
> -               u64 duration, start = sched_clock();
> +               u64 duration, start, start_time, end_time, irq_delta;
>                 unsigned long flags;
> +               unsigned int cpu;
>
> -               ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
> +               #ifdef CONFIG_IRQ_TIME_ACCOUNTING
> +               if (in_task()) {
> +                       cpu = get_cpu();
> +                       put_cpu();
> +                       start_time = irq_time_read(cpu);
> +               }
> +               #endif
>
> +               start = sched_clock();
> +               ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
>                 duration = sched_clock() - start;
> +
> +               #ifdef CONFIG_IRQ_TIME_ACCOUNTING
> +               if (in_task()) {
> +                       end_time = irq_time_read(cpu);
> +                       if (end_time > start_time) {
> +                               irq_delta = end_time - start_time;
> +                               duration -= irq_delta;
> +                       }
> +               }
> +               #endif
> +

This is way too much overhead.
This timing loop is optimized to measure bpf prog runtime.
See commit ce09cbdd9888 ("bpf: Improve program stats run-time calculation")
IRQ can happen and distort the numbers, but you shouldn't
be running with bpf_stats_enabled for a long time.
You need to sample it instead.
Every couple minutes turn it on for a second, capture the stats
and aggregate over time. Filter out outliers due to IRQ or whatever.

Re: [RFC PATCH bpf-next 1/2] Enhance BPF execution timing by excluding IRQ time

[kernel test robot]

Hi Jianlin,

[This is a private test report for your RFC patch.]
kernel test robot noticed the following build warnings:

[auto build test WARNING on bpf-next/master]

url:    https://github.com/intel-lab-lkp/linux/commits/Jianlin-Lv/Enhance-BPF-execution-timing-by-excluding-IRQ-time/20250422-214957
base:   https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git master
patch link:    https://lore.kernel.org/r/73fdbbf9aafd3e24e12bb58f89c70959fb3a37f1.1745250534.git.iecedge%40gmail.com
patch subject: [RFC PATCH  bpf-next 1/2] Enhance BPF execution timing by excluding IRQ time
config: i386-buildonly-randconfig-001-20250423 (https://download.01.org/0day-ci/archive/20250423/202504231319.Ruutd2WV-lkp@intel.com/config)
compiler: gcc-12 (Debian 12.2.0-14) 12.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20250423/202504231319.Ruutd2WV-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202504231319.Ruutd2WV-lkp@intel.com/

All warnings (new ones prefixed by >>):

   In file included from kernel/kallsyms.c:25:
   include/linux/filter.h: In function '__bpf_prog_run':
>> include/linux/filter.h:708:30: warning: unused variable 'cpu' [-Wunused-variable]
     708 |                 unsigned int cpu;
         |                              ^~~
>> include/linux/filter.h:706:60: warning: unused variable 'irq_delta' [-Wunused-variable]
     706 |                 u64 duration, start, start_time, end_time, irq_delta;
         |                                                            ^~~~~~~~~
>> include/linux/filter.h:706:50: warning: unused variable 'end_time' [-Wunused-variable]
     706 |                 u64 duration, start, start_time, end_time, irq_delta;
         |                                                  ^~~~~~~~
>> include/linux/filter.h:706:38: warning: unused variable 'start_time' [-Wunused-variable]
     706 |                 u64 duration, start, start_time, end_time, irq_delta;
         |                                      ^~~~~~~~~~
   At top level:
   cc1: note: unrecognized command-line option '-Wno-unterminated-string-initialization' may have been intended to silence earlier diagnostics


vim +/cpu +708 include/linux/filter.h

   686	
   687	extern struct mutex nf_conn_btf_access_lock;
   688	extern int (*nfct_btf_struct_access)(struct bpf_verifier_log *log,
   689					     const struct bpf_reg_state *reg,
   690					     int off, int size);
   691	
   692	typedef unsigned int (*bpf_dispatcher_fn)(const void *ctx,
   693						  const struct bpf_insn *insnsi,
   694						  unsigned int (*bpf_func)(const void *,
   695									   const struct bpf_insn *));
   696	
   697	static __always_inline u32 __bpf_prog_run(const struct bpf_prog *prog,
   698						  const void *ctx,
   699						  bpf_dispatcher_fn dfunc)
   700	{
   701		u32 ret;
   702	
   703		cant_migrate();
   704		if (static_branch_unlikely(&bpf_stats_enabled_key)) {
   705			struct bpf_prog_stats *stats;
 > 706			u64 duration, start, start_time, end_time, irq_delta;
   707			unsigned long flags;
 > 708			unsigned int cpu;
   709	
   710			#ifdef CONFIG_IRQ_TIME_ACCOUNTING
   711			if (in_task()) {
   712				cpu = get_cpu();
   713				put_cpu();
   714				start_time = irq_time_read(cpu);
   715			}
   716			#endif
   717	
   718			start = sched_clock();
   719			ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
   720			duration = sched_clock() - start;
   721	
   722			#ifdef CONFIG_IRQ_TIME_ACCOUNTING
   723			if (in_task()) {
   724				end_time = irq_time_read(cpu);
   725				if (end_time > start_time) {
   726					irq_delta = end_time - start_time;
   727					duration -= irq_delta;
   728				}
   729			}
   730			#endif
   731	
   732			stats = this_cpu_ptr(prog->stats);
   733			flags = u64_stats_update_begin_irqsave(&stats->syncp);
   734			u64_stats_inc(&stats->cnt);
   735			u64_stats_add(&stats->nsecs, duration);
   736			u64_stats_update_end_irqrestore(&stats->syncp, flags);
   737		} else {
   738			ret = dfunc(ctx, prog->insnsi, prog->bpf_func);
   739		}
   740		return ret;
   741	}
   742	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki