RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1850275 - Add new access log keywords for time spent in work queue and actual operation time
Summary: Add new access log keywords for time spent in work queue and actual operation...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: 389-ds-base
Version: 8.3
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: rc
: 8.0
Assignee: mreynolds
QA Contact: RHDS QE
Marc Muehlfeld
URL:
Whiteboard:
Depends On:
Blocks: 1953673
TreeView+ depends on / blocked
 
Reported: 2020-06-23 21:14 UTC by mreynolds
Modified: 2024-03-25 16:05 UTC (History)
8 users (show)

Fixed In Version: 389-ds-devel-1.4-8040020201105165416.866effaa
Doc Type: Enhancement
Doc Text:
.Directory Server now logs the work and operation time in `RESULT` entries With this update, Directory Server now logs two additional time values in `RESULT` entries in the `/var/log/dirsrv/slapd-<instance_name>/access` file: * The `wtime` value indicates how long it took for an operation to move from the work queue to a worker thread. * The `optime` value shows the time the actual operation took to be completed once a worker thread started the operation. The new values provide additional information about how the Directory Server handles load and processes operations. For further details, see the link:https://access.redhat.com/documentation/en-us/red_hat_directory_server/11/html/configuration_command_and_file_reference/logs-reference#Access_Log_and_Connection_Code_Reference[Access Log Reference] section in the Red Hat Directory Server Configuration, Command, and File Reference.
Clone Of:
: 1953673 (view as bug list)
Environment:
Last Closed: 2021-05-18 15:45:16 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github 389ds 389-ds-base issues 4218 0 None closed Track time operation spends in work queue 2021-02-16 14:46:43 UTC

Description mreynolds 2020-06-23 21:14:07 UTC 
Description of problem:

This bug is created as a clone of upstream ticket:
https://pagure.io/389-ds-base/issue/51165

#### Issue Description

There are customer performance cases where it would be very useful to know how long an operation waited in the work queue before being assigned to a worker thread.  This should be easy to do, and we can add a new keyword in the access log, maybe something like "wtime", like "etime", but for how long it "waited" in the queue, and "optime" for long the operation actually look.
Comment 1 thierry bordaz 2020-06-24 05:54:17 UTC 
Will impact https://access.redhat.com/documentation/en-us/red_hat_directory_server/11/html/administration_guide/configuring_logs#configuring_the_log_levels
Comment 10 Viktor Ashirov 2020-08-26 15:40:42 UTC 
Fixed upstream https://pagure.io/389-ds-base/c/dda3ab0da56c42aa529bca35d7a05604f2076f75?branch=master
Moving to POST
Comment 15 mreynolds 2020-10-06 15:13:02 UTC 
Verification is easy, yuou just need to check a RESULT message in the access log for the keywords: "optime" and "wtime":

    RESULT err=0 tag=101 nentries=13 wtime=0.000569022 optime=0.002921434 etime=0.003485962
Comment 16 sgouvern 2020-11-16 10:27:03 UTC 
Verified with build 389-ds-base-libs-1.4.3.16-1.module+el8.4.0+8740+d5ec8778.x86_64 :


]# PYTHONPATH=src/lib389 py.test -s -v dirsrvtests/tests/suites/ds_logs/ds_logs_test.py::test_optime_and_wtime_keywords
re-exec with libfaketime dependencies
========================================================== test session starts ===========================================================
platform linux -- Python 3.6.8, pytest-6.1.2, py-1.9.0, pluggy-0.13.1 -- /usr/bin/python3.6
cachedir: .pytest_cache
metadata: {'Python': '3.6.8', 'Platform': 'Linux-4.18.0-247.el8.x86_64-x86_64-with-redhat-8.4-Ootpa', 'Packages': {'pytest': '6.1.2', 'py': '1.9.0', 'pluggy': '0.13.1'}, 'Plugins': {'metadata': '1.10.0', 'html': '3.0.0', 'libfaketime': '0.1.2'}}
389-ds-base: 1.4.3.16-1.module+el8.4.0+8740+d5ec8778
nss: 3.53.1-11.el8_2
nspr: 4.25.0-2.el8_2
openldap: 2.4.46-16.el8
cyrus-sasl: 2.1.27-5.el8
FIPS: disabled
rootdir: /mnt/tests/rhds/tests/upstream/ds/dirsrvtests, configfile: pytest.ini
plugins: metadata-1.10.0, html-3.0.0, libfaketime-0.1.2
collected 1 item                                                                                                                         

==================================================== 1 passed, 27 warnings in 13.98s =====================================================

-> marking as verified:tested
Comment 19 sgouvern 2020-11-16 15:26:16 UTC 
verified:tested (see comment 16) with build https://brewweb.engineering.redhat.com/brew/buildinfo?buildID=1383684 
-> marking as VERIFIED
Comment 22 errata-xmlrpc 2021-05-18 15:45:16 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (389-ds:1.4 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:1835
Note You need to log in before you can comment on or make changes to this bug.