2021-08-21 12:16:50

by Tiezhu Yang

Subject: [PATCH bpf-next] bpf: test_bpf: Print total time of test in the summary

The total time of test is useful to compare the performance
when bpf_jit_enable is 0 or 1, so print it in the summary.

Signed-off-by: Tiezhu Yang <[email protected]>
---
lib/test_bpf.c | 27 +++++++++++++++++++++------
1 file changed, 21 insertions(+), 6 deletions(-)

diff --git a/lib/test_bpf.c b/lib/test_bpf.c
index 830a18e..b1b17ba 100644
--- a/lib/test_bpf.c
+++ b/lib/test_bpf.c
@@ -8920,6 +8920,9 @@ static __init int test_skb_segment_single(const struct skb_segment_test *test)
static __init int test_skb_segment(void)
{
int i, err_cnt = 0, pass_cnt = 0;
+ u64 start, finish;
+
+ start = ktime_get_ns();

for (i = 0; i < ARRAY_SIZE(skb_segment_tests); i++) {
const struct skb_segment_test *test = &skb_segment_tests[i];
@@ -8935,8 +8938,10 @@ static __init int test_skb_segment(void)
}
}

- pr_info("%s: Summary: %d PASSED, %d FAILED\n", __func__,
- pass_cnt, err_cnt);
+ finish = ktime_get_ns();
+
+ pr_info("%s: Summary: %d PASSED, %d FAILED in %llu nsec\n",
+ __func__, pass_cnt, err_cnt, finish - start);
return err_cnt ? -EINVAL : 0;
}

@@ -8944,6 +8949,9 @@ static __init int test_bpf(void)
{
int i, err_cnt = 0, pass_cnt = 0;
int jit_cnt = 0, run_cnt = 0;
+ u64 start, finish;
+
+ start = ktime_get_ns();

for (i = 0; i < ARRAY_SIZE(tests); i++) {
struct bpf_prog *fp;
@@ -8983,8 +8991,10 @@ static __init int test_bpf(void)
}
}

- pr_info("Summary: %d PASSED, %d FAILED, [%d/%d JIT'ed]\n",
- pass_cnt, err_cnt, jit_cnt, run_cnt);
+ finish = ktime_get_ns();
+
+ pr_info("Summary: %d PASSED, %d FAILED, [%d/%d JIT'ed] in %llu nsec\n",
+ pass_cnt, err_cnt, jit_cnt, run_cnt, finish - start);

return err_cnt ? -EINVAL : 0;
}
@@ -9192,6 +9202,9 @@ static __init int test_tail_calls(struct bpf_array *progs)
{
int i, err_cnt = 0, pass_cnt = 0;
int jit_cnt = 0, run_cnt = 0;
+ u64 start, finish;
+
+ start = ktime_get_ns();

for (i = 0; i < ARRAY_SIZE(tail_call_tests); i++) {
struct tail_call_test *test = &tail_call_tests[i];
@@ -9222,8 +9235,10 @@ static __init int test_tail_calls(struct bpf_array *progs)
}
}

- pr_info("%s: Summary: %d PASSED, %d FAILED, [%d/%d JIT'ed]\n",
- __func__, pass_cnt, err_cnt, jit_cnt, run_cnt);
+ finish = ktime_get_ns();
+
+ pr_info("%s: Summary: %d PASSED, %d FAILED, [%d/%d JIT'ed] in %llu nsec\n",
+ __func__, pass_cnt, err_cnt, jit_cnt, run_cnt, finish - start);

return err_cnt ? -EINVAL : 0;
}
--
2.1.0

2021-08-23 15:50:10

by Daniel Borkmann

Subject: Re: [PATCH bpf-next] bpf: test_bpf: Print total time of test in the summary

On 8/21/21 2:13 PM, Tiezhu Yang wrote:
> The total time of test is useful to compare the performance
> when bpf_jit_enable is 0 or 1, so print it in the summary.
>
> Signed-off-by: Tiezhu Yang <[email protected]>
> ---
> lib/test_bpf.c | 27 +++++++++++++++++++++------
> 1 file changed, 21 insertions(+), 6 deletions(-)
>
> diff --git a/lib/test_bpf.c b/lib/test_bpf.c
> index 830a18e..b1b17ba 100644
> --- a/lib/test_bpf.c
> +++ b/lib/test_bpf.c
> @@ -8920,6 +8920,9 @@ static __init int test_skb_segment_single(const struct skb_segment_test *test)
> static __init int test_skb_segment(void)
> {
> int i, err_cnt = 0, pass_cnt = 0;
> + u64 start, finish;
> +
> + start = ktime_get_ns();
>
> for (i = 0; i < ARRAY_SIZE(skb_segment_tests); i++) {
> const struct skb_segment_test *test = &skb_segment_tests[i];
> @@ -8935,8 +8938,10 @@ static __init int test_skb_segment(void)
> }
> }
>
> - pr_info("%s: Summary: %d PASSED, %d FAILED\n", __func__,
> - pass_cnt, err_cnt);
> + finish = ktime_get_ns();
> +
> + pr_info("%s: Summary: %d PASSED, %d FAILED in %llu nsec\n",
> + __func__, pass_cnt, err_cnt, finish - start);
> return err_cnt ? -EINVAL : 0;
> }

I don't think this gives you any accurate results (e.g. what if this gets migrated
or preempted?); maybe rather use the duration from __run_one() ..

Thanks,
Daniel