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 1301097 - logconv.pl displays negative operation speeds
Summary: logconv.pl displays negative operation speeds
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: 389-ds-base
Version: 7.3
Hardware: Unspecified
OS: Unspecified
low
low
Target Milestone: rc
: ---
Assignee: Noriko Hosoi
QA Contact: Viktor Ashirov
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-01-22 15:11 UTC by Viktor Ashirov
Modified: 2020-09-13 21:39 UTC (History)
3 users (show)

Fixed In Version: 389-ds-base-1.3.5.2-1.el7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-11-03 20:38:57 UTC
Target Upstream Version:
Embargoed:

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


Links
System ID Private Priority Status Summary Last Updated
Github 389ds 389-ds-base issues 1768 0 None None None 2020-09-13 21:39:03 UTC
Red Hat Product Errata RHSA-2016:2594 0 normal SHIPPED_LIVE Moderate: 389-ds-base security, bug fix, and enhancement update 2016-11-03 12:11:08 UTC

Description Viktor Ashirov 2016-01-22 15:11:03 UTC 
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 17:12:54 UTC 
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 17:29:44 UTC 
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 17:39:38 UTC 
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 15:01:21 UTC 
Upstream ticket:
https://fedorahosted.org/389/ticket/48446
Comment 6 mreynolds 2016-01-29 16:57:30 UTC 
Fixed upstream
Comment 7 Mike McCune 2016-03-28 23:13:32 UTC 
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions
Comment 9 Viktor Ashirov 2016-06-08 14:01:22 UTC 
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 20:38:57 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, 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.