| Message ID | 20250108184354.997818-1-berrange@redhat.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | crypto: fix bogus error benchmarking pbkdf on fast machines | expand |
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.
On 08/01/2025 19.43, 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. > 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. Thanks, this seems to fix the issue for me: Tested-by: Thomas Huth <thuth@redhat.com>
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 + * 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;
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. 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> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- crypto/pbkdf.c | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-)