FIPS provider ossl_prov_is_running() is slow when running threads with PBKDF2

[slontis]

I wanted to write a simple threaded test running a KDF to see what differences there were in speeds, when comparing master, and 3.0.9
plus fips provider from both places.. (In particular is the internal fetch time significant).

I noticed when running that the following in either master or 3.0.9
LD_LIBRARY_PATH=. ./test/mythreadtest -fips -config test/fips.cnf

took considerably more time than:
./test/mythreadtest -config test/default.cnf

Enabling and comparing cachegrind outputs (in debug) e.g
LD_LIBRARY_PATH=. valgrind --tool=callgrind --instr-atstart=no ./test/threadstest -config test/default.cnf

I could see that there are 2.5 million calls to ossl_prov_is_running(). Commenting out the read lock inside this function makes the time closer to the default provider times.

#include <string.h>
#include <stdio.h>
#include <time.h>
#include <openssl/crypto.h>
#include <openssl/kdf.h>
#include <openssl/core_names.h>
#include <openssl/err.h>
#include "internal/nelem.h"
#include "testutil.h"
#include "threadstest.h"
#include <sys/time.h>
#include "/usr/include/valgrind/callgrind.h"

/* Limit the maximum number of threads */
#define MAXIMUM_THREADS     20

/* Limit the maximum number of providers loaded into a library context */
#define MAXIMUM_PROVIDERS   4

static int do_fips = 0;
static char *config_file = NULL;

static const char *default_provider[] = { "default", NULL };
//static const char *fips_provider[] = { "fips", NULL };
//static const char *fips_and_default_providers[] = { "default", "fips", NULL };

static OSSL_LIB_CTX *multi_libctx = NULL;
static int multi_success;
static OSSL_PROVIDER *multi_provider[MAXIMUM_PROVIDERS + 1];
static size_t multi_num_threads;
static thread_t multi_threads[MAXIMUM_THREADS];

static void multi_intialise(void)
{
    multi_success = 1;
    multi_num_threads = 0;
    memset(multi_threads, 0, sizeof(multi_threads));
}


static void multi_set_fail(void)
{
    multi_success = 0;
}

static void teardown_libctx(void)
{
    OSSL_PROVIDER **p;

    for (p = multi_provider; *p != NULL; p++)
        OSSL_PROVIDER_unload(*p);
    OSSL_LIB_CTX_free(multi_libctx);
}

static int setup_libctx(const char *providers[])
{
    size_t n;

    if (!TEST_true(test_get_libctx(&multi_libctx, NULL, config_file,
                                   NULL, NULL)))
        return 0;


    if (providers != NULL)
        for (n = 0; providers[n] != NULL; n++)
            if (!TEST_size_t_lt(n, MAXIMUM_PROVIDERS)
                || !TEST_ptr(multi_provider[n] = OSSL_PROVIDER_load(multi_libctx,
                                                                    providers[n]))) {
                teardown_libctx();
                return 0;
            }
    return 1;
}



static int teardown_threads(void)
{
    size_t i;

    for (i = 0; i < multi_num_threads; i++)
        if (!TEST_true(wait_for_thread(multi_threads[i])))
            return 0;
    return 1;
}

static int start_threads(size_t n, void (*thread_func)(void))
{
    size_t i;

    if (!TEST_size_t_le(multi_num_threads + n, MAXIMUM_THREADS))
        return 0;

    for (i = 0 ; i < n; i++)
        if (!TEST_true(run_thread(multi_threads + multi_num_threads++, thread_func)))
            return 0;
    return 1;
}

static long timeMillis(struct timeval t)
{
    return t.tv_sec * 1000 + t.tv_usec / 1000;
}

static double tdiff(struct timeval end, struct timeval start)
{
    return (timeMillis(end) - timeMillis(start)) / 1000.0;
}

/* Template multi-threaded test function */
static int thread_run_test(void (*thread_func)(void), size_t num_threads, double *elapsed)
{
    int testresult = 0;

    struct timeval start, end;

    multi_intialise();


    gettimeofday(&start, NULL);
    if (!start_threads(num_threads, thread_func))
        goto err;

    testresult = (teardown_threads() && TEST_true(multi_success));
    gettimeofday(&end, NULL);
    *elapsed = tdiff(end, start);
    printf("\nElapsed Time = %f\n", *elapsed);
 err:
    return testresult;
}


static void pbkdf2_worker(void)
{
    int pass = 0;
    EVP_KDF_CTX *kctx = NULL;
    EVP_KDF *kdf = NULL;
    unsigned char out[25];
    OSSL_PARAM params[6], *p = params;

    const char digest[] = "sha256";
    const char passwd[] = "passwordPASSWORDpassword";
    const char salt[] = "saltSALTsaltSALTsaltSALTsaltSALTsalt";
    // unsigned int iterations = 4096;
    // int mode = 0;

    *p++ = OSSL_PARAM_construct_octet_string(OSSL_KDF_PARAM_PASSWORD,
                                             (unsigned char *)passwd, strlen(passwd));
    *p++ = OSSL_PARAM_construct_octet_string(OSSL_KDF_PARAM_SALT,
                                             (unsigned char *)salt, strlen(salt));
    // *p++ = OSSL_PARAM_construct_uint(OSSL_KDF_PARAM_ITER, iter);
    *p++ = OSSL_PARAM_construct_utf8_string(OSSL_KDF_PARAM_DIGEST,
                                            (char *)digest, 0);
    // *p++ = OSSL_PARAM_construct_int(OSSL_KDF_PARAM_PKCS5, mode);
    *p = OSSL_PARAM_construct_end();


    kdf = EVP_KDF_fetch(multi_libctx, OSSL_KDF_NAME_PBKDF2, NULL);
    kctx = EVP_KDF_CTX_new(kdf);
    EVP_KDF_free(kdf);

    if (kctx != NULL && EVP_KDF_derive(kctx, out, sizeof(out), params) > 0)
        pass = 1;

    EVP_KDF_CTX_free(kctx);
    if (!pass)
        multi_set_fail();
}



static int test_multi_pbkdf2_worker(void)
{
    int i, iterations = 10;
    int ret = 1;
    double cur = 0, total = 0;
    EVP_KDF *kdf = EVP_KDF_fetch(multi_libctx, OSSL_KDF_NAME_PBKDF2, NULL);
    EVP_MD *md = EVP_MD_fetch(multi_libctx, "sha256", NULL);

    CALLGRIND_START_INSTRUMENTATION;
    for (i = 0; i < iterations; ++i) {
        if (!thread_run_test(&pbkdf2_worker, MAXIMUM_THREADS, &cur))
            ret = 0;
        else
            total += cur;
    }
    CALLGRIND_STOP_INSTRUMENTATION;

    printf("Avg Time = %f\n", total / iterations);
    EVP_MD_free(md);
    EVP_KDF_free(kdf);

    return ret;
}

typedef enum OPTION_choice {
    OPT_ERR = -1,
    OPT_EOF = 0,
    OPT_FIPS, OPT_CONFIG_FILE,
    OPT_TEST_ENUM
} OPTION_CHOICE;

const OPTIONS *test_get_options(void)
{
    static const OPTIONS options[] = {
        OPT_TEST_OPTIONS_DEFAULT_USAGE,
        { "fips", OPT_FIPS, '-', "Test the FIPS provider" },
        { "config", OPT_CONFIG_FILE, '<',
          "The configuration file to use for the libctx" },
        { NULL }
    };
    return options;
}


int setup_tests(void)
{
    OPTION_CHOICE o;

    while ((o = opt_next()) != OPT_EOF) {
        switch (o) {
        case OPT_FIPS:
            do_fips = 1;
            break;
        case OPT_CONFIG_FILE:
            config_file = opt_arg();
            break;
        case OPT_TEST_CASES:
            break;
        default:
            return 0;
        }
    }

    if (!setup_libctx(do_fips ? NULL : default_provider))
        return 0;
    ADD_TEST(test_multi_pbkdf2_worker);
    return 1;
}

void cleanup_tests(void)
{
    teardown_libctx();
}

[slontis]

@paulidale Is this code useful for you? (It is just a cutdown version of threadtest.c)

[t8m]

Could we, when we are calling ossl_prov_is_running() from within the provider, avoid the locking altogether? Or even assume that we must be already running when we are inside the FIPS provider call.

[slontis]

On the rare case of error where it changes state, do we care that much?

[mattcaswell]

Perhaps FIPS_state could be handled as an atomic rather than being protected by a lock?

[paulidale]

Memory barriers are probably sufficient rather than atomic.

I suspect they could be quite weak ones. As rule this value won't change after initialisation.

[neverpanic]

Even if the value did change after initialization, certification labs would probably only care that it is eventually consistent.

Let's say, for example, that we'd start changing the state to error whenever a pairwise consistency test after key generation fails, and that key generation happens in the presence of threads. At what point would a completely unrelated cryptographic operation in a different thread have to stop working? I'd argue (and last time we brought this up our certification lab agreed) that it doesn't have to be immediate, it's enough to just eventually stop accepting new operations. It should be immediately consistent within a thread, but that's simple.