Re: [PATCH] crypto: fix bogus error benchmarking pbkdf on fast machines

["Richard W.M. Jones" <rjones@redhat.com>]

On Wed, Jan 08, 2025 at 06:43:54PM +0000, Daniel P. Berrangé wrote:
> We're seeing periodic reports of errors like:
> 
> $ qemu-img create -f luks --object secret,data=123456,id=sec0 \
>                   -o key-secret=sec0 luks-info.img 1M
>   Formatting 'luks-info.img', fmt=luks size=1048576 key-secret=sec0
>   qemu-img: luks-info.img: Unable to get accurate CPU usage
> 
> This error message comes from a recent attempt to workaround a
> kernel bug with measuring rusage in long running processes:
> 
>   commit c72cab5ad9f849bbcfcf4be7952b8b8946cc626e
>   Author: Tiago Pasqualini <tiago.pasqualini@canonical.com>
>   Date:   Wed Sep 4 20:52:30 2024 -0300
> 
>     crypto: run qcrypto_pbkdf2_count_iters in a new thread
> 
> Unfortunately this has a subtle bug on machines which are very fast.
> 
> On the first time around the loop, the 'iterations' value is quite
> small (1 << 15), and so will run quite fast. Testing has shown that
> some machines can complete this benchmarking task in as little as
> 7 milliseconds.
> 
> Unfortunately the 'getrusage' data is not updated at the time of
> the 'getrusage' call, it is done asynchronously by the schedular.

scheduler (https://en.wiktionary.org/wiki/scheduler)

> The 7 millisecond completion time for the benchmark is short
> enough that 'getrusage' sometimes reports 0 accumulated execution
> time.
> 
> As a result the 'delay_ms == 0' sanity check in the above commit
> is triggering non-deterministically on such machines.
> 
> The benchmarking loop intended to run multiple times, increasing
> the 'iterations' value until the benchmark ran for > 500 ms, but
> the sanity check doesn't allow this to happen.
> 
> To fix it, we keep a loop counter and only run the sanity check
> after we've been around the loop more than 5 times. At that point
> the 'iterations' value is high enough that even with infrequent
> updates of 'getrusage' accounting data on fast machines, we should
> see a non-zero value.
> 
> Reported-by: Thomas Huth <thuth@redhat.com>
> Reported-by: Richard W.M. Jones <rjones@redhat.com>

I think it was originally reported by a Debian automated tool in
https://lore.kernel.org/qemu-devel/ffe542bb-310c-4616-b0ca-13182f849fd1@redhat.com/

> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  crypto/pbkdf.c | 15 +++++++++++++--
>  1 file changed, 13 insertions(+), 2 deletions(-)
> 
> diff --git a/crypto/pbkdf.c b/crypto/pbkdf.c
> index 0dd7c3aeaa..b285958319 100644
> --- a/crypto/pbkdf.c
> +++ b/crypto/pbkdf.c
> @@ -107,7 +107,7 @@ static void *threaded_qcrypto_pbkdf2_count_iters(void *data)
>      size_t nsalt = iters_data->nsalt;
>      size_t nout = iters_data->nout;
>      Error **errp = iters_data->errp;
> -
> +    size_t scaled = 0;
>      uint64_t ret = -1;
>      g_autofree uint8_t *out = g_new(uint8_t, nout);
>      uint64_t iterations = (1 << 15);
> @@ -131,7 +131,17 @@ static void *threaded_qcrypto_pbkdf2_count_iters(void *data)
>  
>          delta_ms = end_ms - start_ms;
>  
> -        if (delta_ms == 0) { /* sanity check */
> +        /*
> +         * For very small 'iterations' values, CPU (or crypto
> +         * accelerator) might be fast enough that the schedular

scheduler as above

> +         * hasn't incremented getrusage() data, or incremented
> +         * it by a very small amount, resulting in delta_ms == 0.
> +         * Once we've scaled 'iterations' x10, 5 times, we really
> +         * should be seeing delta_ms != 0, so sanity check at
> +         * that point.
> +         */
> +        if (scaled > 5 &&
> +            delta_ms == 0) { /* sanity check */
>              error_setg(errp, "Unable to get accurate CPU usage");
>              goto cleanup;
>          } else if (delta_ms > 500) {
> @@ -141,6 +151,7 @@ static void *threaded_qcrypto_pbkdf2_count_iters(void *data)
>          } else {
>              iterations = (iterations * 1000 / delta_ms);
>          }
> +        scaled++;
>      }
>  
>      iterations = iterations * 1000 / delta_ms;
> -- 
> 2.47.1

I don't have a good way to test this unfortunately as we only saw it
once, on s390x, in a build system.

You might want to add links to the bug reports and earlier threads
about this:

https://lore.kernel.org/qemu-devel/ffe542bb-310c-4616-b0ca-13182f849fd1@redhat.com/
https://lore.kernel.org/qemu-devel/ffe542bb-310c-4616-b0ca-13182f849fd1@redhat.com/
https://bugzilla.redhat.com/show_bug.cgi?id=2336437

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-builder quickly builds VMs from scratch
http://libguestfs.org/virt-builder.1.html