Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sdap: record time needed for a sdap operation #5969

Closed
wants to merge 11 commits into from

Conversation

sumit-bose
Copy link
Contributor

The start time of an sdap operation is stored to calculate the spend time
when the operation finished. This spend time is an upper limit for the time
the underlying LDAP operation took. The actual time of the LDAP operation
might be shorter. This might happen is many sdap operations are running in
parallel and the given operation has to wait for processing due to the
asynchronous handling of the operations.

To easy identify LDAP request which are running longer than expected all
requests needing 80% of there timeout are recorded wit h log level
SSSDBG_IMPORTANT_INFO.

The threshold of 80% is currently hard-coded.

Please note that due to the asynchronous processing in the backend some
requests might be logged with a long execution time not because they need
the recorded time but because their processing is delayed by another
request which was processed before.

Resolves: #5967

@alexey-tikhonov
Copy link
Member

alexey-tikhonov commented Jan 28, 2022

Thank you for the patches.

Covscan is nearly clean. In general looks good to me code wise.

I plan to test it once minor inline comments are resolved.

@sumit-bose
Copy link
Contributor Author

Hi,

thanks for the review, the latest version should cover most of your comments.

bye,
Sumit

@alexey-tikhonov
Copy link
Member

Thank you for the update. I still have few questions.

@alexey-tikhonov
Copy link
Member

This is practically ready, there is only one minor conversation left open.

@sumit-bose, could you please add (or re-format existing commit message(s)) a release note?

SSSDBG_PERF_STAT should be use for statistical or performance data, e.g
time needed for a request.

:relnote: A new debug level is added to show statistical and performance
data. Currently the duration of a backend request and of single LDAP
operations are recorded if debug_level is set to 9 or the bit 0x20000 is
set.

Resolves: SSSD#5967
Two new calls get_start_time() and get_spend_time_us() are added to make
it easy to calculate time differences in micro-seconds (us).

Resolves: SSSD#5967
The start time of an sdap operation is stored to calculate the spend
time when the operation finished. This spend time is an upper limit for
the time the underlying LDAP operation took. The actual time of the LDAP
operation might be shorter. This might happen is many sdap operations
are running in parallel and the given operation has to wait for
processing due to the asynchronous handling of the operations.

Resolves: SSSD#5967
The time a backend request needs from start to finish is recorded in the
logs.

Resolves: SSSD#5967
Currently the IP address of the current LDAP server is only available in
a log message. The new call sdap_get_server_ip_str() makes it available
for other purposes as well.

Resolves: SSSD#5967
Besides the LDAP message id other information might be helpful when
collections statistics about LDAP operations.

Resolves: SSSD#5967
Add the server IP address and other information about the current LDAP
request to the timing statistics.

Resolves: SSSD#5967
Add the server IPA address and other information about the current
extdom LDAP extended operation to the timing statistics.

Resolves: SSSD#5967
To easy identify LDAP request which are running longer than expected all
requests needing 80% of there timeout are recorded wit h log level
SSSDBG_IMPORTANT_INFO.

The threshold of 80% is currently hard-coded.

Please note that due to the asynchronous processing in the backend some
requests might be logged with a long execution time not because they
need the recorded time but because their processing is delayed by
another request which was processed before.

:relnote: A warning is added in the logs if an LDAP operation needs more
than 80% of the configured timeout.

Resolves: SSSD#5967
Only the msgid member of struct sdap_op is used for debugging messages
in some other places of the code.
This new call is similar to sdap_get_server_ip_str() but will never
return NULL so that the caller can always expect a string.
sdap_get_server_ip_str() is replaced with the new call where needed.

Resolves: SSSD#5967
@sumit-bose
Copy link
Contributor Author

This is practically ready, there is only one minor conversation left open.

@sumit-bose, could you please add (or re-format existing commit message(s)) a release note?

Hi,

the latest version has release notes.

bye,
Sumit

@alexey-tikhonov
Copy link
Member

Thank you. ACK.

@pbrezina
Copy link
Member

Pushed PR: #5969

  • master
    • 5494f7f - sdap: add sdap_get_server_ip_str_safe()
    • 15f66ef - sdap: make struct sdap_op private
    • b3646c6 - sdap: warn if request needs 80% of timeout
    • e2082c0 - ipa: add info string for statistics
    • a9b4ae6 - ldap: add info string for statistics
    • 5dc34b7 - sdap_op: add strings member for extra statistical information
    • 23e64be - sdap: split out function to get the server IP as string
    • 3063a73 - dp: adding log message with spend time
    • 3b79553 - sdap: record time needed for a sdap operation
    • 2fb5cbf - util: add time measurement helpers
    • 775150b - debug: add new dubug level SSSDBG_PERF_STAT

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[RFE] Implement time logging for the LDAP queries and warning of high queries time
3 participants