Bug 1301097 - logconv.pl displays negative operation speeds
logconv.pl displays negative operation speeds
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: 389-ds-base (Show other bugs)
7.3
Unspecified Unspecified
low Severity low
: rc
: ---
Assigned To: Noriko Hosoi
Viktor Ashirov
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2016-01-22 10:11 EST by Viktor Ashirov
Modified: 2016-11-03 16:38 EDT (History)
3 users (show)

See Also:
Fixed In Version: 389-ds-base-1.3.5.2-1.el7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-11-03 16:38:57 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
access logs (9.61 KB, application/x-gzip)
2016-01-22 12:39 EST, Viktor Ashirov
no flags Details

  None (edit)
Description Viktor Ashirov 2016-01-22 10:11:03 EST
Description of problem:
When I run logconv.pl on access* logs (as man page says), operation speeds are negative:
$ logconv.pl access*

Searches:                     2             (-0.01/sec)  (-0.42/min)
Modifications:                1             (-0.00/sec)  (-0.21/min)
Adds:                         0             (-0.00/sec)  (-0.00/min)
Deletes:                      0             (-0.00/sec)  (-0.00/min)
Mod RDNs:                     0             (-0.00/sec)  (-0.00/min)
Compares:                     0             (-0.00/sec)  (-0.00/min)
Binds:                        2             (-0.01/sec)  (-0.42/min)


But when I run it as:
$ logconv.pl access.* access

Searches:                     2             (0.01/sec)  (0.40/min)
Modifications:                1             (0.00/sec)  (0.20/min)
Adds:                         0             (0.00/sec)  (0.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        2             (0.01/sec)  (0.40/min)

Issue is with the order of new and old access log files that are passed to logconv.pl.
In order to display right numbers, I need to run it with the list of files starting from the oldest one to the newest one.
We might as well fix the man page to explicitly mention that. 

Version-Release number of selected component (if applicable):
389-ds-base-1.3.4.0-25.el7_2.x86_64
Comment 2 mreynolds 2016-01-22 12:12:54 EST
This is a bug, using "access*" should work correctly.  

What are your steps to reproduce?  How many logs do you have?
Comment 3 mreynolds 2016-01-22 12:29:44 EST
Works for me:


# logconv.pl /var/log/dirsrv/slapd-localhost/access*
Access Log Analyzer 8.1
Command: logconv.pl /var/log/dirsrv/slapd-localhost/access /var/log/dirsrv/slapd-localhost/access.20160122-122207 /var/log/dirsrv/slapd-localhost/access.20160122-122424 /var/log/dirsrv/slapd-localhost/access.20160122-122438 /var/log/dirsrv/slapd-localhost/access.20160122-122603 /var/log/dirsrv/slapd-localhost/access.20160122-122608 /var/log/dirsrv/slapd-localhost/access.rotationinfo
Processing 6 Access Log(s)...

[006] /var/log/dirsrv/slapd-localhost/access.20160122-122207	size (bytes):      1148884

[005] /var/log/dirsrv/slapd-localhost/access.20160122-122424	size (bytes):      1048598

[004] /var/log/dirsrv/slapd-localhost/access.20160122-122438	size (bytes):      1379760

[003] /var/log/dirsrv/slapd-localhost/access.20160122-122603	size (bytes):      1572685

[002] /var/log/dirsrv/slapd-localhost/access.20160122-122608	size (bytes):      1142625

[001] /var/log/dirsrv/slapd-localhost/access	size (bytes):       555981


Total Log Lines Analysed:  79854


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:12:22:10
End of Logs:      22/Jan/2016:12:26:15

Processed Log Time:  0 Hours, 4 Minutes, 5 Seconds

Restarts:                     1
Total Connections:            11310
 - LDAP Connections:          11310
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  6
Total Operations:             22952
Total Results:                22951
Overall Performance:          100.0%

Searches:                     11526         (47.04/sec)  (2822.69/min)
Modifications:                6             (0.02/sec)  (1.47/min)
Adds:                         107           (0.44/sec)  (26.20/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        11312         (46.17/sec)  (2770.29/min)
...
...
...
Comment 4 Viktor Ashirov 2016-01-22 12:39 EST
Created attachment 1117311 [details]
access logs

[root@rhel7ds slapd-rhel7ds]# pwd
/var/log/dirsrv/slapd-rhel7ds
[root@rhel7ds slapd-rhel7ds]# logconv.pl /var/log/dirsrv/slapd-rhel7ds/access*
Access Log Analyzer 8.1
Command: logconv.pl /var/log/dirsrv/slapd-rhel7ds/access /var/log/dirsrv/slapd-rhel7ds/access.20160122-182552 /var/log/dirsrv/slapd-rhel7ds/access.20160122-182653 /var/log/dirsrv/slapd-rhel7ds/access.rotationinfo
Processing 3 Access Log(s)...

[003] /var/log/dirsrv/slapd-rhel7ds/access.20160122-182552	size (bytes):          485

[002] /var/log/dirsrv/slapd-rhel7ds/access.20160122-182653	size (bytes):       132687

[001] /var/log/dirsrv/slapd-rhel7ds/access	size (bytes):        45234


Total Log Lines Analysed:  2069


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:18:25:57
End of Logs:      22/Jan/2016:18:28:07

Processed Log Time:  0 Hours, 2 Minutes, 10 Seconds

Restarts:                     2
Total Connections:            13
 - LDAP Connections:          13
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  10
Total Operations:             1017
Total Results:                1017
Overall Performance:          100.0%

Searches:                     2             (0.02/sec)  (0.92/min)
Modifications:                1             (0.01/sec)  (0.46/min)
Adds:                         1001          (7.70/sec)  (462.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        13            (0.10/sec)  (6.00/min)

...
Looks good, but, when I do the same without the full path, speeds are zeros:

[root@rhel7ds slapd-rhel7ds]# logconv.pl access*
Access Log Analyzer 8.1
Command: logconv.pl access access.20160122-182552 access.20160122-182653 access.rotationinfo
Processing 3 Access Log(s)...

[003] access                        	size (bytes):        45234

[002] access.20160122-182552        	size (bytes):          485

[001] access.20160122-182653        	size (bytes):       132687


Total Log Lines Analysed:  2069


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:18:27:33
End of Logs:      22/Jan/2016:18:27:33

Processed Log Time:  0 Hours, 0 Minutes, 0 Seconds

Restarts:                     2
Total Connections:            13
 - LDAP Connections:          13
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  0
Total Operations:             1017
Total Results:                1017
Overall Performance:          100.0%

Searches:                     2             (0.00/sec)  (0.00/min)
Modifications:                1             (0.00/sec)  (0.00/min)
Adds:                         1001          (0.00/sec)  (0.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        13            (0.00/sec)  (0.00/min)


And when the wrong order is used:

[root@rhel7ds slapd-rhel7ds]# logconv.pl access.20160122-182653 access.20160122-182552
Access Log Analyzer 8.1
Command: logconv.pl access.20160122-182653 access.20160122-182552
Processing 2 Access Log(s)...

[002] access.20160122-182653        	size (bytes):       132687

[001] access.20160122-182552        	size (bytes):          485


Total Log Lines Analysed:  1541


----------- Access Log Output ------------

Start of Logs:    22/Jan/2016:18:26:34
End of Logs:      22/Jan/2016:18:25:57

Processed Log Time:  0 Hours, 0 Minutes, -37 Seconds

Restarts:                     2
Total Connections:            12
 - LDAP Connections:          12
 - LDAPI Connections:         0
 - LDAPS Connections:         0
 - StartTLS Extended Ops:     0
Peak Concurrent Connections:  10
Total Operations:             766
Total Results:                756
Overall Performance:          98.7%

Searches:                     1             (-0.03/sec)  (-1.62/min)
Modifications:                1             (-0.03/sec)  (-1.62/min)
Adds:                         752           (-20.32/sec)  (-1219.46/min)
Deletes:                      0             (-0.00/sec)  (-0.00/min)
Mod RDNs:                     0             (-0.00/sec)  (-0.00/min)
Compares:                     0             (-0.00/sec)  (-0.00/min)
Binds:                        12            (-0.32/sec)  (-19.46/min)
Comment 5 mreynolds 2016-01-29 10:01:21 EST
Upstream ticket:
https://fedorahosted.org/389/ticket/48446
Comment 6 mreynolds 2016-01-29 11:57:30 EST
Fixed upstream
Comment 7 Mike McCune 2016-03-28 19:13:32 EDT
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune@redhat.com with any questions
Comment 9 Viktor Ashirov 2016-06-08 10:01:22 EDT
Build tested:
389-ds-base-1.3.5.4-1.el7.x86_64

I tried different orders of files passed to logconv, it correctly shows speeds:

Searches:                     2             (0.02/sec)  (0.92/min)
Modifications:                1             (0.01/sec)  (0.46/min)
Adds:                         1001          (7.70/sec)  (462.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        13            (0.10/sec)  (6.00/min)

Marking as VERIFIED.
Comment 11 errata-xmlrpc 2016-11-03 16:38:57 EDT
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, 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://rhn.redhat.com/errata/RHSA-2016-2594.html

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