Bug 1850275

Summary:	Add new access log keywords for time spent in work queue and actual operation time
Product:	Red Hat Enterprise Linux 8	Reporter:	mreynolds
Component:	389-ds-base	Assignee:	mreynolds
Status:	CLOSED ERRATA	QA Contact:	RHDS QE <ds-qe-bugs>
Severity:	medium	Docs Contact:	Marc Muehlfeld <mmuehlfe>
Priority:	unspecified
Version:	8.3	CC:	ldap-maint, msauton, pasik, sgouvern, spichugi, tbordaz, tmihinto, vashirov
Target Milestone:	rc	Flags:	pm-rhel: mirror+
Target Release:	8.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
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.	Story Points:	---
Clone Of:
Clones:	1953673 (view as bug list)		Environment:
Last Closed:	2021-05-18 15:45:16 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1953673

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