Bug 2110559 - logconv.pl - Use a higher threshold for wtime, optime and etime in the Recommendations section.
Summary: logconv.pl - Use a higher threshold for wtime, optime and etime in the Recomm...
Keywords:
Status: NEW
Alias: None
Product: Red Hat Enterprise Linux 9
Classification: Red Hat
Component: 389-ds-base
Version: 9.3
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: beta
: 9.4
Assignee: LDAP Maintainers
QA Contact: LDAP QA Team
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-07-25 15:54 UTC by Têko Mihinto
Modified: 2023-07-28 08:29 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker RHELPLAN-163750 0 None None None 2023-07-28 08:27:41 UTC

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.
$


Note You need to log in before you can comment on or make changes to this bug.