Improve KeysInUse logging performance during burst of first use events - #174
Draft
Maxwell Moyer-McKee (mamckee) wants to merge 2 commits into
Draft
Improve KeysInUse logging performance during burst of first use events#174Maxwell Moyer-McKee (mamckee) wants to merge 2 commits into
Maxwell Moyer-McKee (mamckee) wants to merge 2 commits into
Conversation
Contributor
There was a problem hiding this comment.
Pull request overview
Warning
Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.
Improve KeysInUse logging thread throughput during bursts of first-use events by narrowing how long logging_thread_mutex is held, reducing caller delays while still avoiding holding key locks across fork().
Changes:
- Add
O_CLOEXECwhen opening the log file descriptor. - Reduce
logging_thread_mutexhold time to only the critical section that touchespKeysinuseInfostate. - Move
p_scossl_keysinuse_log_noticecalls outside the mutex to remove logging I/O from the contended section.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Comment on lines
+1031
to
1075
| while (sk_SCOSSL_PROV_KEYSINUSE_INFO_num(sk_keysinuse_info_pending) > 0) | ||
| { | ||
| while (sk_SCOSSL_PROV_KEYSINUSE_INFO_num(sk_keysinuse_info_pending) > 0) | ||
| if ((pthreadErr = pthread_mutex_lock(&logging_thread_mutex)) != 0) | ||
| { | ||
| pKeysinuseInfo = sk_SCOSSL_PROV_KEYSINUSE_INFO_pop(sk_keysinuse_info_pending); | ||
| if (CRYPTO_THREAD_write_lock(pKeysinuseInfo->lock)) | ||
| { | ||
| now = time(NULL); | ||
|
|
||
| pKeysinuseInfo->firstLogTime = pKeysinuseInfo->lastLogTime == 0 ? now : pKeysinuseInfo->firstLogTime; | ||
| pKeysinuseInfo->lastLogTime = now; | ||
| pKeysinuseInfo->logPending = FALSE; | ||
| p_scossl_keysinuse_log_error("Logging thread failed to accquire mutex,SYS_%d", pthreadErr); | ||
| goto cleanup; | ||
| } | ||
|
|
||
| keysinuseInfoTmp = *pKeysinuseInfo; | ||
| pKeysinuseInfo = sk_SCOSSL_PROV_KEYSINUSE_INFO_pop(sk_keysinuse_info_pending); | ||
| if (pKeysinuseInfo != NULL && | ||
| CRYPTO_THREAD_write_lock(pKeysinuseInfo->lock)) | ||
| { | ||
| now = time(NULL); | ||
|
|
||
| pKeysinuseInfo->decryptCounter = 0; | ||
| pKeysinuseInfo->signCounter = 0; | ||
| pKeysinuseInfo->firstLogTime = pKeysinuseInfo->lastLogTime == 0 ? now : pKeysinuseInfo->firstLogTime; | ||
| pKeysinuseInfo->lastLogTime = now; | ||
| pKeysinuseInfo->logPending = FALSE; | ||
|
|
||
| CRYPTO_THREAD_unlock(pKeysinuseInfo->lock); | ||
| } | ||
| else | ||
| { | ||
| p_scossl_keysinuse_log_error("Failed to lock keysinuse info,OPENSSL_%d", ERR_get_error()); | ||
| keysinuseInfoTmp.refCount = -1; | ||
| } | ||
| keysinuseInfoTmp = *pKeysinuseInfo; | ||
|
|
||
| p_scossl_keysinuse_info_free(pKeysinuseInfo); | ||
| pKeysinuseInfo->decryptCounter = 0; | ||
| pKeysinuseInfo->signCounter = 0; | ||
|
|
||
| if (keysinuseInfoTmp.refCount > 0) | ||
| { | ||
| p_scossl_keysinuse_log_notice("%s,%d,%d,%ld,%ld", | ||
| keysinuseInfoTmp.keyIdentifier, | ||
| keysinuseInfoTmp.signCounter, | ||
| keysinuseInfoTmp.decryptCounter, | ||
| keysinuseInfoTmp.firstLogTime, | ||
| keysinuseInfoTmp.lastLogTime); | ||
| } | ||
| CRYPTO_THREAD_unlock(pKeysinuseInfo->lock); | ||
| } | ||
| else | ||
| { | ||
| p_scossl_keysinuse_log_error("Failed to lock keysinuse info,OPENSSL_%d", ERR_get_error()); | ||
| keysinuseInfoTmp.refCount = -1; | ||
| } | ||
|
|
||
| pthread_mutex_unlock(&logging_thread_mutex); | ||
|
|
||
| p_scossl_keysinuse_info_free(pKeysinuseInfo); | ||
|
|
||
| if (keysinuseInfoTmp.refCount > 0) | ||
| { | ||
| p_scossl_keysinuse_log_notice("%s,%d,%d,%ld,%ld", | ||
| keysinuseInfoTmp.keyIdentifier, | ||
| keysinuseInfoTmp.signCounter, | ||
| keysinuseInfoTmp.decryptCounter, | ||
| keysinuseInfoTmp.firstLogTime, | ||
| keysinuseInfoTmp.lastLogTime); | ||
| } | ||
| } |
| pKeysinuseInfo->firstLogTime = pKeysinuseInfo->lastLogTime == 0 ? now : pKeysinuseInfo->firstLogTime; | ||
| pKeysinuseInfo->lastLogTime = now; | ||
| pKeysinuseInfo->logPending = FALSE; | ||
| p_scossl_keysinuse_log_error("Logging thread failed to accquire mutex,SYS_%d", pthreadErr); |
Copilot started reviewing on behalf of
Maxwell Moyer-McKee (mamckee)
August 6, 2026 23:49
View session
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The logging thread in keysinuse was updated to hold the logging thread mutex while logging events to prevent any of the keysinuse info locks from being held at the time of fork. In the case where lots of first use events happen at the same time, this causes a delay to callers. If the logging thread is busy logging a large number of first use events, then the next first use of a key will be stuck waiting for the logging thread to free the logging thread mutex.
This PR improves performance by having the logging thread only hold the lock through the critical patch where an keysinuse info's lock is held.