tlssig test takes huge amount of time

[mouse07410]

Describe the bug

 Cloudflare:
  x25519_kyber768 @ oqsprovider
kex=X25519Kyber768Draft00
  x25519_kyber512 @ oqsprovider
kex=X25519Kyber512Draft00
Test project /Users/ur20980/src/oqs-provider/_build
    Start 1: oqs_signatures
1/6 Test #1: oqs_signatures ...................   Passed    3.99 sec
    Start 2: oqs_kems
2/6 Test #2: oqs_kems .........................   Passed    0.24 sec
    Start 3: oqs_groups
3/6 Test #3: oqs_groups .......................   Passed    0.38 sec
    Start 4: oqs_tlssig
4/6 Test #4: oqs_tlssig .......................   Passed  271.71 sec
    Start 5: oqs_endecode
5/6 Test #5: oqs_endecode .....................   Passed    8.92 sec
    Start 6: oqs_evp_pkey_params
6/6 Test #6: oqs_evp_pkey_params ..............   Passed    1.27 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) = 288.36 sec

All the other tests take within 1 to 10 seconds. oqs_tlssig test takes about 272 seconds. It used to run on par with the other tests. I think something is wrong here.

This is with OpenSSL master.

To Reproduce

Configure, build, and run scripts/runtests.sh. Observe the timing.

Expected behavior

Here's the timing from the Macports-installed OpenSSL 3.3.1 4 Jun 2024 (Library: OpenSSL 3.3.1 4 Jun 2024):

 Cloudflare:
  x25519_kyber768 @ oqsprovider
kex=X25519Kyber768Draft00
  x25519_kyber512 @ oqsprovider
kex=X25519Kyber512Draft00
Test project /Users/ur20980/src/oqs-provider/_build
    Start 1: oqs_signatures
1/6 Test #1: oqs_signatures ...................   Passed    4.30 sec
    Start 2: oqs_kems
2/6 Test #2: oqs_kems .........................   Passed    0.33 sec
    Start 3: oqs_groups
3/6 Test #3: oqs_groups .......................   Passed    0.47 sec
    Start 4: oqs_tlssig
4/6 Test #4: oqs_tlssig .......................   Passed    3.22 sec
    Start 5: oqs_endecode
5/6 Test #5: oqs_endecode .....................   Passed   10.40 sec
    Start 6: oqs_evp_pkey_params
6/6 Test #6: oqs_evp_pkey_params ..............   Passed    1.07 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) =  19.81 sec

Environment (please complete the following information):

• OS: MacOS Sonoma
• OpenSSL version: OpenSSL 3.4.0-dev (Library: OpenSSL 3.4.0-dev )
• oqsprovider version: 0.6.2-dev

Please run the following commands to obtain the version information:

$ openssl3 version
OpenSSL 3.4.0-dev  (Library: OpenSSL 3.4.0-dev )
$ openssl3 list -providers
Providers:
  default
    name: OpenSSL Default Provider
    version: 3.4.0
    status: active
  legacy
    name: OpenSSL Legacy Provider
    version: 3.3.1
    status: active
  oqs
    name: OpenSSL OQS Provider
    version: 0.6.2-dev
    status: active
  pkcs11
    name: PKCS#11 Provider
    version: 3.3.1
    status: active
$ 
$ openssl version
OpenSSL 3.3.1 4 Jun 2024 (Library: OpenSSL 3.3.1 4 Jun 2024)
$ openssl list -providers
Providers:
  default
    name: OpenSSL Default Provider
    version: 3.3.1
    status: active
  legacy
    name: OpenSSL Legacy Provider
    version: 3.3.1
    status: active
  oqs
    name: OpenSSL OQS Provider
    version: 0.6.2-dev
    status: active
  pkcs11
    name: PKCS#11 Provider
    version: 3.3.1
    status: active
  vigenere
    version: 1.2
$ 

[baentsch]

Wow -- so the only thing changed between the two runs above is the OpenSSL version (3.3.1 vs. master)? Same oqsprovider/liboqs code? Same platform (OSX)? Any difference in baseline openssl speed (performance) tests?

[mouse07410]

Wow -- so the only thing changed between the two runs above is the OpenSSL version (3.3.1 vs. master)?

Apparently. Though I recall that sometimes the tests for the OpenSSL-3.3.1 were also outrageous for tlssig.

Same oqsprovider/liboqs code? Same platform (OSX)?

Oh yes.

Any difference in baseline openssl speed (performance) tests?

If you name a specific test(s), I'd be happy to run it and report. Offhand, I'd say - no. But I'd be happier if I could give you specific numbers.

[baentsch]

If you name a specific test(s), I'd be happy to run it and report. Offhand, I'd say - no. But I'd be happier if I could give you specific numbers.

I cannot -- as I have no clue which part of OpenSSL could trigger this. I just thought you might have run openssl speed in both of your configurations to see whether there are obvious deviations, @mouse07410 . Another question: Is this aarch64 or x64?

@levitte @romen As I cannot reproduce this on my machine (x64, Ubuntu) -- have you heard of any such, probably platform-dependent performance degradation of openssl "master"?

[baentsch]

@mouse07410 FWIW, I now re-ran your setup (openssl 3.3.1 vs master) on a Mac M1 running MacOS 13.5, not yet Sonoma without problem:

Test setup:
LD_LIBRARY_PATH=/Users/baentsch/git/oqs-provider/.local/lib
OPENSSL_APP=/Users/baentsch/git/oqs-provider/openssl/apps/openssl
OPENSSL_CONF=/Users/baentsch/git/oqs-provider/scripts/openssl-ca.cnf
OPENSSL_MODULES=/Users/baentsch/git/oqs-provider/_build/lib
DYLD_LIBRARY_PATH=/Users/baentsch/git/oqs-provider/.local/lib
Version information:
OpenSSL 3.4.0-dev  (Library: OpenSSL 3.4.0-dev )
Providers:
  default
    name: OpenSSL Default Provider
    version: 3.4.0
    status: active
    build info: 3.4.0-dev
    gettable provider parameters:
      name: pointer to a UTF8 encoded string (arbitrary size)
      version: pointer to a UTF8 encoded string (arbitrary size)
      buildinfo: pointer to a UTF8 encoded string (arbitrary size)
      status: integer (arbitrary size)
  oqsprovider
    name: OpenSSL OQS Provider
    version: 0.6.2-dev
    status: active
    build info: OQS Provider v.0.6.2-dev (bf10e6e) based on liboqs v.0.10.2-dev
    gettable provider parameters:
      name: pointer to a UTF8 encoded string (arbitrary size)
      version: pointer to a UTF8 encoded string (arbitrary size)
      buildinfo: pointer to a UTF8 encoded string (arbitrary size)
      status: integer (arbitrary size)
Cert gen/verify, CMS sign/verify, CA tests for all enabled OQS signature algorithms commencing: 
........................................................
External interop tests commencing
 Cloudflare:
  x25519_kyber768 @ oqsprovider
kex=X25519Kyber768Draft00
  x25519_kyber512 @ oqsprovider
kex=X25519Kyber512Draft00
Test project /Users/baentsch/git/oqs-provider/_build
    Start 1: oqs_signatures
1/6 Test #1: oqs_signatures ...................   Passed    5.90 sec
    Start 2: oqs_kems
2/6 Test #2: oqs_kems .........................   Passed    0.69 sec
    Start 3: oqs_groups
3/6 Test #3: oqs_groups .......................   Passed    0.90 sec
    Start 4: oqs_tlssig
4/6 Test #4: oqs_tlssig .......................   Passed    4.47 sec
    Start 5: oqs_endecode
5/6 Test #5: oqs_endecode .....................   Passed   10.02 sec
    Start 6: oqs_evp_pkey_params
6/6 Test #6: oqs_evp_pkey_params ..............   Passed    1.61 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) =  23.59 sec

[mouse07410]

My experience on M2 chip is similar, but the delay is not as drastic.

Here are the openssl speed results for

• OpenSSL-3.3.1 (Macports-installed): openssl-speed.txt
• OpenSSL-3.4-dev (built from sources): openssl3-speed.txt

It does show that OpenSSL-3.4-dev is a bit slower - but not nearly to the degree exhibited.

I'll update this post with the M2 benchmarks.

[baentsch]

My experience on M2 chip is similar, but the delay is not as drastic.

So what was the platform you used initally (HW/OS/compilers/openssl config/build flags)? How can we reproduce your results?

One more thought: If the consideration were right that this has to do with some changes in the openssl crypto in "master", what about you build oqsprovider (rather the underlying liboqs) completely without use of openssl primitives (setting cmake config variable OQS_USE_OPENSSL=OFF) and see whether the results persist? Another suggestion would be you build openssl v3.3.1 also from source -- if the slowdown happens then too, it has to do with the config/compilation environment and neither oqsprovider nor openssl code.

[mouse07410]

I have only two HW platforms: x86_64 and M2. All running MacOS Sonoma 14.6 and the latest released (not beta!) Xcode.
They all have Macports-installed stable OpenSSL (which happens to be 3.3.1 as of now), and compiled-from-sources OpenSSL master (which happens to be 3.4-dev now) with -g added to CFLAGS (they also contain -O3) and --debug passed to the config script.

Here are the M2 numbers for openssl speed:

• M2 OpenSSL-3.3.1: m2-openssl-speed.txt
• M2 OpenSSL-3.4-dev: m2-openssl3-speed.txt

And the tests.
OpenSSL-3.3.1:

 Cloudflare:
  x25519_kyber768 @ oqsprovider
kex=X25519Kyber768Draft00
  x25519_kyber512 @ oqsprovider
kex=X25519Kyber512Draft00
Test project /Users/ur20980/src/oqs-provider/_build
    Start 1: oqs_signatures
1/6 Test #1: oqs_signatures ...................   Passed    6.60 sec
    Start 2: oqs_kems
2/6 Test #2: oqs_kems .........................   Passed    0.81 sec
    Start 3: oqs_groups
3/6 Test #3: oqs_groups .......................   Passed    1.00 sec
    Start 4: oqs_tlssig
4/6 Test #4: oqs_tlssig .......................   Passed    5.17 sec
    Start 5: oqs_endecode
5/6 Test #5: oqs_endecode .....................   Passed    9.35 sec
    Start 6: oqs_evp_pkey_params
6/6 Test #6: oqs_evp_pkey_params ..............   Passed    1.33 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) =  24.28 sec

OpenSSL-3.4-dev:

 Cloudflare:
  x25519_kyber768 @ oqsprovider
kex=X25519Kyber768Draft00
  x25519_kyber512 @ oqsprovider
kex=X25519Kyber512Draft00
Test project /Users/ur20980/src/oqs-provider/_build
    Start 1: oqs_signatures
1/6 Test #1: oqs_signatures ...................   Passed    5.91 sec
    Start 2: oqs_kems
2/6 Test #2: oqs_kems .........................   Passed    0.77 sec
    Start 3: oqs_groups
3/6 Test #3: oqs_groups .......................   Passed    0.96 sec
    Start 4: oqs_tlssig
4/6 Test #4: oqs_tlssig .......................   Passed  101.08 sec
    Start 5: oqs_endecode
5/6 Test #5: oqs_endecode .....................   Passed   11.50 sec
    Start 6: oqs_evp_pkey_params
6/6 Test #6: oqs_evp_pkey_params ..............   Passed    1.25 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) = 123.85 sec

[baentsch]

--debug passed to the config script

That's IMO a substantial enough difference between a "release" level/MacPorts OSSL 3.3.1 and your own build 3.4.0-dev I'd argue.

-> Please try running 3.3.1 also "manually" built and configured like the 3.4.0-dev and I bet it'll be as slow as 3.4.0-dev. And/or config 3.4.0/master without --debug.

Another suggestion: You may want to run the ctests with the verbose option to see whether there's actually any marked difference in per-algorithm runtime (each one is output if run verbose): That would be another indication whether there are algorithm-specific primitives triggering this slowdown or a general/"systematic" problem with the TLS sig logic.

[mouse07410]

run the ctests with the verbose option

Would you mind posting the exact command (and what dir I should execute it, and what env vars it requires)?

[baentsch]

Would you mind posting the exact command (and what dir I should execute it, and what env vars it requires)?

Easiest if you run scripts/runtests.sh -V (passes that arg to ctest).

[levitte]

@levitte @romen As I cannot reproduce this on my machine (x64, Ubuntu) -- have you heard of any such, probably platform-dependent performance degradation of openssl "master"?

Unfortunately, no.

I'd suggest raising an issue with OpenSSL.

[mouse07410]

Would you mind posting the exact command (and what dir I should execute it, and what env vars it requires)?

Easiest if you run scripts/runtests.sh -V (passes that arg to ctest).

I did this. The uncompressed output is 900MB+. Here's the compressed log: tests-out-s.txt.gz
Hopefully, it would be of some use.