Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

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 2110559

Summary:	logconv.pl - Use a higher threshold for wtime, optime and etime in the Recommendations section.
Product:	Red Hat Enterprise Linux 9	Reporter:	Têko Mihinto <tmihinto>
Component:	389-ds-base	Assignee:	LDAP Maintainers <idm-ds-dev-bugs>
Status:	CLOSED MIGRATED	QA Contact:	LDAP QA Team <idm-ds-qe-bugs>
Severity:	low	Docs Contact:
Priority:	unspecified
Version:	9.3	CC:	idm-ds-dev-bugs, mreynolds, vashirov
Target Milestone:	beta	Keywords:	MigratedToJIRA, Triaged
Target Release:	9.4	Flags:	pm-rhel: mirror+
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2023-09-19 15:11:44 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:

Description Têko Mihinto 2022-07-25 15:54:03 UTC

Description of problem:

Some recommendations might sound like there is indeed a performance issue.

Version-Release number of selected component (if applicable):
$ cat /etc/redhat-release 
Red Hat Enterprise Linux release 8.6 (Ootpa)
$
$ rpm -qa | grep 389-ds-base-1
389-ds-base-1.4.3.29-3.module+el8dsrv+14615+a86efbbf.x86_64
$

How reproducible:
Always.

Steps to Reproduce:
1. Run logconv.pl

$ more single_conn.txt 
[25/Jul/2022:14:01:08.825370464 +0200] conn=3062 fd=64 slot=64 SSL connection from ::1 to ::1
[25/Jul/2022:14:01:08.848575252 +0200] conn=3062 TLS1.3 128-bit AES-GCM
[25/Jul/2022:14:01:08.848729518 +0200] conn=3062 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[25/Jul/2022:14:01:08.849915890 +0200] conn=3062 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.017515933 optime=0.001235780 etime=0.018750058 dn="cn=directory m
anager"
[25/Jul/2022:14:01:08.850415787 +0200] conn=3062 op=1 SRCH base="dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs="1.1"
[25/Jul/2022:14:01:08.850656536 +0200] conn=3062 op=1 RESULT err=0 tag=101 nentries=1 wtime=0.000407047 optime=0.000241813 etime=0.000647483
[25/Jul/2022:14:01:08.850949192 +0200] conn=3062 op=2 UNBIND
[25/Jul/2022:14:01:08.851035154 +0200] conn=3062 op=2 fd=64 closed error - U1
$

$ logconv.pl -V single_conn.txt > single_conn.conv.txt

2. Check the "Recommendations" section

$ grep -A 3 Recommendations single_conn.conv.txt 
----- Recommendations -----

 1.  Your average wtime is 0.00896149, you may want to investigate this performance problem.

$

3. Check the "Longest" sections:

$ grep -A 4 Longest single_conn.conv.txt 
----- Top 20 Longest etimes (elapsed times) -----

etime=0.018750058    1         
etime=0.000647483    1         

--
----- Top 20 Longest wtimes (wait times) -----

wtime=0.017515933    1         
wtime=0.000407047    1         

--
----- Top 20 Longest optimes (actual operation times) -----

optime=0.001235780    1         
optime=0.000241813    1         

$

Actual results:

==>  1.  Your average wtime is 0.00896149, you may want to investigate this performance problem.


Expected results:

IMHO an average wtime of 0.00896149 shouldn't be considered as a potential performance issue.

I think the threshold can be set to a value around 0.5 second ( maybe make it configurable via a logconv option ).


Additional info:

On RHEL 8.5 ( RHDS 11.4 ), the output can be interpreted as "Any etime higher than zero is a potential performance issue":

$ grep -A 3 Recommendations single_conn.conv.txt 
----- Recommendations -----

 1.  You have a majority of etimes that are greater than zero, you may want to investigate this performance problem.

$

Comment 1 mreynolds 2022-10-12 16:02:46 UTC

I can not reproduce this.  The code shows it only logs a recommendation is it's greater than 0:

        if (sprintf("%.2f", $wtimeAvg)  > 0){
                print "\n $recCount.  Your average wtime is $wtimeAvg, you may want to investigate this performance problem.\n";
                $recCount++; 
        }


Here is my output from logconv:


...
...
Average wtime (wait time):     0.000558868
Average optime (op time):      0.024036543
Average etime (elapsed time):  0.024593760

...
...

----- Recommendations -----

 1.  You have a significant difference between binds and unbinds.  You may want to investigate this difference.

 2.  You have a significant difference between file descriptors taken and file descriptors returned.  You may want to investigate this difference.

Cleaning up temp files...
Done.

Comment 2 Têko Mihinto 2022-10-13 13:35:20 UTC

Hi Mark,

I can reproduce this behavior with RHDS 11.5 on RHEL 8.6

$ cat /etc/redhat-release 
Red Hat Enterprise Linux release 8.6 (Ootpa)
$
$ rpm -qa | grep 389-ds-base-1
389-ds-base-1.4.3.29-3.module+el8dsrv+14615+a86efbbf.x86_64
$
$ logconv.pl -V single_conn.txt | tail -5

 1.  Your average wtime is 0.00896149, you may want to investigate this performance problem.

Cleaning up temp files...
Done.
$

Comment 6 RHEL Program Management 2023-09-19 15:11:27 UTC

Issue migration from Bugzilla to Jira is in process at this time. This will be the last message in Jira copied from the Bugzilla bug.

Comment 7 RHEL Program Management 2023-09-19 15:11:44 UTC

This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there.

Due to differences in account names between systems, some fields were not replicated.  Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information.

To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "RHEL-" followed by an integer.  You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like:

"Bugzilla Bug" = 1234567

In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information.