#47446 logconv.pl memory continually grows
Closed: Fixed None Opened 5 years ago by rmeggins.

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


I am seeing steady growth with logconv.pl in general. If I use the (-m/-M) option the growth is the same.

Also, the CSV report is already using DB Files.

I'm going to investigate the growth but I suspect it might be "normal"...

Resolved a significant memory leak around the file descriptor count parsing. Cleaned up other unnecessary memory usage, and made some minor performance improvements by avoiding gathering verbose stats when not using verbose stats.

{{{
Processed 7.5 lines of access log:

./logconv.pl /logs/access*

Before:

DATE - [TIME] ------- PID VSZ RSS PCPU
...
05/28-[10:49:36] ------- 7346 395496 239680 100 growth: 2244 k
05/28-[10:49:37] ------- 7346 397608 242056 100 growth: 2112 k
05/28-[10:49:38] ------- 7346 399720 243904 100 growth: 2112 k
05/28-[10:49:39] ------- 7346 401832 246016 100 growth: 2112 k
<done>

After:

DATE - [TIME] ------- PID VSZ RSS PCPU
...
05/28-[10:53:36] ------- 8378 172644 17064 99.8 growth: 0 k
05/28-[10:53:37] ------- 8378 172644 17064 99.8 growth: 0 k
05/28-[10:53:38] ------- 8378 172644 17064 99.8 growth: 0 k
05/28-[10:53:39] ------- 8378 172644 17064 99.8 growth: 0 k
<done>

}}}

Performance Improvement Summary

This improvement only affects the generic report and the CVS reports - but it does not affect the verbose options.

7.5 million lines of logging

{{{
Generic Report:

./logconv.pl /logs/access*

Master:
2m21.946s

Patch:
1m37.208s

~32% improvement
}}}

{{{
CVS Report:

./logconv.pl -m /tmp/csv.out /logs/access*

Master:
3m26

Patch:
2m51

~17% improvement
}}}

{{{
Full Verbose Report

./logconv.pl -V /logs/access*

Master:
5m34

Patch:
5m34

No improvement
}}}

I agree with Mark to back port this fix to the older version.

c476d41..805386c master -> master
commit 805386c

1472381..519c58e 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit 519c58e

803c86a..a5e636b 389-ds-base-1.3.1 -> 389-ds-base-1.3.1
commit a5e636bfff12098b0b73e8efbb44e8097c0c78b5

8155bea..bf4cbf1 389-ds-base-1.2.11 -> 389-ds-base-1.2.11
commit bf4cbf1

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.

To ssh://git.fedorahosted.org/git/389/ds.git
06dfa1d..81e5f14 389-ds-base-1.2.11 -> 389-ds-base-1.2.11
commit 81e5f14
Author: Rich Megginson rmeggins@redhat.com
Date: Mon Aug 18 09:59:47 2014 -0600
88c7de6..3be0931 389-ds-base-1.3.1 -> 389-ds-base-1.3.1
commit 3be093105fe5525fd66ac055ff58d48fbd0f823a
Author: Rich Megginson rmeggins@redhat.com
Date: Mon Aug 18 09:59:47 2014 -0600
3ff6d52..db9c4e7 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit db9c4e7
Author: Rich Megginson rmeggins@redhat.com
Date: Mon Aug 18 09:59:47 2014 -0600
8e1345a..c4f396d master -> master
commit c4f396d
Author: Rich Megginson rmeggins@redhat.com
Date: Mon Aug 18 09:59:47 2014 -0600

This patch has introduced a (small) regression. when there are autobinds with ldapi, the code enters into the
{{{ if($_ =~ /AUTOBIND dn=\"(.*)\"/) }}}
and compares {{{ $1 }}} with {{{ $rootDN }}}. Everything is ok until the next if concerning the usage
{{{ if($usage =~ /f/ || $usage =~ /u/ || $usage =~ /U/ || $usage =~ /b/ || $verb eq "yes") }}}

At this stage, {{{ $1 }}} is reset to {{{ undef }}} and the translate operator {{{ $tmpp =~ tr/A-Z/a-z/; }}} spits out
{{{
Use of uninitialized value in transliteration (tr///) at /Local/dirsrv/bin/logconv.pl line 2018, <$LOGFH> line 207.
Use of uninitialized value $tmpp in hash element at /Local/dirsrv/bin/logconv.pl line 2019, <$LOGFH> line 207.
}}}

The patch is trivial - just set the value of {{{ $tmpp }}} outside of the second if. For the logconv.pl from the branch 1.3.3.x :
{{{
--- ./dirsrv/bin/logconv.pl 2015-07-28 11:24:31.000000000 +0200
+++ /Local/dirsrv/bin/logconv.pl 2015-07-28 14:59:06.358309779 +0200
@@ -2013,8 +2013,8 @@
if($1 eq $rootDN){
$rootDNBindCount++;
}
+ $tmpp = $1;
if($usage =~ /f/ || $usage =~ /u/ || $usage =~ /U/ || $usage =~ /b/ || $verb eq "yes"){
- $tmpp = $1;
$tmpp =~ tr/A-Z/a-z/;
$hashes->{bindlist}->{$tmpp}++;
}
}}}

Since this bug is so old, I've opened a new bug for the regression - https://fedorahosted.org/389/ticket/48231

Metadata Update from @mreynolds:
- Issue assigned to mreynolds
- Issue set to the milestone: 1.2.11.30

2 years ago

Login to comment on this ticket.

Metadata