af-alg stressor triggers modprobe throttling

[dann frazier]

Due to the combination of high core counts and perhaps a lack of available hash/crypto hardware acceleration drivers, arm64 server platforms generate a lot of noisy modprobe throttling messages when running the af-alg stressor. This appears to be partially mitigated in master by disabling hashes/ciphers once they are found to be not present. But, w/ 96 cores/hogs, we presumably still hit the kernel with 96 * (nr_hashes + nr_ciphers) before that mitigation takes effect, and that is sufficient to cause the kernel to emit throttling messages.

$ sudo dmesg -c > /dev/null ; ./stress-ng --af-alg 0 --af-alg-ops=200000; sudo dmesg -c
stress-ng: info: [76141] defaulting to a 86400 second (1 day, 0.00 secs) run per stressor
stress-ng: info: [76141] dispatching hogs: 96 af-alg
stress-ng: info: [76141] successful run completed in 0.40s
[ 5808.489046] __request_module: 25 callbacks suppressed
[ 5808.489050] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...
[ 5808.489503] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...
[ 5808.489724] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...
[ 5808.489731] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...
[ 5808.490092] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-xor-all, throttling...
[ 5808.490235] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash-all, throttling...
[ 5808.490308] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...
[ 5808.490367] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...
[ 5808.490597] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-ghash, throttling...

[Colin Ian King (colin-king)]

I'm not sure this really is a stress-ng issue, the purpose of stress-ng is to force out kernel problems like this. Isn't this a kernel issue instead?

[dann frazier (dannf)]

I can see that argument, and also an argument that this isn't a bug at all. That is, the kernel is telling us something strange is happening, but "something strange" is stress-ng's middle name :) That said, these errors combined with a later (and now known to be unrelated) kernel Oops caused me to dig into it. It would be nice if we could somehow prevent this from raising hackles for other users.

Perhaps the kernel's tolerance should be tweaked - that's a policy call for which I lack the expertise to make. Or, perhaps stress-ng could warn that these messages are expected and can be ignored. If nothing else, just having this bug report come up in a Google search will hopefully lessen the impact.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1813847

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Colin Ian King (colin-king)]

Fix committed: https://kernel.ubuntu.com/git/cking/stress-ng.git/commit/?id=a4e26439837ce6e472b502da430ff863f6c7c265

[Frank Heimes (fheimes)]

I'm also seeing a lot of these msgs on s390x still with kinetic, when server certification runs are done:

Oct 31 11:33:57 s1lp10 kernel: [592067.859684] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd320, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592067.872844] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592067.883019] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592068.050389] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-aegis128l, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592068.103120] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592068.104379] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592068.105161] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592068.105896] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:57 s1lp10 kernel: [592068.297550] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:33:58 s1lp10 kernel: [592068.305050] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-rmd128, throttling...
Oct 31 11:34:13 s1lp10 kernel: [592069.189683] request_module: modprobe crypto-rmd128 cannot be processed, kmod busy with 50 threads for more than 5 seconds now
Oct 31 11:34:13 s1lp10 kernel: [592083.809924] __request_module: 266 callbacks suppressed

(s390x has a lot of add. crypto modules)

Or:

stress-ng: info: [2822111] defaulting to a 86400 second (1 day, 0.00 secs) run per stressor
stress-ng: info: [2822111] dispatching hogs: 282 af-alg
stress-ng: info: [2822112] stress-ng-af-alg: 90 cryptographic algorithms found in /proc/crypto
stress-ng: info: [2822112] stress-ng-af-alg: 113 cryptographic algorithms in total (with defconfigs)
stress-ng: info: [2822111] successful run completed in 23.38s
[594523.200917] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-tgr160, throttling...
[758066.621778] __request_module: 483 callbacks suppressed
[758066.621782] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-blowfish, throttling...
[758066.621801] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-blowfish, throttling...
[758066.622950] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-blowfish, throttling...
[758066.622970] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: 50), for module crypto-blowfish, throttling...
[758066.623279] request_module: kmod_concurrent_max (0) close to 0 (max_modprobes: ...