hi,
I have tested v5.16-rc1 kernel bpf function by make run_tests -C tools/testing/selftests/bpf.
And found it cost above 5 hours.
Check dmesg and found that lib/test_bpf.ko cost so much time.
In tools/testing/selftests/bpf/test_kmod.sh insmod test_bpf.ko four times.
It took 40 seconds for the first three times.
When do 4th test among 1009 test cases from #812 ALU64_AND_K to #936 JMP_JSET_K every test case cost above 1 min.
Is it currently to cost so much time?
kern :info : [ 1127.985791] test_bpf: #811 ALU64_MOV_K: all immediate value magnitudes
kern :info : [ 1237.158485] test_bpf: #812 ALU64_AND_K: all immediate value magnitudes jited:1 127955 PASS
kern :info : [ 1341.638557] test_bpf: #813 ALU64_OR_K: all immediate value magnitudes jited:1 155039 PASS
kern :info : [ 1447.725483] test_bpf: #814 ALU64_XOR_K: all immediate value magnitudes jited:1 129621 PASS
kern :info : [ 1551.808683] test_bpf: #815 ALU64_ADD_K: all immediate value magnitudes jited:1 120428 PASS
kern :info : [ 1655.550594] test_bpf: #816 ALU64_SUB_K: all immediate value magnitudes jited:1 175712 PASS
......
kern :info : [16725.824950] test_bpf: #931 JMP32_JLE_X: all register value magnitudes jited:1 216508 PASS
kern :info : [16911.555675] test_bpf: #932 JMP32_JSGT_X: all register value magnitudes jited:1 178367 PASS
kern :info : [17101.466163] test_bpf: #933 JMP32_JSGE_X: all register value magnitudes jited:1 191436 PASS
kern :info : [17288.359154] test_bpf: #934 JMP32_JSLT_X: all register value magnitudes jited:1 165714 PASS
kern :info : [17480.615048] test_bpf: #935 JMP32_JSLE_X: all register value magnitudes jited:1 172846 PASS
kern :info : [17667.472140] test_bpf: #936 JMP_JSET_K: imm = 0 -> never taken jited:1 14 PASS
test_bpf.ko dmesg output is attached.
best regards,
ping
________________________________________
From: Zhou, Jie2X
Sent: Monday, November 29, 2021 3:36 PM
To: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Cc: [email protected]; [email protected]; [email protected]; Li, ZhijianX; Ma, XinjianX
Subject: kernel-selftests: make run_tests -C bpf cost 5 hours
hi,
I have tested v5.16-rc1 kernel bpf function by make run_tests -C tools/testing/selftests/bpf.
And found it cost above 5 hours.
Check dmesg and found that lib/test_bpf.ko cost so much time.
In tools/testing/selftests/bpf/test_kmod.sh insmod test_bpf.ko four times.
It took 40 seconds for the first three times.
When do 4th test among 1009 test cases from #812 ALU64_AND_K to #936 JMP_JSET_K every test case cost above 1 min.
Is it currently to cost so much time?
kern :info : [ 1127.985791] test_bpf: #811 ALU64_MOV_K: all immediate value magnitudes
kern :info : [ 1237.158485] test_bpf: #812 ALU64_AND_K: all immediate value magnitudes jited:1 127955 PASS
kern :info : [ 1341.638557] test_bpf: #813 ALU64_OR_K: all immediate value magnitudes jited:1 155039 PASS
kern :info : [ 1447.725483] test_bpf: #814 ALU64_XOR_K: all immediate value magnitudes jited:1 129621 PASS
kern :info : [ 1551.808683] test_bpf: #815 ALU64_ADD_K: all immediate value magnitudes jited:1 120428 PASS
kern :info : [ 1655.550594] test_bpf: #816 ALU64_SUB_K: all immediate value magnitudes jited:1 175712 PASS
......
kern :info : [16725.824950] test_bpf: #931 JMP32_JLE_X: all register value magnitudes jited:1 216508 PASS
kern :info : [16911.555675] test_bpf: #932 JMP32_JSGT_X: all register value magnitudes jited:1 178367 PASS
kern :info : [17101.466163] test_bpf: #933 JMP32_JSGE_X: all register value magnitudes jited:1 191436 PASS
kern :info : [17288.359154] test_bpf: #934 JMP32_JSLT_X: all register value magnitudes jited:1 165714 PASS
kern :info : [17480.615048] test_bpf: #935 JMP32_JSLE_X: all register value magnitudes jited:1 172846 PASS
kern :info : [17667.472140] test_bpf: #936 JMP_JSET_K: imm = 0 -> never taken jited:1 14 PASS
test_bpf.ko dmesg output is attached.
best regards,
On 12/1/21 7:54 AM, Zhou, Jie2X wrote:
> ping
>
> ________________________________________
> From: Zhou, Jie2X
> Sent: Monday, November 29, 2021 3:36 PM
> To: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
> Cc: [email protected]; [email protected]; [email protected]; Li, ZhijianX; Ma, XinjianX
> Subject: kernel-selftests: make run_tests -C bpf cost 5 hours
>
> hi,
>
> I have tested v5.16-rc1 kernel bpf function by make run_tests -C tools/testing/selftests/bpf.
> And found it cost above 5 hours.
>
> Check dmesg and found that lib/test_bpf.ko cost so much time.
> In tools/testing/selftests/bpf/test_kmod.sh insmod test_bpf.ko four times.
> It took 40 seconds for the first three times.
>
> When do 4th test among 1009 test cases from #812 ALU64_AND_K to #936 JMP_JSET_K every test case cost above 1 min.
> Is it currently to cost so much time?
>
> kern :info : [ 1127.985791] test_bpf: #811 ALU64_MOV_K: all immediate value magnitudes
> kern :info : [ 1237.158485] test_bpf: #812 ALU64_AND_K: all immediate value magnitudes jited:1 127955 PASS
> kern :info : [ 1341.638557] test_bpf: #813 ALU64_OR_K: all immediate value magnitudes jited:1 155039 PASS
> kern :info : [ 1447.725483] test_bpf: #814 ALU64_XOR_K: all immediate value magnitudes jited:1 129621 PASS
> kern :info : [ 1551.808683] test_bpf: #815 ALU64_ADD_K: all immediate value magnitudes jited:1 120428 PASS
> kern :info : [ 1655.550594] test_bpf: #816 ALU64_SUB_K: all immediate value magnitudes jited:1 175712 PASS
> ......
> kern :info : [16725.824950] test_bpf: #931 JMP32_JLE_X: all register value magnitudes jited:1 216508 PASS
> kern :info : [16911.555675] test_bpf: #932 JMP32_JSGT_X: all register value magnitudes jited:1 178367 PASS
> kern :info : [17101.466163] test_bpf: #933 JMP32_JSGE_X: all register value magnitudes jited:1 191436 PASS
> kern :info : [17288.359154] test_bpf: #934 JMP32_JSLT_X: all register value magnitudes jited:1 165714 PASS
> kern :info : [17480.615048] test_bpf: #935 JMP32_JSLE_X: all register value magnitudes jited:1 172846 PASS
> kern :info : [17667.472140] test_bpf: #936 JMP_JSET_K: imm = 0 -> never taken jited:1 14 PASS
>
> test_bpf.ko dmesg output is attached.
On my side, I'm seeing:
# time ./test_kmod.sh
[ JIT enabled:0 hardened:0 ]
[ 107.182567] test_bpf: Summary: 1009 PASSED, 0 FAILED, [0/997 JIT'ed]
[ 107.200319] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [0/8 JIT'ed]
[ 107.200379] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
[ JIT enabled:1 hardened:0 ]
[ 108.130568] test_bpf: Summary: 1009 PASSED, 0 FAILED, [997/997 JIT'ed]
[ 108.143447] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [8/8 JIT'ed]
[ 108.143510] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
[ JIT enabled:1 hardened:1 ]
[ 109.116727] test_bpf: Summary: 1009 PASSED, 0 FAILED, [997/997 JIT'ed]
[ 109.129915] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [8/8 JIT'ed]
[ 109.129979] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
[ JIT enabled:1 hardened:2 ]
[ 6617.952848] test_bpf: Summary: 1009 PASSED, 0 FAILED, [948/997 JIT'ed]
[ 6617.965936] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [8/8 JIT'ed]
[ 6617.966004] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
real 108m32.833s
user 0m0.031s
sys 108m17.939s
The hardened:2 run takes significantly longer due to excessive patching for the
jit constant blinding code. Maybe the test cases can be reduced for the latter,
otoh, it's good to know that they all pass as well.
Thanks,
Daniel
On Thu, Dec 2, 2021 at 10:26 AM Daniel Borkmann <[email protected]> wrote:
>
> On 12/1/21 7:54 AM, Zhou, Jie2X wrote:
> > ping
> >
> > ________________________________________
> > From: Zhou, Jie2X
> > Sent: Monday, November 29, 2021 3:36 PM
> > To: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
> > Cc: [email protected]; [email protected]; [email protected]; Li, ZhijianX; Ma, XinjianX
> > Subject: kernel-selftests: make run_tests -C bpf cost 5 hours
> >
> > hi,
> >
> > I have tested v5.16-rc1 kernel bpf function by make run_tests -C tools/testing/selftests/bpf.
> > And found it cost above 5 hours.
> >
> > Check dmesg and found that lib/test_bpf.ko cost so much time.
> > In tools/testing/selftests/bpf/test_kmod.sh insmod test_bpf.ko four times.
> > It took 40 seconds for the first three times.
> >
> > When do 4th test among 1009 test cases from #812 ALU64_AND_K to #936 JMP_JSET_K every test case cost above 1 min.
> > Is it currently to cost so much time?
> >
> > kern :info : [ 1127.985791] test_bpf: #811 ALU64_MOV_K: all immediate value magnitudes
> > kern :info : [ 1237.158485] test_bpf: #812 ALU64_AND_K: all immediate value magnitudes jited:1 127955 PASS
> > kern :info : [ 1341.638557] test_bpf: #813 ALU64_OR_K: all immediate value magnitudes jited:1 155039 PASS
> > kern :info : [ 1447.725483] test_bpf: #814 ALU64_XOR_K: all immediate value magnitudes jited:1 129621 PASS
> > kern :info : [ 1551.808683] test_bpf: #815 ALU64_ADD_K: all immediate value magnitudes jited:1 120428 PASS
> > kern :info : [ 1655.550594] test_bpf: #816 ALU64_SUB_K: all immediate value magnitudes jited:1 175712 PASS
> > ......
> > kern :info : [16725.824950] test_bpf: #931 JMP32_JLE_X: all register value magnitudes jited:1 216508 PASS
> > kern :info : [16911.555675] test_bpf: #932 JMP32_JSGT_X: all register value magnitudes jited:1 178367 PASS
> > kern :info : [17101.466163] test_bpf: #933 JMP32_JSGE_X: all register value magnitudes jited:1 191436 PASS
> > kern :info : [17288.359154] test_bpf: #934 JMP32_JSLT_X: all register value magnitudes jited:1 165714 PASS
> > kern :info : [17480.615048] test_bpf: #935 JMP32_JSLE_X: all register value magnitudes jited:1 172846 PASS
> > kern :info : [17667.472140] test_bpf: #936 JMP_JSET_K: imm = 0 -> never taken jited:1 14 PASS
> >
> > test_bpf.ko dmesg output is attached.
>
> On my side, I'm seeing:
>
> # time ./test_kmod.sh
> [ JIT enabled:0 hardened:0 ]
> [ 107.182567] test_bpf: Summary: 1009 PASSED, 0 FAILED, [0/997 JIT'ed]
> [ 107.200319] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [0/8 JIT'ed]
> [ 107.200379] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
> [ JIT enabled:1 hardened:0 ]
> [ 108.130568] test_bpf: Summary: 1009 PASSED, 0 FAILED, [997/997 JIT'ed]
> [ 108.143447] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [8/8 JIT'ed]
> [ 108.143510] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
> [ JIT enabled:1 hardened:1 ]
> [ 109.116727] test_bpf: Summary: 1009 PASSED, 0 FAILED, [997/997 JIT'ed]
> [ 109.129915] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [8/8 JIT'ed]
> [ 109.129979] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
> [ JIT enabled:1 hardened:2 ]
> [ 6617.952848] test_bpf: Summary: 1009 PASSED, 0 FAILED, [948/997 JIT'ed]
> [ 6617.965936] test_bpf: test_tail_calls: Summary: 8 PASSED, 0 FAILED, [8/8 JIT'ed]
> [ 6617.966004] test_bpf: test_skb_segment: Summary: 2 PASSED, 0 FAILED
>
> real 108m32.833s
> user 0m0.031s
> sys 108m17.939s
>
> The hardened:2 run takes significantly longer due to excessive patching for the
> jit constant blinding code.
I can confirm this too.
The slow tests are designed to check the result of all ALU and JMP
operations for as many different operand values as possible. It is not
feasible to test every combination of the two operand values, so the
space needs to be narrowed down. To exercise JIT code paths that
depend on the operand magnitude, values are chosen with different high
bit set (power-of-two magnitude) and some added small perturbations.
There is a quadratic pattern where both operands vary independently,
and a linear pattern were the MSBs are equal.
> Maybe the test cases can be reduced for the latter,
> otoh, it's good to know that they all pass as well.
The patterns described above can be tuned by changing the constants
PATTERN_BLOCK{1,2} in lib/test_bpf.c. According to my tests it seems
that the quadratic pattern takes most of the time, but the linear part
is not insignificant either. If I disable the quadratic pattern
completely and reduce the perturbation size for the linear pattern, I
get down to a more reasonable few seconds for each test case instead
of minutes.
The default test patterns may be a bit excessive, but they have also
found real bugs in some JITs. I would like to keep the settings as-is
for the non-hardened runs. I also think it is valuable to be able to
run the full tests during development. One solution could be to add a
module parameter for using a reduced pattern instead. Then the
test_kmod.sh script could set that parameter when running the 4:th
test, while still making it possible to run the full patterns with
hardening manually.
Thanks,
Johan
Hi Zhou,
Not sure what exactly you were asking, can you clarify what the question is?
By the way, the recommend way to run bpf selftests are through :
`./tools/testing/selftests/bpf/vmtest.sh`. ,it will take care of
building image, selftets and also run those in a qemu vm.
This test should finish within a minute or so, (excluding building time)
Cheers.