1103287 – logconv.pl memory continually grows

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 1103287 - logconv.pl memory continually grows

Summary: logconv.pl memory continually grows

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	389-ds-base
Sub Component:
Version:	6.6
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Target Release:	---
Assignee:	mreynolds
QA Contact:	Sankar Ramalingam
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1108874
TreeView+	depends on / blocked

Reported:	2014-05-30 15:27 UTC by mreynolds
Modified:	2020-09-13 20:39 UTC (History)
CC List:	5 users (show)
Fixed In Version:	389-ds-base-1.2.11.15-34.el6 389-ds-base-1.2.11.15-40.el6
Doc Type:	Bug Fix
Doc Text:	Cause: Processing a large amount of access logs without using any "verbose" options. Consequence: Memory continues to grow until the system is exhausted of available memory, or logs are completely processed. Fix: An old/unused feature was partially implemented,and it only consumed memory without a purpose. This partial feature was removed. Result: Memory remains stable regardless of the amount of logging that is being processed
Clone Of:
Clones:	1108874 (view as bug list)
Environment:
Last Closed:	2014-10-14 07:55:09 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	389ds 389-ds-base issues 783	0	None	None	None	2020-09-13 20:39:40 UTC
Red Hat Product Errata	RHBA-2014:1385	0	normal	SHIPPED_LIVE	389-ds-base bug fix and enhancement update	2014-10-14 01:27:42 UTC

Description mreynolds 2014-05-30 15:27:34 UTC

This bug is created as a clone of upstream ticket:
https://fedorahosted.org/389/ticket/47446

Logconv.pl, with no special options, memory usage steadily increases until the system runs out of memory.

Comment 1 mreynolds 2014-05-30 15:34:34 UTC

Fixed upstream

Verification steps

[1]  Use a access log with at least 1 million lines of logging, and place in /tmp
[2]  ./logconv.pl /tmp/access
[3]  Wait a few seconds, and start monitoring the process size

It should remain stable and not grow linearly.

Comment 3 srkrishn@redhat.com 2014-07-18 06:23:59 UTC

bug has been verified as seen below.
build tested 389-ds-base-1.2.11.15-33

logconv.pl /var/tmp/dirsr/access


1350000 Lines Processed
1375000 Lines Processed
1400000 Lines Processed
1425000 Lines Processed

13988 root      20   0  132m  11m 2228 R 99.7  0.2   0:06.50 perl
13991 root      20   0 15036 1240  928 R  0.3  0.0   0:00.03 top

13984 root      20   0  277m 156m 2228 R 99.7  2.0   2:55.93 perl
   61 root      39  19     0    0    0 S  1.0  0.0   0:02.18 khugepaged   

13984 root      20   0  311m 189m 2228 R 100.0  2.4   3:26.02 perl
13987 root      20   0 15036 1248  928 R  1.0  0.0   0:01.26 top      
   
   
   
   build tested 389-ds-base-1.2.11.15-38

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
14227 root      20   0  143m  16m 2788 R 100.0  0.2   0:43.13 perl                                                                          
14229 root      20   0 15036 1244  928 R  1.0  0.0   0:00.33 top                   
   
    825000 Lines Processed         74138502 of    282013304 bytes (26.289%)
    850000 Lines Processed         76387957 of    282013304 bytes (27.087%)
    875000 Lines Processed         78637972 of    282013304 bytes (27.884%)
   
14227 root      20   0  143m  16m 2788 R 99.5  0.2   1:46.45 perl
   
   1250000 Lines Processed        112335692 of    282013304 bytes (39.833%)
   1275000 Lines Processed        114585829 of    282013304 bytes (40.631%)
   1300000 Lines Processed        116830507 of    282013304 bytes (41.427%)
   
As mentioned above, the memory utilization does not grow linearly with the latest build of 389-ds-base-1.2.11.15-38
hence, marking the bug as verified.

Comment 4 Sankar Ramalingam 2014-07-23 16:31:35 UTC

Marking the bug as Verified as per previous comment

Comment 5 Rich Megginson 2014-08-18 15:53:48 UTC

The patch introduced a problem when using all of the following flags:

using logconv.pl -efcibaltnxrgjuyp accesslog
     
I got the following errors:
    Use of uninitialized value $1 in string ne at /usr/bin/logconv.pl line 2135, <LOG> line 113254.
    Use of uninitialized value $1 in array element at /usr/bin/logconv.pl line 2134, <LOG> line 113256.
    Use of uninitialized value $1 in string ne at /usr/bin/logconv.pl line 2135, <LOG> line 113256.
    Use of uninitialized value $1 in hash element at /usr/bin/logconv.pl line 2146, <LOG> line 113256.
    Use of uninitialized value $1 in array element at /usr/bin/logconv.pl line 2134, <LOG> line 113258.

tested on version:1.2.11.15 38.el6

Comment 6 srkrishn@redhat.com 2014-08-19 13:42:39 UTC

hi,
i tested verified logconv.pl script with a customer sourced access log file for testing its performance.
got the following output
    Processing 1 Access Log(s)...
     
    [00] /RHEL7/data/DS/6.0/logfile/en/access.20120131-000045       size (bytes):     58138502
         25000 Lines Processed          2279028 of     58138502 bytes (3.920%)
         50000 Lines Processed          4655574 of     58138502 bytes (8.008%)
         75000 Lines Processed          6953209 of     58138502 bytes (11.960%)
        100000 Lines Processed          9317693 of     58138502 bytes (16.027%)
        125000 Lines Processed         11813913 of     58138502 bytes (20.320%)
        150000 Lines Processed         14523110 of     58138502 bytes (24.980%)
        175000 Lines Processed         17138508 of     58138502 bytes (29.479%)
        200000 Lines Processed         19735952 of     58138502 bytes (33.946%)
        225000 Lines Processed         22297554 of     58138502 bytes (38.352%)
        250000 Lines Processed         24853780 of     58138502 bytes (42.749%)
        275000 Lines Processed         27495940 of     58138502 bytes (47.294%)
        300000 Lines Processed         30053026 of     58138502 bytes (51.692%)
        325000 Lines Processed         32682936 of     58138502 bytes (56.216%)
        350000 Lines Processed         35219682 of     58138502 bytes (60.579%)
        375000 Lines Processed         37772853 of     58138502 bytes (64.970%)
        400000 Lines Processed         40402948 of     58138502 bytes (69.494%)
        425000 Lines Processed         42998390 of     58138502 bytes (73.959%)
        450000 Lines Processed         45621276 of     58138502 bytes (78.470%)
        475000 Lines Processed         48071364 of     58138502 bytes (82.684%)
        500000 Lines Processed         50481556 of     58138502 bytes (86.830%)
        525000 Lines Processed         53007518 of     58138502 bytes (91.175%)
        550000 Lines Processed         55440476 of     58138502 bytes (95.359%)
        575000 Lines Processed         57790092 of     58138502 bytes (99.401%)
     
     
    Total Log Lines Analysed:  578797
     
    ----------- Access Log Output ------------
     
    Start of Logs:    31/Jan/2012:00:00:16
    End of Logs:      01/Feb/2012:00:00:45
     
    Processed Log Time:  0 Hours, 0 Minutes, 29 Seconds
     
    Restarts:                     0
    Total Connections:            146088
     - StartTLS Connections:      1
     - LDAPS Connections:         80491
     - LDAPI Connections:         0
    Peak Concurrent Connections:  6
    Total Operations:             127884
    Total Results:                127884
    Overall Performance:          100.0%
     
    Searches:                     18224         (628.41/sec)  (37704.83/min)
    Modifications:                37441         (1291.07/sec)  (77464.14/min)
    Adds:                         1843          (63.55/sec)  (3813.10/min)
    Deletes:                      1179          (40.66/sec)  (2439.31/min)
    Mod RDNs:                     0             (0.00/sec)  (0.00/min)
    Compares:                     0             (0.00/sec)  (0.00/min)
    Binds:                        15622         (538.69/sec)  (32321.38/min)
     
    Proxied Auth Operations:      0
    Persistent Searches:          0
    Internal Operations:          0
    Entry Operations:             0
    Extended Operations:          53575
     
    real    0m40.950s
    user    0m37.044s
    sys     0m3.751s

tested this on the latest build.1.2.11.15.40

Comment 7 srkrishn@redhat.com 2014-08-19 13:47:31 UTC

[root@hp-dl360g4-01 ~]# logconv.pl -efcibaltnxrgjuyp access.20120131-000045
Access Log Analyzer 8.0
Command: logconv.pl access.20120131-000045
Processing 1 Access Log(s)...
[001] access.20120131-000045        	size (bytes):    813938384
     25000 Lines Processed          2279028 of    813938384 bytes (0.280%)
     50000 Lines Processed          4655574 of    813938384 bytes (0.572%)
     75000 Lines Processed          6953209 of    813938384 bytes (0.854%)
    100000 Lines Processed          9317622 of    813938384 bytes (1.145%)

this command is not throwing any errors as mentioned in comment #5

hence marking the bug as verified

Comment 8 Sankar Ramalingam 2014-08-19 13:49:06 UTC

Based on previous comment from Sriram, marking it as Verified.

Comment 9 errata-xmlrpc 2014-10-14 07:55:09 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.

http://rhn.redhat.com/errata/RHBA-2014-1385.html

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