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:	NEW ---	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:	Triaged
Target Release:	9.4
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:		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.
$