Skip Menu |

This queue is for tickets about the Sys-Syslog CPAN distribution.

Report information
The Basics
Id: 130154
Status: open
Priority: 0/
Queue: Sys-Syslog

People
Owner: Nobody in particular
Requestors: a.shikov [...] dtel-ix.net
Cc:
AdminCc:

Bug Information
Severity: (no value)
Broken in: (no value)
Fixed in: (no value)



Subject: Sys::Syslog 3.35 Memory Leak
Date: Tue, 23 Jul 2019 17:00:02 +0300
To: bug-Sys-Syslog [...] rt.cpan.org
From: Alexander Shikov <a.shikov [...] dtel-ix.net>
Hello! Recently we migrated some Perl scripts to another server. Both servers - FreeBSD. On the old server there were 11.2-RELEASE, Perl 5.24 and Sys::Syslog 0.33_01. On the new server there are 12.0-RELEASE, Perl 5.28 and Sys::Syslog 0.35. On a new server we've noticed an intensive memory leak. After investigation the trouble we've found that memory leak is caused by Sys::Syslog and can be re-produced by simple script: ----------------------------------------------------------------------------------------- #!/usr/local/bin/perl -w use strict; use Sys::Syslog qw(:standard :macros); openlog('yarpd-syslog', 'ndelay', LOG_LOCAL2); my $c = 0; my @chars = ("A".."Z", "a".."z", "0".."9", "." , "-", "_" ); while ($c++ <= 10000) { my $string = ''; $string .= $chars[rand @chars] for 1..32; for (1..512) { syslog(LOG_DEBUG, "DEBUG LOG %d/%d RANDOM STRING: %s", $c, $_, $string ); } sleep 1; } ----------------------------------------------------------------------------------------- Add the line below to syslog.conf to save log to file: local2.* /var/log/yarpd.log Then start script and check out the log file with tail -f. Right after script is started 'top' shows that memory utilization starts to grow rapidly: last pid: 44500; load averages: 1.12, 1.19, 1.22 up 21+05:23:33 15:21:28 105 processes: 2 running, 103 sleeping CPU: 43.2% user, 0.0% nice, 7.2% system, 0.4% interrupt, 49.2% idle Mem: 427M Active, 189M Inact, 6452K Laundry, 448M Wired, 200M Buf, 892M Free Swap: 4096M Total, 222M Used, 3874M Free, 5% Inuse PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND 45209 root 1 22 0 19M 8956K nanslp 0 0:00 1.11% perl [...] 45209 root 1 22 0 196M 186M nanslp 1 0:04 4.50% perl [...] 45209 root 1 22 0 266M 258M nanslp 0 0:05 4.64% perl [...] 45209 root 1 22 0 541M 534M nanslp 0 0:11 2.29% perl Tested on physical machine, on virtual machine - the situation is the same on both. It just depends on the number of messages per second. 512 was enough for VDS to trigger the problem, on physical machine I tested it with 9000. I tested the same script on old server as well, and there everything is fine. It was tested with any msg per second: 512, 4000, 9000 - problem is absent. Possibly there is a bug introduced between 0.33 and 0.35 versions. Thanks. -- Alexander Shikov Technical Staff, Digital Telecom IX Tel.: +380 44 201 14 07 Mob.: +380 50 410 30 57 http://dtel-ix.net/
On 2019-07-23 10:22:41, a.shikov@dtel-ix.net wrote: Show quoted text
> Hello!
Hello, Show quoted text
> Recently we migrated some Perl scripts to another server. > Both servers - FreeBSD. > > On the old server there were 11.2-RELEASE, Perl 5.24 and Sys::Syslog > 0.33_01. > On the new server there are 12.0-RELEASE, Perl 5.28 and Sys::Syslog > 0.35. > > On a new server we've noticed an intensive memory leak. After > investigation the trouble we've found that memory leak is caused > by Sys::Syslog and can be re-produced by simple script: > > ------------------------------------------------------------------ > #!/usr/local/bin/perl -w > > use strict; > use Sys::Syslog qw(:standard :macros); > > openlog('yarpd-syslog', 'ndelay', LOG_LOCAL2); > > my $c = 0; > > my @chars = ("A".."Z", "a".."z", "0".."9", "." , "-", "_" ); > > while ($c++ <= 10000) { > my $string = ''; > $string .= $chars[rand @chars] for 1..32; > for (1..512) { > syslog(LOG_DEBUG, "DEBUG LOG %d/%d RANDOM STRING: %s", > $c, $_, $string ); > } > sleep 1; > } > -------------------------------------------------------------------- > > Add the line below to syslog.conf to save log to file: > local2.* /var/log/yarpd.log > > Then start script and check out the log file with tail -f. > > Right after script is started 'top' shows that memory utilization > starts to grow rapidly: > > […] > > Tested on physical machine, on virtual machine - the situation is the > same on both. It just depends on the number of messages per second. > 512 was enough for VDS to trigger the problem, on physical machine > I tested it with 9000. > > I tested the same script on old server as well, and there everything > is fine. It was tested with any msg per second: 512, 4000, 9000 - > problem is absent. > > Possibly there is a bug introduced between 0.33 and 0.35 versions.
Using a VM image of FreeBSD 12.0, I installed Perl 5.28 with default options, which came with Sys::Syslog 0.35. I ran your script, which took hours to complete. Logging the output of ps(1) provided the output in cpan-rt-130154.log. After the first few lines, where perl allocates memory, the resident size stays stable to 9600 KB during the whole execution. Did you use the stock FreeBSD perl? Did you use a specific memory allocator or enabled some debugging option? Best Regards -- Close the world, txEn eht nepO.
Subject: cpan-rt-130154.log
$ while :; do ps auxw | grep [p]erl; done USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND maddingue 96735 0.0 0.6 15264 5944 0 R+ 22:21 0:00.00 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 0.6 15928 6464 0 R+ 22:21 0:00.00 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 0.7 16244 6944 0 R+ 22:21 0:00.01 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 0.8 17304 7824 0 R+ 22:21 0:00.01 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 0.8 18016 8416 0 R+ 22:21 0:00.02 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 0.9 18508 9012 0 R+ 22:21 0:00.02 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 0.9 18904 9488 0 R+ 22:21 0:00.03 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 R+ 22:21 0:00.03 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 0.0 1.0 19032 9600 0 S+ 22:21 0:00.04 /usr/local/bin/perl5.28.2 cpan-rt-130154.t [...] $ while :; do ps auxw | grep [p]erl; sleep 1; done USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.14 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.15 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.17 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.18 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.20 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.22 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.24 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.26 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 2:46.27 /usr/local/bin/perl5.28.2 cpan-rt-130154.t [...] maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.26 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.28 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.29 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.31 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.32 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.34 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.35 /usr/local/bin/perl5.28.2 cpan-rt-130154.t maddingue 96735 1.0 1.0 19032 9600 0 S+ 22:21 3:56.37 /usr/local/bin/perl5.28.2 cpan-rt-130154.t