curl -> pkcs11 openssl engine -> pkcs11 TA -> Vendor

[muraliselvaraj2020]

Hi Team,

Please refer below details and share your inputs..

1. curl from opensource + pkcs11 openssl from libp11 + pkc11 TA (No change in curl + No change in openssl + PKCS11 TA from vendor)

time curl --key "pkcs11:id=%44;type=private;pin-value=1234" --cert "pkcs11:id=%44;type=cert;pin-value=1234" https://<mtls_enabled_endpoint>

real 0m2.041s
user 0m0.138s
sys 0m0.736s

2. PKCS11 TA from Vendor where pkcs11-tool directly interface with PKCS11-TA ( bypassing curl and openssl layers )

time pkcs11-tool --module /usr/lib/libckteec.so --login --pin 1234 --read-object --type pubkey --id 44

real 0m0.485s
user 0m0.006s
sys 0m0.048s

We would like to measure the time taken within curl, openssl , engine and PKCS11 TA from curl --key "pkcs11:id=%44;type=private;pin-value=1234" --cert "pkcs11:id=%44;type=cert;pin-value=1234" https://<mtls_enabled_endpoint>

Do we have any existing tool or preference from libp11 community to measure the time taken by each component (curl, openssl, pkcs11 engine, TA).

Please share the details, Thanks.
Regards,
Murali.S

[dwmw2]

Can pkcs11-spy output timestamps?

[muraliselvaraj2020]

Thanks @dwmw2 , Please review below pkcs11-spy log details and share your inputs.

curl → libcurl → OpenSSL → PKCS#11 Engine → Vendor PKCS#11 Module → Vendor PKCS#11 TA

I'm using open-source curl 7.82.0, PKCS11 engine from OpenSC (https://github.com/OpenSC/libp11) and libckteec.so, PKCS11 TA from vendor.

From the spy logs, we are trying to find the delay from REE or PKCS11 module API or PKCS11 TA?

Kindly review my analysis with pkcs11-spy logs and share your inputs to determine the breakdown which is causing the delay (REE or PKCS11 module API or PKCS11 TA)?

curl --key "pkcs11:id=%88;type=private;pin-value=1234" --cert "pkcs11:id=%88;type=cert;pin-value=1234" https://<mtls_enabled_secure_endpoint.com>

As per the logs, observed more time took for finding and loading the cert and private objects from pkcs11 token.
Pls review and correct my understanding.

For certificate:
C_FindObjectsInit -> start time -> 21:23:16.532
C_FindObjects -> start time -> 21:23:17.209
Does it mean, C_FindObjectsInit took this much time 21:23:17.209 - 21:23:16.532 = 323 milliseconds ?

11: C_OpenSession
2025-09-08 21:23:16.532
[in] slotID = 0x0
[in] flags = 0x4
[in] pApplication = (nil)
[in] Notify = (nil)
[out] *phSession = 0x1
Returned: 0 CKR_OK

12: C_FindObjectsInit
2025-09-08 21:23:16.532
[in] hSession = 0x1
[in] pTemplate[2]:
CKA_CLASS CKO_CERTIFICATE
CKA_ID 00077ba8 / 1
00000000 88 ,
Returned: 0 CKR_OK

13: C_FindObjects
2025-09-08 21:23:17.209
[in] hSession = 0x1
[in] ulMaxObjectCount = 0x1
[out] ulObjectCount = 0x1
Object 0x1 matches
Returned: 0 CKR_OK

14: C_GetAttributeValue
2025-09-08 21:23:17.209
[in] hSession = 0x1
[in] hObject = 0x1
[in] pTemplate[1]:
CKA_CLASS ffdb9d40 / 4
[out] pTemplate[1]:
CKA_CLASS CKO_CERTIFICATE
Returned: 0 CKR_OK

23: C_GetSessionInfo
2025-09-08 21:23:17.216
[in] hSession = 0x1
[out] pInfo:
slotID: 0
state: ' CKS_RO_PUBLIC_SESSION'
flags: 4
CKF_SERIAL_SESSION
ulDeviceError: 0
Returned: 0 CKR_OK

24: C_FindObjectsInit
2025-09-08 21:23:17.216
[in] hSession = 0x1
[in] pTemplate[2]:
CKA_CLASS CKO_PRIVATE_KEY
CKA_ID 0007d4f8 / 1
00000000 88 ,
Returned: 0 CKR_OK

25: C_FindObjects
2025-09-08 21:23:19.067
[in] hSession = 0x1
[in] ulMaxObjectCount = 0x1
[out] ulObjectCount = 0x0
Returned: 0 CKR_OK

26: C_FindObjectsFinal
2025-09-08 21:23:19.067
[in] hSession = 0x1
Returned: 0 CKR_OK

**For private key:

C_FindObjectsInit -> start time -> 21:23:17.216
C_FindObjects -> start time -> 21:23:19.067

Does it mean, C_FindObjectsInit took this much time 21:23:19.067 - 21:23:17.216 = 1851 milliseconds ?**

Thanks,
Murali.S

[muraliselvaraj2020]

Hi @dwmw2 ,

Can you please review the above data and share your inputs. Thanks.

[dwmw2]

Sounds possible. Note that your original 2.041s will be finding the cert, and the key, and actually using the key for a signature. While your original 0.485s that you compared it against, is only finding the cert.

Yes, PKCS#11 hardware devices are sometimes slow. Is there something in particular you think is wrong here?

Maybe we could use search terms to C_FindObjects which run faster? But it looks like you're already using id= so that ought to be fairly much optimal.

[muraliselvaraj2020]

Thanks @dwmw2 for the explanation.

Can you please review additional details and share your inputs.

Here, these are 3 major components (curl from open-source, pkcs11 engine from OpenSC and libckteec.so, PKCS11 TA from Vendor) are involved here.

Curl → OpenSSL → PKCS#11 Engine → PKCS#11 Module (libckteec.so from Vendor) → PKCS#11 TA (from Vendor)

We would like to find the breakdown to determine which component/interfaces take more time while running below curl command.

time curl --key "pkcs11:id=%44;type=private;pin-value=1234" --cert "pkcs11:id=%44;type=cert;pin-value=1234" https://<mtls_enabled_endpoint>

real 0m2.041s
user 0m0.138s
sys 0m0.736s

From pkcs11-spy logs, could see searching cert and private key , signing operation took these timings.

12: C_FindObjectsInit took 324 ms -> Prepares a search for objects (certs).
30: C_FindObjectsInit took 286 ms -> Prepares a search for objects (private key).
47: C_Sign took 755 ms -> Performing cryptographic signing.

@dwmw2 can you pls clarify below queries.

Query:

Does it indicate, the optimization would be required ONLY in Vendor components (libckteec.so, PKCS#11 TA) ?

Or Do we need look into PKCS11 engine or curl code (we believe these are stable code as it's open-source version) ?

Thanks,
Murali.S

[muraliselvaraj2020]

Good morning @dwmw2 ; can you pls clarify above queries which would be really helpful for our progress/debugging. Thanks.