Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Memory Leak in perl 5.28 and 5.30 #17105

Closed
p5pRT opened this issue Jul 23, 2019 · 20 comments
Closed

Memory Leak in perl 5.28 and 5.30 #17105

p5pRT opened this issue Jul 23, 2019 · 20 comments

Comments

@p5pRT
Copy link

p5pRT commented Jul 23, 2019

Migrated from rt.perl.org#134305 (status was 'open')

Searchable as RT134305$

@p5pRT
Copy link
Author

p5pRT commented Jul 23, 2019

From a.shikov@dtel-ix.net

Created by a.shikov@dtel-ix.net

Hello!

Recently we migrated some Perl scripts from old to another server.
Both servers - FreeBSD.
On the old server there were 11.2-RELEASE, Perl 5.24.
On the new server there are 12.0-RELEASE, Perl 5.28.2.

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
reproduced by simple script​:

---------------------------------------------------------------------------
#!/usr/local/bin/perl -w

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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.

The problem is not with Sys​::Syslog module, because with Unix​::Syslog the problem is the same.

After that I tested this script with three major versions of Perl​: 5.26.3, 5.28.1, 5.28.2 and 5.30.0
on my desktop with FreeBSD 12.0-RELEASE.

Only with 5.26.3 the script does not eats memory. The rest three versions have this
problem. It looks like in 5.28 there is a kind of bug causing memory leak if there is
intensive I/O operation invoked, for example, by generating of big number of syslog messages.

Any suggestions are kindly appreciated. Thanks!

Perl Info

Flags:
    category=core
    severity=high

Site configuration information for perl 5.28.1:

Configured by mat at Thu Nov 29 21:03:47 EET 2018.

Summary of my perl5 (revision 5 version 28 subversion 1) configuration:
   
  Platform:
    osname=freebsd
    osvers=12.0-release-p1
    archname=amd64-freebsd-thread-multi
    uname='freebsd crete.itcons.net.ua 12.0-release-p1 freebsd 12.0-release-p1 r342298 generic amd64 '
    config_args='-sde -Dprefix=/usr/local -Dlibperl=libperl.so.5.28.1 -Darchlib=/usr/local/lib/perl5/5.28/mach -Dprivlib=/usr/local/lib/perl5/5.28 -Dman3dir=/usr/local/lib/perl5/5.28/perl/man/man3 -Dman1dir=/usr/local/lib/perl5/5.28/perl/man/man1 -Dsitearch=/usr/local/lib/perl5/site_perl/mach/5.28 -Dsitelib=/usr/local/lib/perl5/site_perl -Dscriptdir=/usr/local/bin -Dsiteman3dir=/usr/local/lib/perl5/site_perl/man/man3 -Dsiteman1dir=/usr/local/lib/perl5/site_perl/man/man1 -Ui_malloc -Ui_iconv -Uinstallusrbinperl -Dusenm=n -Dcc=cc -Duseshrplib -Dinc_version_list=none -Dcf_by=mat -Dcf_email=mat@FreeBSD.org -Dcf_time=Thu Nov 29 21:03:47 EET 2018 -Alddlflags=-L/usr/ports/lang/perl5.28/work/perl-5.28.1 -L/usr/local/lib/perl5/5.28/mach/CORE -lperl -Dshrpldflags=$(LDDLFLAGS:N-L/usr/ports/lang/perl5.28/work/perl-5.28.1:N-L/usr/local/lib/perl5/5.28/mach/CORE:N-lperl) -Wl,-soname,$(LIBPERL:R)
-Doptimize=-O2 -pipe  -fstack-protector -fno-strict-aliasing  -Ddefault_inc_excludes_dot=n -Uusedtrace -Ui_gdbm -Dusemultiplicity=y -Dusemymalloc=n -Dusesitecustomize -Dusethreads=y'
    hint=recommended
    useposix=true
    d_sigaction=define
    useithreads=define
    usemultiplicity=define
    use64bitint=define
    use64bitall=define
    uselongdouble=undef
    usemymalloc=n
    default_inc_excludes_dot=undef
    bincompat5005=undef
  Compiler:
    cc='cc'
    ccflags ='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -D_FORTIFY_SOURCE=2'
    optimize='-O2 -pipe -fstack-protector -fno-strict-aliasing '
    cppflags='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
    ccversion=''
    gccversion='4.2.1 Compatible FreeBSD Clang 6.0.1 (tags/RELEASE_601/final 335540)'
    gccosandvers=''
    intsize=4
    longsize=8
    ptrsize=8
    doublesize=8
    byteorder=12345678
    doublekind=3
    d_longlong=define
    longlongsize=8
    d_longdbl=define
    longdblsize=16
    longdblkind=3
    ivtype='long'
    ivsize=8
    nvtype='double'
    nvsize=8
    Off_t='off_t'
    lseeksize=8
    alignbytes=8
    prototype=define
  Linker and Libraries:
    ld='cc'
    ldflags ='-pthread -Wl,-E  -fstack-protector-strong -L/usr/local/lib'
    libpth=/usr/lib /usr/local/lib /usr/lib/clang/6.0.1/lib /usr/lib
    libs=-lpthread -lm -lcrypt -lutil
    perllibs=-lpthread -lm -lcrypt -lutil
    libc=
    so=so
    useshrplib=true
    libperl=libperl.so.5.28.1
    gnulibc_version=''
  Dynamic Linking:
    dlsrc=dl_dlopen.xs
    dlext=so
    d_dlsymun=undef
    ccdlflags='  -Wl,-R/usr/local/lib/perl5/5.28/mach/CORE'
    cccdlflags='-DPIC -fPIC'
    lddlflags='-shared	-L/usr/local/lib/perl5/5.28/mach/CORE -lperl -L/usr/local/lib -fstack-protector-strong'



@INC for perl 5.28.1:
    /usr/local/lib/perl5/site_perl/mach/5.28
    /usr/local/lib/perl5/site_perl
    /usr/local/lib/perl5/5.28/mach
    /usr/local/lib/perl5/5.28


Environment for perl 5.28.1:
    HOME=/home/minotaur
    LANG=uk_UA.UTF-8
    LANGUAGE (unset)
    LC_COLLATE=C
    LD_LIBRARY_PATH (unset)
    LOGDIR (unset)
    PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/games:/usr/local/sbin:/usr/local/bin:/home/minotaur/bin
    PERLDOC_PAGER=less -sR
    PERL_BADLANG (unset)
    SHELL=/bin/tcsh

@p5pRT
Copy link
Author

p5pRT commented Jul 24, 2019

From @jkeenan

On Tue, 23 Jul 2019 17​:22​:46 GMT, a.shikov@​dtel-ix.net wrote​:

This is a bug report for perl from a.shikov@​dtel-ix.net,
generated with the help of perlbug 1.41 running under perl 5.28.1.

-----------------------------------------------------------------
[Please describe your issue here]

Hello!

Recently we migrated some Perl scripts from old to another server.
Both servers - FreeBSD.
On the old server there were 11.2-RELEASE, Perl 5.24.
On the new server there are 12.0-RELEASE, Perl 5.28.2.

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
reproduced by simple script​:

---------------------------------------------------------------------------
#!/usr/local/bin/perl -w

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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.

The problem is not with Sys​::Syslog module, because with Unix​::Syslog
the problem is the same.

After that I tested this script with three major versions of Perl​:
5.26.3, 5.28.1, 5.28.2 and 5.30.0
on my desktop with FreeBSD 12.0-RELEASE.

Only with 5.26.3 the script does not eats memory. The rest three
versions have this
problem. It looks like in 5.28 there is a kind of bug causing memory
leak if there is
intensive I/O operation invoked, for example, by generating of big
number of syslog messages.

Any suggestions are kindly appreciated. Thanks!

1. I'm a bit confused by this report. Near the top you say, "we've found that memory leak is caused by Sys​::Syslog". But later on, you say, "The problem is not with Sys​::Syslog module, because with Unix​::Syslog the problem is the same." Which is it?

2. Have you tried your diagnostic script on FreeBSD-11 with perl-5.26, 5.28 and 5.30? What results do you get there? (We have to try to distinguish between changes in Perl and changes in FreeBSD.)

Thank you very much.

--
James E Keenan (jkeenan@​cpan.org)

@p5pRT
Copy link
Author

p5pRT commented Jul 24, 2019

The RT System itself - Status changed from 'new' to 'open'

@p5pRT
Copy link
Author

p5pRT commented Jul 24, 2019

From @jkeenan

On Tue, 23 Jul 2019 17​:22​:46 GMT, a.shikov@​dtel-ix.net wrote​:

This is a bug report for perl from a.shikov@​dtel-ix.net,
generated with the help of perlbug 1.41 running under perl 5.28.1.

-----------------------------------------------------------------
[Please describe your issue here]

Hello!

Recently we migrated some Perl scripts from old to another server.
Both servers - FreeBSD.
On the old server there were 11.2-RELEASE, Perl 5.24.
On the new server there are 12.0-RELEASE, Perl 5.28.2.

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
reproduced by simple script​:

---------------------------------------------------------------------------
#!/usr/local/bin/perl -w

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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

I tried that (as well as another spelling including this ticket number) but each time the output was simply appended to /var/log/debug.log.

How can I get this to go to a file just for this problem?

Thank you very much.

--
James E Keenan (jkeenan@​cpan.org)

@p5pRT
Copy link
Author

p5pRT commented Jul 26, 2019

From @rootkwok

Hello,

Interesting case, looks like it is a problem with locale implementation. I
am
looking into locale.c to see if I can find anything. Can you try to run your
perl script with LC_ALL=C and see if the memory leak problem persists?
Thanks a lot.

Best regards,
Baggio

(via RT) <perlbug-followup@​perl.org> æ�¼ 2019å¹´7æ��26æ�¥ é�±äº� ä¸�å��6​:50寫é��ï¼�

# New Ticket Created by
# Please include the string​: [perl #134305]
# in the subject line of all future correspondence about this issue.
# <URL​: https://rt-archive.perl.org/perl5/Ticket/Display.html?id=134305 >

This is a bug report for perl from a.shikov@​dtel-ix.net,
generated with the help of perlbug 1.41 running under perl 5.28.1.

-----------------------------------------------------------------
[Please describe your issue here]

Hello!

Recently we migrated some Perl scripts from old to another server.
Both servers - FreeBSD.
On the old server there were 11.2-RELEASE, Perl 5.24.
On the new server there are 12.0-RELEASE, Perl 5.28.2.

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
reproduced by simple script​:

---------------------------------------------------------------------------
#!/usr/local/bin/perl -w

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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.

The problem is not with Sys​::Syslog module, because with Unix​::Syslog the
problem is the same.

After that I tested this script with three major versions of Perl​: 5.26.3,
5.28.1, 5.28.2 and 5.30.0
on my desktop with FreeBSD 12.0-RELEASE.

Only with 5.26.3 the script does not eats memory. The rest three versions
have this
problem. It looks like in 5.28 there is a kind of bug causing memory leak
if there is
intensive I/O operation invoked, for example, by generating of big number
of syslog messages.

Any suggestions are kindly appreciated. Thanks!

[Please do not change anything below this line]
-----------------------------------------------------------------
---
Flags​:
category=core
severity=high
---
Site configuration information for perl 5.28.1​:

Configured by mat at Thu Nov 29 21​:03​:47 EET 2018.

Summary of my perl5 (revision 5 version 28 subversion 1) configuration​:

Platform​:
osname=freebsd
osvers=12.0-release-p1
archname=amd64-freebsd-thread-multi
uname='freebsd crete.itcons.net.ua 12.0-release-p1 freebsd
12.0-release-p1 r342298 generic amd64 '
config_args='-sde -Dprefix=/usr/local -Dlibperl=libperl.so.5.28.1
-Darchlib=/usr/local/lib/perl5/5.28/mach
-Dprivlib=/usr/local/lib/perl5/5.28
-Dman3dir=/usr/local/lib/perl5/5.28/perl/man/man3
-Dman1dir=/usr/local/lib/perl5/5.28/perl/man/man1
-Dsitearch=/usr/local/lib/perl5/site_perl/mach/5.28
-Dsitelib=/usr/local/lib/perl5/site_perl -Dscriptdir=/usr/local/bin
-Dsiteman3dir=/usr/local/lib/perl5/site_perl/man/man3
-Dsiteman1dir=/usr/local/lib/perl5/site_perl/man/man1 -Ui_malloc -Ui_iconv
-Uinstallusrbinperl -Dusenm=n -Dcc=cc -Duseshrplib -Dinc_version_list=none
-Dcf_by=mat -Dcf_email=mat@​FreeBSD.org -Dcf_time=Thu Nov 29 21​:03​:47 EET
2018 -Alddlflags=-L/usr/ports/lang/perl5.28/work/perl-5.28.1
-L/usr/local/lib/perl5/5.28/mach/CORE -lperl
-Dshrpldflags=$(LDDLFLAGS​:N-L/usr/ports/lang/perl5.28/work/perl-5.28.1​:N-L/usr/local/lib/perl5/5.28/mach/CORE​:N-lperl)
-Wl,-soname,$(LIBPERL​:R)
-Doptimize=-O2 -pipe -fstack-protector -fno-strict-aliasing
-Ddefault_inc_excludes_dot=n -Uusedtrace -Ui_gdbm -Dusemultiplicity=y
-Dusemymalloc=n -Dusesitecustomize -Dusethreads=y'
hint=recommended
useposix=true
d_sigaction=define
useithreads=define
usemultiplicity=define
use64bitint=define
use64bitall=define
uselongdouble=undef
usemymalloc=n
default_inc_excludes_dot=undef
bincompat5005=undef
Compiler​:
cc='cc'
ccflags ='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing
-pipe -fstack-protector-strong -I/usr/local/include -D_FORTIFY_SOURCE=2'
optimize='-O2 -pipe -fstack-protector -fno-strict-aliasing '
cppflags='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing
-pipe -fstack-protector-strong -I/usr/local/include'
ccversion=''
gccversion='4.2.1 Compatible FreeBSD Clang 6.0.1
(tags/RELEASE_601/final 335540)'
gccosandvers=''
intsize=4
longsize=8
ptrsize=8
doublesize=8
byteorder=12345678
doublekind=3
d_longlong=define
longlongsize=8
d_longdbl=define
longdblsize=16
longdblkind=3
ivtype='long'
ivsize=8
nvtype='double'
nvsize=8
Off_t='off_t'
lseeksize=8
alignbytes=8
prototype=define
Linker and Libraries​:
ld='cc'
ldflags ='-pthread -Wl,-E -fstack-protector-strong -L/usr/local/lib'
libpth=/usr/lib /usr/local/lib /usr/lib/clang/6.0.1/lib /usr/lib
libs=-lpthread -lm -lcrypt -lutil
perllibs=-lpthread -lm -lcrypt -lutil
libc=
so=so
useshrplib=true
libperl=libperl.so.5.28.1
gnulibc_version=''
Dynamic Linking​:
dlsrc=dl_dlopen.xs
dlext=so
d_dlsymun=undef
ccdlflags=' -Wl,-R/usr/local/lib/perl5/5.28/mach/CORE'
cccdlflags='-DPIC -fPIC'
lddlflags='-shared -L/usr/local/lib/perl5/5.28/mach/CORE -lperl
-L/usr/local/lib -fstack-protector-strong'

---
@​INC for perl 5.28.1​:
/usr/local/lib/perl5/site_perl/mach/5.28
/usr/local/lib/perl5/site_perl
/usr/local/lib/perl5/5.28/mach
/usr/local/lib/perl5/5.28

---
Environment for perl 5.28.1​:
HOME=/home/minotaur
LANG=uk_UA.UTF-8
LANGUAGE (unset)
LC_COLLATE=C
LD_LIBRARY_PATH (unset)
LOGDIR (unset)

PATH=/sbin​:/bin​:/usr/sbin​:/usr/bin​:/usr/games​:/usr/local/sbin​:/usr/local/bin​:/home/minotaur/bin
PERLDOC_PAGER=less -sR
PERL_BADLANG (unset)
SHELL=/bin/tcsh

@p5pRT
Copy link
Author

p5pRT commented Jul 26, 2019

From a.shikov@dtel-ix.net

On Fri, Jul 26, 2019 at 11​:50​:04 +0800, é�­æ¨�è�° wrote​:

Hello,

Interesting case, looks like it is a problem with locale implementation. I
am
looking into locale.c to see if I can find anything. Can you try to run your
perl script with LC_ALL=C and see if the memory leak problem persists?
Thanks a lot.

Best regards,
Baggio

Hello!

Dear Baggio,

yes, you're right. With env LC_ALL=C script executes without leak​:

top -b | grep perl
20006 minotaur 1 81 0 19M 9716K RUN 1​:22 26.95% perl5.30.0
20014 minotaur 1 52 0 19M 9724K RUN 0​:44 25.00% perl5.30.0
19991 root 1 52 0 19M 9720K nanslp 0​:44 23.97% perl5.30.0

O_o

(via RT) <perlbug-followup@​perl.org> æ�¼ 2019å¹´7æ��26æ�¥ é�±äº� ä¸�å��6​:50寫é��ï¼�

# New Ticket Created by
# Please include the string​: [perl #134305]
# in the subject line of all future correspondence about this issue.
# <URL​: https://rt-archive.perl.org/perl5/Ticket/Display.html?id=134305 >

This is a bug report for perl from a.shikov@​dtel-ix.net,
generated with the help of perlbug 1.41 running under perl 5.28.1.

-----------------------------------------------------------------
[Please describe your issue here]

Hello!

Recently we migrated some Perl scripts from old to another server.
Both servers - FreeBSD.
On the old server there were 11.2-RELEASE, Perl 5.24.
On the new server there are 12.0-RELEASE, Perl 5.28.2.

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
reproduced by simple script​:

---------------------------------------------------------------------------
#!/usr/local/bin/perl -w

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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.

The problem is not with Sys​::Syslog module, because with Unix​::Syslog the
problem is the same.

After that I tested this script with three major versions of Perl​: 5.26.3,
5.28.1, 5.28.2 and 5.30.0
on my desktop with FreeBSD 12.0-RELEASE.

Only with 5.26.3 the script does not eats memory. The rest three versions
have this
problem. It looks like in 5.28 there is a kind of bug causing memory leak
if there is
intensive I/O operation invoked, for example, by generating of big number
of syslog messages.

Any suggestions are kindly appreciated. Thanks!

[Please do not change anything below this line]
-----------------------------------------------------------------
---
Flags​:
category=core
severity=high
---
Site configuration information for perl 5.28.1​:

Configured by mat at Thu Nov 29 21​:03​:47 EET 2018.

Summary of my perl5 (revision 5 version 28 subversion 1) configuration​:

Platform​:
osname=freebsd
osvers=12.0-release-p1
archname=amd64-freebsd-thread-multi
uname='freebsd crete.itcons.net.ua 12.0-release-p1 freebsd
12.0-release-p1 r342298 generic amd64 '
config_args='-sde -Dprefix=/usr/local -Dlibperl=libperl.so.5.28.1
-Darchlib=/usr/local/lib/perl5/5.28/mach
-Dprivlib=/usr/local/lib/perl5/5.28
-Dman3dir=/usr/local/lib/perl5/5.28/perl/man/man3
-Dman1dir=/usr/local/lib/perl5/5.28/perl/man/man1
-Dsitearch=/usr/local/lib/perl5/site_perl/mach/5.28
-Dsitelib=/usr/local/lib/perl5/site_perl -Dscriptdir=/usr/local/bin
-Dsiteman3dir=/usr/local/lib/perl5/site_perl/man/man3
-Dsiteman1dir=/usr/local/lib/perl5/site_perl/man/man1 -Ui_malloc -Ui_iconv
-Uinstallusrbinperl -Dusenm=n -Dcc=cc -Duseshrplib -Dinc_version_list=none
-Dcf_by=mat -Dcf_email=mat@​FreeBSD.org -Dcf_time=Thu Nov 29 21​:03​:47 EET
2018 -Alddlflags=-L/usr/ports/lang/perl5.28/work/perl-5.28.1
-L/usr/local/lib/perl5/5.28/mach/CORE -lperl
-Dshrpldflags=$(LDDLFLAGS​:N-L/usr/ports/lang/perl5.28/work/perl-5.28.1​:N-L/usr/local/lib/perl5/5.28/mach/CORE​:N-lperl)
-Wl,-soname,$(LIBPERL​:R)
-Doptimize=-O2 -pipe -fstack-protector -fno-strict-aliasing
-Ddefault_inc_excludes_dot=n -Uusedtrace -Ui_gdbm -Dusemultiplicity=y
-Dusemymalloc=n -Dusesitecustomize -Dusethreads=y'
hint=recommended
useposix=true
d_sigaction=define
useithreads=define
usemultiplicity=define
use64bitint=define
use64bitall=define
uselongdouble=undef
usemymalloc=n
default_inc_excludes_dot=undef
bincompat5005=undef
Compiler​:
cc='cc'
ccflags ='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing
-pipe -fstack-protector-strong -I/usr/local/include -D_FORTIFY_SOURCE=2'
optimize='-O2 -pipe -fstack-protector -fno-strict-aliasing '
cppflags='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing
-pipe -fstack-protector-strong -I/usr/local/include'
ccversion=''
gccversion='4.2.1 Compatible FreeBSD Clang 6.0.1
(tags/RELEASE_601/final 335540)'
gccosandvers=''
intsize=4
longsize=8
ptrsize=8
doublesize=8
byteorder=12345678
doublekind=3
d_longlong=define
longlongsize=8
d_longdbl=define
longdblsize=16
longdblkind=3
ivtype='long'
ivsize=8
nvtype='double'
nvsize=8
Off_t='off_t'
lseeksize=8
alignbytes=8
prototype=define
Linker and Libraries​:
ld='cc'
ldflags ='-pthread -Wl,-E -fstack-protector-strong -L/usr/local/lib'
libpth=/usr/lib /usr/local/lib /usr/lib/clang/6.0.1/lib /usr/lib
libs=-lpthread -lm -lcrypt -lutil
perllibs=-lpthread -lm -lcrypt -lutil
libc=
so=so
useshrplib=true
libperl=libperl.so.5.28.1
gnulibc_version=''
Dynamic Linking​:
dlsrc=dl_dlopen.xs
dlext=so
d_dlsymun=undef
ccdlflags=' -Wl,-R/usr/local/lib/perl5/5.28/mach/CORE'
cccdlflags='-DPIC -fPIC'
lddlflags='-shared -L/usr/local/lib/perl5/5.28/mach/CORE -lperl
-L/usr/local/lib -fstack-protector-strong'

---
@​INC for perl 5.28.1​:
/usr/local/lib/perl5/site_perl/mach/5.28
/usr/local/lib/perl5/site_perl
/usr/local/lib/perl5/5.28/mach
/usr/local/lib/perl5/5.28

---
Environment for perl 5.28.1​:
HOME=/home/minotaur
LANG=uk_UA.UTF-8
LANGUAGE (unset)
LC_COLLATE=C
LD_LIBRARY_PATH (unset)
LOGDIR (unset)

PATH=/sbin​:/bin​:/usr/sbin​:/usr/bin​:/usr/games​:/usr/local/sbin​:/usr/local/bin​:/home/minotaur/bin
PERLDOC_PAGER=less -sR
PERL_BADLANG (unset)
SHELL=/bin/tcsh

--
Alexander Shikov
Technical Staff, Digital Telecom IX
Tel.​: +380 44 201 14 07
Mob.​: +380 50 410 30 57
http​://dtel-ix.net/

@p5pRT
Copy link
Author

p5pRT commented Jul 27, 2019

From a.shikov@dtel-ix.net

Hello!

On Wed, Jul 24, 2019 at 15​:07​:48 -0700, James E Keenan via RT wrote​:

Add the line below to syslog.conf to save log to file​:
local2.* /var/log/yarpd.log

I tried that (as well as another spelling including this ticket number) but each time the output was simply appended to /var/log/debug.log.

How can I get this to go to a file just for this problem?

It does not matter. I just described closely our environment but problem can
be triggered with default syslogd configuration file as well

I repeated a test some minutes ago.
I've started three scripts, each with different version of perl​:

# ps ax|grep syslog-demo :
/home/minotaur>ps ax|grep syslog-demo
96010 9 S+ 0​:00,00 grep syslog-demo
96008 10 S+ 0​:00,43 /usr/local/bin/perl5.30.0 -w ./syslog-demo-5.30.pl
96007 11 S+ 0​:00,60 /usr/local/bin/perl5.28.2 -w ./syslog-demo-5.28.pl (perl)
96006 15 S+ 0​:00,75 /usr/local/bin/perl5.26.3 -w ./syslog-demo-5.26.pl

The results are​:

<9​:46​:18> # top -b | grep perl
96007 root 1 30 0 522M 515M nanslp 3 0​:05 14.26% perl
96008 root 1 31 0 412M 401M nanslp 3 0​:05 14.16% perl5.30.0
96006 root 1 25 0 17M 8624K nanslp 0 0​:04 7.57% perl5.26.3

<9​:46​:19> # top -b | grep perl
96007 root 1 30 0 543M 537M nanslp 1 0​:06 14.36% perl
96008 root 1 31 0 434M 423M nanslp 3 0​:05 14.26% perl5.30.0
96006 root 1 25 0 17M 8624K nanslp 0 0​:04 7.57% perl5.26.3

<9​:46​:20> # top -b | grep perl
96007 root 1 30 0 564M 559M nanslp 1 0​:06 14.45% perl
96008 root 1 31 0 455M 446M nanslp 2 0​:05 14.36% perl5.30.0
96006 root 1 25 0 17M 8624K nanslp 2 0​:04 7.57% perl5.26.3

<9​:46​:21> # top -b | grep perl
96007 root 1 28 0 565M 559M CPU1 1 0​:06 12.70% perl
96008 root 1 31 0 455M 446M nanslp 2 0​:05 12.70% perl5.30.0
96006 root 1 25 0 17M 8624K nanslp 1 0​:04 7.67% perl5.26.3

<9​:46​:22> # top -b | grep perl
96007 root 1 30 0 586M 581M nanslp 0 0​:06 14.45% perl
96008 root 1 31 0 476M 468M nanslp 2 0​:05 14.45% perl5.30.0
96006 root 1 25 0 17M 8624K nanslp 1 0​:04 7.67% perl5.26.3

<9​:46​:23> # top -b | grep perl
96007 root 1 31 0 607M 603M nanslp 3 0​:06 14.70% perl
96008 root 1 31 0 498M 490M nanslp 2 0​:06 14.70% perl5.30.0
96006 root 1 25 0 17M 8624K nanslp 1 0​:04 7.67% perl5.26.3

Also I tested that on FreeBSD 11.2-RELEASE. On 11.2 the problem is absent.
So it seems to be OS-specific​:

1. The problem is present in FreeBSD 12.0-RELEASE.
2. The problem is only with Perl versions greater than 5.26​: 5.28 and 5.30.

Thanks.

--
Alexander Shikov
Technical Staff, Digital Telecom IX
Tel.​: +380 44 201 14 07
Mob.​: +380 50 410 30 57
http​://dtel-ix.net/

@p5pRT
Copy link
Author

p5pRT commented Jul 30, 2019

From @tonycoz

On Tue, 23 Jul 2019 10​:22​:46 -0700, a.shikov@​dtel-ix.net wrote​:

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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;
}

This simplifies down to​:

use POSIX qw(setlocale LC_TIME);

while (1) {
  setlocale(LC_TIME, "en_AU.UTF-8");
}

Unfortunately valgrind[1] says there's no leaks​:

==28285== HEAP SUMMARY​:
==28285== in use at exit​: 0 bytes in 0 blocks
==28285== total heap usage​: 0 allocs, 0 frees, 0 bytes allocated
==28285==
==28285== All heap blocks were freed -- no leaks are possible
==28285==

I see a similar issue with the following C code​:

#include <locale.h>

int main() {
  while (1) {
  locale_t n = newlocale(LC_TIME_MASK, "en_AU.UTF-8", (locale_t)0);
  locale_t old = uselocale(n);
  uselocale(old);
  freelocale(n);
  }
}

which I believe is handling the locale objects correctly, so I suspect this is a FreeBSD libc issue.

Tony

[1] from pkg install valgrind

@p5pRT
Copy link
Author

p5pRT commented Jul 31, 2019

From a.shikov@dtel-ix.net

Hello!

On Mon, Jul 29, 2019 at 22​:35​:27 -0700, Tony Cook via RT wrote​:

On Tue, 23 Jul 2019 10​:22​:46 -0700, a.shikov@​dtel-ix.net wrote​:

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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;
}

This simplifies down to​:

use POSIX qw(setlocale LC_TIME);

while (1) {
setlocale(LC_TIME, "en_AU.UTF-8");
}

Unfortunately valgrind[1] says there's no leaks​:

==28285== HEAP SUMMARY​:
==28285== in use at exit​: 0 bytes in 0 blocks
==28285== total heap usage​: 0 allocs, 0 frees, 0 bytes allocated
==28285==
==28285== All heap blocks were freed -- no leaks are possible
==28285==

I see a similar issue with the following C code​:

#include <locale.h>

int main() {
while (1) {
locale_t n = newlocale(LC_TIME_MASK, "en_AU.UTF-8", (locale_t)0);
locale_t old = uselocale(n);
uselocale(old);
freelocale(n);
}
}

which I believe is handling the locale objects correctly, so I suspect this is a FreeBSD libc issue.

Thank you for pointing this out.
Does this mean that Perl versions 5.26 and 5.28 handle locales in different way?

And what's strange is that your C code results to same memory leak on both 11.2-RELEASE
and 12.0-RELEASE, but I'm not able to reproduce an issue with Perl 5.28 on 11.2-RELEASE.

I've filled the bug in FreeBSD Bugzilla. Let's see the findings there as well.
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=239520

--
Alexander Shikov
Technical Staff, Digital Telecom IX
Tel.​: +380 44 201 14 07
Mob.​: +380 50 410 30 57
http​://dtel-ix.net/

@p5pRT
Copy link
Author

p5pRT commented Jul 31, 2019

From @tonycoz

On Tue, 30 Jul 2019 21​:23​:10 -0700, a.shikov@​dtel-ix.net wrote​:

Hello!

On Mon, Jul 29, 2019 at 22​:35​:27 -0700, Tony Cook via RT wrote​:

On Tue, 23 Jul 2019 10​:22​:46 -0700, a.shikov@​dtel-ix.net wrote​:

use strict;
use Sys​::Syslog qw(​:standard :macros);

openlog('syslog-demo', '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;
}

This simplifies down to​:

use POSIX qw(setlocale LC_TIME);

while (1) {
setlocale(LC_TIME, "en_AU.UTF-8");
}

Unfortunately valgrind[1] says there's no leaks​:

==28285== HEAP SUMMARY​:
==28285== in use at exit​: 0 bytes in 0 blocks
==28285== total heap usage​: 0 allocs, 0 frees, 0 bytes allocated
==28285==
==28285== All heap blocks were freed -- no leaks are possible
==28285==

I see a similar issue with the following C code​:

#include <locale.h>

int main() {
while (1) {
locale_t n = newlocale(LC_TIME_MASK, "en_AU.UTF-8", (locale_t)0);
locale_t old = uselocale(n);
uselocale(old);
freelocale(n);
}
}

which I believe is handling the locale objects correctly, so I
suspect this is a FreeBSD libc issue.

Thank you for pointing this out.
Does this mean that Perl versions 5.26 and 5.28 handle locales in
different way?

Yes, this has changed to make locale handling efficiently thread-safe.

The C setlocale() changes the locale across all threads, so locks are needed to ensure that one thread doesn't step on the locale usage of another thread.

uselocale() etc are thread local, so it's not a problem.

And what's strange is that your C code results to same memory leak on
both 11.2-RELEASE
and 12.0-RELEASE, but I'm not able to reproduce an issue with Perl
5.28 on 11.2-RELEASE.

hints/freebsd.sh blocks usage of those APIs in 11.2, see https​://bugs.freebsd.org/bugzilla/show_bug.cgi?id=211743 and https://rt-archive.perl.org/perl5/Ticket/Display.html?id=128867.

I've filled the bug in FreeBSD Bugzilla. Let's see the findings there
as well.
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=239520

Thanks.

@khwilliamson
Copy link
Contributor

There has been no real action taken by freebsd on https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=239520. This isn't a bug in Perl. Is there anything left for us to do? If not, can we close this ticket

@jkeenan
Copy link
Contributor

jkeenan commented Mar 20, 2020 via email

@jkeenan
Copy link
Contributor

jkeenan commented Mar 20, 2020

On 3/20/20 11:39 AM, Karl Williamson wrote: There has been no real action taken by freebsd on https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=239520 . This isn't a bug in Perl. Is there anything left for us to do? If not, can we close this ticket
Please leave open for a while. I just posted in the FreeBSD ticket and that stirred a response. jimk

FreeBSD is making a change ...
https://svnweb.freebsd.org/base/head/lib/libc/locale/xlocale.c?r1=359183&r2=359182&pathrev=359183&diff_format=u
... but I don't know when it will appear in a release.

@jkeenan
Copy link
Contributor

jkeenan commented Apr 3, 2020

On 3/20/20 11:39 AM, Karl Williamson wrote: There has been no real action taken by freebsd on https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=239520 . This isn't a bug in Perl. Is there anything left for us to do? If not, can we close this ticket
Please leave open for a while. I just posted in the FreeBSD ticket and that stirred a response. jimk

FreeBSD is making a change ...
https://svnweb.freebsd.org/base/head/lib/libc/locale/xlocale.c?r1=359183&r2=359182&pathrev=359183&diff_format=u
... but I don't know when it will appear in a release.

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=239520#c11

"This will be fixed in [FreeBSD-]11.4 and 12.2."

@khwilliamson
Copy link
Contributor

So what does Perl do in response. Re-reading the thread, it seems to me we should set the hints file to not use thread safe locale handling before the fixed versions. Or is thread safety so important that we live with the leak in them.

@khwilliamson
Copy link
Contributor

@tonycoz @jkeenan what to do about this

@tonycoz
Copy link
Contributor

tonycoz commented Oct 28, 2020

So what does Perl do in response. Re-reading the thread, it seems to me we should set the hints file to not use thread safe locale handling before the fixed versions. Or is thread safety so important that we live with the leak in them.

I think updating the hints is the correct thing to do.

If I understand correctly, without uselocale() etc we just fall back to setlocale() and locking which should be safe if only perl is touching/using the locale in the process.

@khwilliamson
Copy link
Contributor

khwilliamson commented Oct 29, 2020 via email

@jkeenan
Copy link
Contributor

jkeenan commented Mar 30, 2023

@tonycoz @khwilliamson, the FreeBSD Bugzilla ticket tracking this problem has been closed, with the problem reported to be "Fixed in all currently supported releases". Can our ticket now be closed?

@khwilliamson
Copy link
Contributor

as far as I'm concerned, yes

@jkeenan jkeenan closed this as completed Mar 30, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants