[bpf-next] bpf: use O(log(N)) binary search to find line info record

Commit Message

Andrii Nakryiko Feb. 14, 2024, 12:23 a.m. UTC

Real-world BPF applications keep growing in size. Medium-sized production
application can easily have 50K+ verified instructions, and its line
info section in .BTF.ext has more than 3K entries.

When verifier emits log with log_level>=1, it annotates assembly code
with matched original C source code. Currently it uses linear search
over line info records to find a match. As complexity of BPF
applications grows, this O(K * N) approach scales poorly.

So, let's instead of linear O(N) search for line info record use faster
equivalent O(log(N)) binary search algorithm. It's not a plain binary
search, as we don't look for exact match. It's an upper bound search
variant, looking for rightmost line info record that starts at or before
given insn_off.

Some unscientific measurements were done before and after this change.
They were done in VM and fluctuate a bit, but overall the speed up is
undeniable.

BASELINE
========
File                              Program           Duration (us)   Insns
--------------------------------  ----------------  -------------  ------
katran.bpf.o                      balancer_ingress        2497130  343552
pyperf600.bpf.linked3.o           on_event               12389611  627288
strobelight_pyperf_libbpf.o       on_py_event              387399   52445
--------------------------------  ----------------  -------------  ------

BINARY SEARCH
=============

File                              Program           Duration (us)   Insns
--------------------------------  ----------------  -------------  ------
katran.bpf.o                      balancer_ingress        2339312  343552
pyperf600.bpf.linked3.o           on_event                5602203  627288
strobelight_pyperf_libbpf.o       on_py_event              294761   52445
--------------------------------  ----------------  -------------  ------

While Katran's speed up is pretty modest (about 105ms, or 6%), for
production pyperf BPF program (on_py_event) it's much greater already,
going from 387ms down to 295ms (23% improvement).

Looking at BPF selftests's biggest pyperf example, we can see even more
dramatic improvement, shaving more than 50% of time, going from 12.3s
down to 5.6s.

Different amount of improvement is the function of overall amount of BPF
assembly instructions in .bpf.o files (which contributes to how much
line info records there will be and thus, on average, how much time linear
search will take), among other things:

$ llvm-objdump -d katran.bpf.o | wc -l
3863
$ llvm-objdump -d strobelight_pyperf_libbpf.o | wc -l
6997
$ llvm-objdump -d pyperf600.bpf.linked3.o | wc -l
87854

Granted, this only applies to debugging cases (e.g., using veristat, or
failing verification in production), but seems worth doing to improve
overall developer experience anyways.

Signed-off-by: Andrii Nakryiko <[e-mail]>
---
 kernel/bpf/log.c | 30 +++++++++++++++++++++++++-----
 1 file changed, 25 insertions(+), 5 deletions(-)

Comments

Jiri Olsa Feb. 14, 2024, 11:28 a.m. UTC | #1

On Tue, Feb 13, 2024 at 04:23:11PM -0800, Andrii Nakryiko wrote:
> Real-world BPF applications keep growing in size. Medium-sized production
> application can easily have 50K+ verified instructions, and its line
> info section in .BTF.ext has more than 3K entries.
> 
> When verifier emits log with log_level>=1, it annotates assembly code
> with matched original C source code. Currently it uses linear search
> over line info records to find a match. As complexity of BPF
> applications grows, this O(K * N) approach scales poorly.
> 
> So, let's instead of linear O(N) search for line info record use faster
> equivalent O(log(N)) binary search algorithm. It's not a plain binary
> search, as we don't look for exact match. It's an upper bound search
> variant, looking for rightmost line info record that starts at or before
> given insn_off.
> 
> Some unscientific measurements were done before and after this change.
> They were done in VM and fluctuate a bit, but overall the speed up is
> undeniable.
> 
> BASELINE
> ========
> File                              Program           Duration (us)   Insns
> --------------------------------  ----------------  -------------  ------
> katran.bpf.o                      balancer_ingress        2497130  343552
> pyperf600.bpf.linked3.o           on_event               12389611  627288
> strobelight_pyperf_libbpf.o       on_py_event              387399   52445
> --------------------------------  ----------------  -------------  ------
> 
> BINARY SEARCH
> =============
> 
> File                              Program           Duration (us)   Insns
> --------------------------------  ----------------  -------------  ------
> katran.bpf.o                      balancer_ingress        2339312  343552
> pyperf600.bpf.linked3.o           on_event                5602203  627288
> strobelight_pyperf_libbpf.o       on_py_event              294761   52445
> --------------------------------  ----------------  -------------  ------
> 
> While Katran's speed up is pretty modest (about 105ms, or 6%), for
> production pyperf BPF program (on_py_event) it's much greater already,
> going from 387ms down to 295ms (23% improvement).
> 
> Looking at BPF selftests's biggest pyperf example, we can see even more
> dramatic improvement, shaving more than 50% of time, going from 12.3s
> down to 5.6s.

nice speedup

Acked-by: Jiri Olsa <[e-mail]>

jirka

> 
> Different amount of improvement is the function of overall amount of BPF
> assembly instructions in .bpf.o files (which contributes to how much
> line info records there will be and thus, on average, how much time linear
> search will take), among other things:
> 
> $ llvm-objdump -d katran.bpf.o | wc -l
> 3863
> $ llvm-objdump -d strobelight_pyperf_libbpf.o | wc -l
> 6997
> $ llvm-objdump -d pyperf600.bpf.linked3.o | wc -l
> 87854
> 
> Granted, this only applies to debugging cases (e.g., using veristat, or
> failing verification in production), but seems worth doing to improve
> overall developer experience anyways.
> 
> Signed-off-by: Andrii Nakryiko <[e-mail]>
> ---
>  kernel/bpf/log.c | 30 +++++++++++++++++++++++++-----
>  1 file changed, 25 insertions(+), 5 deletions(-)
> 
> diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
> index 594a234f122b..2dfac246a27d 100644
> --- a/kernel/bpf/log.c
> +++ b/kernel/bpf/log.c
> @@ -333,7 +333,8 @@ find_linfo(const struct bpf_verifier_env *env, u32 insn_off)
>  {
>  	const struct bpf_line_info *linfo;
>  	const struct bpf_prog *prog;
> -	u32 i, nr_linfo;
> +	u32 nr_linfo;
> +	int l, r, m;
>  
>  	prog = env->prog;
>  	nr_linfo = prog->aux->nr_linfo;
> @@ -342,11 +343,30 @@ find_linfo(const struct bpf_verifier_env *env, u32 insn_off)
>  		return NULL;
>  
>  	linfo = prog->aux->linfo;
> -	for (i = 1; i < nr_linfo; i++)
> -		if (insn_off < linfo[i].insn_off)
> -			break;
> +	/* Loop invariant: linfo[l].insn_off <= insns_off.
> +	 * linfo[0].insn_off == 0 which always satisfies above condition.
> +	 * Binary search is searching for rightmost linfo entry that satisfies
> +	 * the above invariant, giving us the desired record that covers given
> +	 * instruction offset.
> +	 */
> +	l = 0;
> +	r = nr_linfo - 1;
> +	while (l < r) {
> +		/* (r - l + 1) / 2 means we break a tie to the right, so if:
> +		 * l=1, r=2, linfo[l].insn_off <= insn_off, linfo[r].insn_off > insn_off,
> +		 * then m=2, we see that linfo[m].insn_off > insn_off, and so
> +		 * r becomes 1 and we exit the loop with correct l==1.
> +		 * If the tie was broken to the left, m=1 would end us up in
> +		 * an endless loop where l and m stay at 1 and r stays at 2.
> +		 */
> +		m = l + (r - l + 1) / 2;
> +		if (linfo[m].insn_off <= insn_off)
> +			l = m;
> +		else
> +			r = m - 1;
> +	}
>  
> -	return &linfo[i - 1];
> +	return &linfo[l];
>  }
>  
>  static const char *ltrim(const char *s)
> -- 
> 2.39.3
> 
>

[e-mail] Feb. 14, 2024, 11 p.m. UTC | #2

Hello:

This patch was applied to bpf/bpf-next.git (master)
by Daniel Borkmann <[e-mail]>:

On Tue, 13 Feb 2024 16:23:11 -0800 you wrote:
> Real-world BPF applications keep growing in size. Medium-sized production
> application can easily have 50K+ verified instructions, and its line
> info section in .BTF.ext has more than 3K entries.
> 
> When verifier emits log with log_level>=1, it annotates assembly code
> with matched original C source code. Currently it uses linear search
> over line info records to find a match. As complexity of BPF
> applications grows, this O(K * N) approach scales poorly.
> 
> [...]

Here is the summary with links:
  - [bpf-next] bpf: use O(log(N)) binary search to find line info record
    https://git.kernel.org/bpf/bpf-next/c/a4561f5afef8

You are awesome, thank you!

Patch

diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
index 594a234f122b..2dfac246a27d 100644
--- a/kernel/bpf/log.c
+++ b/kernel/bpf/log.c
@@ -333,7 +333,8 @@  find_linfo(const struct bpf_verifier_env *env, u32 insn_off)
 {
 	const struct bpf_line_info *linfo;
 	const struct bpf_prog *prog;
-	u32 i, nr_linfo;
+	u32 nr_linfo;
+	int l, r, m;
 
 	prog = env->prog;
 	nr_linfo = prog->aux->nr_linfo;
@@ -342,11 +343,30 @@  find_linfo(const struct bpf_verifier_env *env, u32 insn_off)
 		return NULL;
 
 	linfo = prog->aux->linfo;
-	for (i = 1; i < nr_linfo; i++)
-		if (insn_off < linfo[i].insn_off)
-			break;
+	/* Loop invariant: linfo[l].insn_off <= insns_off.
+	 * linfo[0].insn_off == 0 which always satisfies above condition.
+	 * Binary search is searching for rightmost linfo entry that satisfies
+	 * the above invariant, giving us the desired record that covers given
+	 * instruction offset.
+	 */
+	l = 0;
+	r = nr_linfo - 1;
+	while (l < r) {
+		/* (r - l + 1) / 2 means we break a tie to the right, so if:
+		 * l=1, r=2, linfo[l].insn_off <= insn_off, linfo[r].insn_off > insn_off,
+		 * then m=2, we see that linfo[m].insn_off > insn_off, and so
+		 * r becomes 1 and we exit the loop with correct l==1.
+		 * If the tie was broken to the left, m=1 would end us up in
+		 * an endless loop where l and m stay at 1 and r stays at 2.
+		 */
+		m = l + (r - l + 1) / 2;
+		if (linfo[m].insn_off <= insn_off)
+			l = m;
+		else
+			r = m - 1;
+	}
 
-	return &linfo[i - 1];
+	return &linfo[l];
 }
 
 static const char *ltrim(const char *s)