Perl bug -- split function

[p5pRT]

Migrated from rt.perl.org#9319 (status was 'stalled')

Searchable as RT9319$

[p5pRT]

From birtl00@dmi.usherb.ca

Hi,
  I got a problem with the 'split' function.

I've attached a program that open each file of a directory one at a
time, read the entire content of the file in a scalar, then attempt to
split the data into list elements of one character each, using the empty
split pattern (//).

The result varies based on the input. For some files (when there are not
many in the directory), it works fine.

Sometimes, after having read 5-6 files, the split function begins to
take a very long time before returning. For the next file, it never
returns, and the CPU is busy 100%. I've run strace on the program and I
saw that no system calls occur when it is stuck in the split function.
The memory usage do not grow, either.

Sometimes, the split function do not slow down too much but the memory
usage grows unbounded, even though the files are not so big. It
consumes all the 512 MB of RAM of my system. I don't see any
circularity in the program that could cause the input not to be garbage
collected.

I've tried the program on two computers running Linux (i386) on
Slackware 8. I tried perl 5.6.0 and 5.6.1, both produces similar
output. The 5.6.1 version was recompiled from the sources, using the
default values as the build options.

Am I doing something really stupid in the program or is there a bug in Perl?
Hopefully you can reproduce the problem on your system. Running the
program in /usr/lib/ triggers the problem for me.

Thanks a lot,

  Laurent Birtz

[p5pRT]

From birtl00@dmi.usherb.ca

#!/usr/bin/perl -w

use strict;
$| = 1;

main();


sub main
{
my $file_data;
my @array;
my $saved_sep;
my @file_list;

### Get all file in current working directory.
@file_list = <*>;
print("The following files will be tried: @file_list\n\n");

foreach my $file (@file_list)
{
if(! -f $file)
{
print("Skipping $file: not regular\n");
next;
}

print("Opening file '$file'...\n");

open(INPUT_FILE, "<$file")
|| die("Cannot open $file: $!");

### Slurp file in.
$saved_sep = $/;
$/ = undef;
$file_data = <INPUT_FILE>;
$/ = $saved_sep;

### Attempt to split file data.
print("Split..\n");

### On my system it hangs here.
@array = split(//, $file_data);

print("End split..\n");

close(INPUT_FILE)
|| die("Cannot close $file: $!");
}
}

[p5pRT]

From @iabyn

On Mon, May 13, 2002 at 04​:47​:42PM -0400, Delta wrote​:

Hi,
I got a problem with the 'split' function.

I've attached a program that open each file of a directory one at a
time, read the entire content of the file in a scalar, then attempt to
split the data into list elements of one character each, using the empty
split pattern (//).

The result varies based on the input. For some files (when there are not
many in the directory), it works fine.

Sometimes, after having read 5-6 files, the split function begins to
take a very long time before returning. For the next file, it never
returns, and the CPU is busy 100%. I've run strace on the program and I
saw that no system calls occur when it is stuck in the split function.
The memory usage do not grow, either.

Sometimes, the split function do not slow down too much but the memory
usage grows unbounded, even though the files are not so big. It
consumes all the 512 MB of RAM of my system. I don't see any
circularity in the program that could cause the input not to be garbage
collected.

The problem here is that when you split large strings into 1-character
strings, you are creating extremely large data structures. This is one
reason why it's noticable in /usr/lib - there are many files in there over
1Mb in size. When you split a 1Mb file into charcters, you are creating a
an array with 1,000,000 elements, each of which holds a Perl string that
happens to be 1 character long. Perl strings are quite big objects (if you
think about it, they have the capability to store strings, numbers,
references etc). So splitting a 1Mb file can end up using a couple of
hundred Mb - especially when you take into account the fact that the array
has to be continually extended.

So, when you split your first large file, it takes a while, and memory
usage grows wildly. Then, when you start to split the next file, Perl has
to release those 1 million strings fromt he previous split, which takes
ages, depending on your system's malloc() library and the vagarities of
Perl.

The moral is​: don't split 1Mbyte strings into individual characters :-)

Note to perl5porters​:

This behaviour appears in bleedperl too; after splitting s 2.3Mb file, memory
usage rose to about 250Mb, and freeing the array took several minutes.
(admittedly that was with -DEBUGGING).
gdb showed that the time was being taken up calling sv_free N zillion
times. So,

* for a future Perl, do we have the technology to presize the array in
  @​a = split //, $s
?
* Freeing the 1M scalars does take an *awfully* long time - is this Perl's
fault or malloc()'s - or is that Life?

Dave.

I've tried the program on two computers running Linux (i386) on
Slackware 8. I tried perl 5.6.0 and 5.6.1, both produces similar
output. The 5.6.1 version was recompiled from the sources, using the
default values as the build options.

Am I doing something really stupid in the program or is there a bug in Perl?
Hopefully you can reproduce the problem on your system. Running the
program in /usr/lib/ triggers the problem for me.

Thanks a lot,

Laurent Birtz

#!/usr/bin/perl -w

use strict;
$| = 1;

main();

sub main
{
my $file_data;
my @​array;
my $saved_sep;
my @​file_list;

\#\#\# Get all file in current working directory\.
@&#8203;file\_list = \<\*>;
print\("The following files will be tried&#8203;: @&#8203;file\_list\\n\\n"\);

foreach my $file \(@&#8203;file\_list\)
    \{
    if\(\! \-f $file\)
        \{
        print\("Skipping $file&#8203;: not regular\\n"\);
        next;
        \}
    
    print\("Opening file '$file'\.\.\.\\n"\);
    
    open\(INPUT\_FILE\, "\<$file"\)
        || die\("Cannot open $file&#8203;: $\!"\);
    
    \#\#\# Slurp file in\.
    $saved\_sep = $/;
    $/ = undef;
    $file\_data = \<INPUT\_FILE>;
    $/ = $saved\_sep;

    \#\#\# Attempt to split file data\.
    print\("Split\.\.\\n"\);
    
    \#\#\# On my system it hangs here\.
    @&#8203;array = split\(//\, $file\_data\);
    
    print\("End split\.\.\\n"\);

    close\(INPUT\_FILE\)
        || die\("Cannot close $file&#8203;: $\!"\);
    \}
\}

--
"There's something wrong with our bloody ships today, Chatfield."
Admiral Beatty at the Battle of Jutland, 31st May 1916.

[p5pRT]

From @paulg1973

Dave Mitchell [mailto​:davem@​fdgroup.com] wonders, based on an inquiry from
Delta,

* Freeing the 1M scalars does take an *awfully* long time -
is this Perl's fault or malloc()'s - or is that Life?

Dave.

I've worked with a number of different operating-system-supplied storage
allocators over the years. They all make the basic assumption that the
caller is allocating a "reasonable" amount of storage and holding onto it
for a "reasonable" length of time. When you have algorithms that
purposefully violate either of these "reasonable" preconditions, you can
beat the performance of said allocator by writing your own. But then, you
are off in the exciting world of dealing with all of the unreasonable
behavior requested by the universe of callers.

The allocator we use on VOS allocates storage that is at least 64-byte
aligned. We allocate in units of 16 bytes. We have a 16-byte overhead for
each block. We have to mask and unmask interrupts on every allocation to
protect against program interrupts. We have to be careful in case the heap
is damaged. Allocation and free performance is a goal, but is outweighed by
correctness, reliability, nonfragmentation, and alignment goals. (By
aligning the data properly we optimize the performance of our clients).

The short answer is that 1M of anything is expensive. The long answer is
that allocating storage is a nontrivial operation. If you want to store a
million bytes efficiently, allocate a million-byte string and use substr.

Any good algorithms course and / or textbook goes into great depth on these
subjects and should be read and studied by any software engineer. This is
just the tip of the icebert. Go get a good book and read it, or find a
local college and take their algorithms course.

HTH
PG

[p5pRT]

From @paulg1973

s/icebert/iceberg/

With apologies to Bert.

PG

-----Original Message-----
From​: Green, Paul [mailto​:Paul.Green@​stratus.com]
Sent​: Monday, May 13, 2002 7​:13 PM
To​: 'Dave Mitchell'; Delta
Cc​: perl5-porters@​perl.org
Subject​: RE​: [ID 20020513.013] Perl bug -- split function

Dave Mitchell [mailto​:davem@​fdgroup.com] wonders, based on an
inquiry from
Delta,

* Freeing the 1M scalars does take an *awfully* long time -
is this Perl's fault or malloc()'s - or is that Life?

Dave.

I've worked with a number of different
operating-system-supplied storage
allocators over the years. They all make the basic assumption that the
caller is allocating a "reasonable" amount of storage and
holding onto it
for a "reasonable" length of time. When you have algorithms that
purposefully violate either of these "reasonable"
preconditions, you can
beat the performance of said allocator by writing your own.
But then, you
are off in the exciting world of dealing with all of the unreasonable
behavior requested by the universe of callers.

The allocator we use on VOS allocates storage that is at least 64-byte
aligned. We allocate in units of 16 bytes. We have a 16-byte
overhead for
each block. We have to mask and unmask interrupts on every
allocation to
protect against program interrupts. We have to be careful in
case the heap
is damaged. Allocation and free performance is a goal, but is
outweighed by
correctness, reliability, nonfragmentation, and alignment goals. (By
aligning the data properly we optimize the performance of our
clients).

The short answer is that 1M of anything is expensive. The
long answer is
that allocating storage is a nontrivial operation. If you
want to store a
million bytes efficiently, allocate a million-byte string and
use substr.

Any good algorithms course and / or textbook goes into great
depth on these
subjects and should be read and studied by any software
engineer. This is
just the tip of the icebert. Go get a good book and read it,
or find a
local college and take their algorithms course.

HTH
PG

[p5pRT]

From @iabyn

On Mon, May 13, 2002 at 07​:12​:43PM -0400, Green, Paul wrote​:

Dave Mitchell [mailto​:davem@​fdgroup.com] wonders, based on an inquiry from
Delta,

* Freeing the 1M scalars does take an *awfully* long time -
is this Perl's fault or malloc()'s - or is that Life?
[snip]
The short answer is that 1M of anything is expensive.

I guess what I meant to say was​:

  I would expect freeing 1M scalars to take a long time, but it took
  even longer than I expected (about 100,000 CPU cycles per sv_free()
  for a simple PV), so note to self​: when you have a free minute, check
  that Perl isn't doing anything silly here. It probably isn't, but it
  may be worth checking.

Dave.

--
In England there is a special word which means the last sunshine
of the summer. That word is "spring".

[p5pRT]

From @jkeenan

On Mon May 13 20​:31​:02 2002, RT_System wrote​:

On Mon, May 13, 2002 at 07​:12​:43PM -0400, Green, Paul wrote​:

Dave Mitchell [mailto​:davem@​fdgroup.com] wonders, based on an
inquiry from
Delta,

* Freeing the 1M scalars does take an *awfully* long time -
is this Perl's fault or malloc()'s - or is that Life?
[snip]
The short answer is that 1M of anything is expensive.

I guess what I meant to say was​:

I would expect freeing 1M scalars to take a long time\, but it took
even longer than I expected \(about 100\,000 CPU cycles per sv\_free\(\)
for a simple PV\)\, so note to self​: when you have a free minute\, check
that Perl isn't doing anything silly here\. It probably isn't\, but it
may be worth checking\.

Reviewing this ticket today, my impression is that it falls into the
category of "Original poster was doing something inadvisable."

So, is Perl "doing anything silly here"? If not, do we need to keep
this ticket open?

Thank you very much.
Jim Keenan

[p5pRT]

From @ikegami

On Mon May 13 20​:31​:02 2002, RT_System wrote​:

On Mon, May 13, 2002 at 07​:12​:43PM -0400, Green, Paul wrote​:

Dave Mitchell [mailto​:davem@​fdgroup.com] wonders, based on an
inquiry from
Delta,

* Freeing the 1M scalars does take an *awfully* long time -
is this Perl's fault or malloc()'s - or is that Life?
[snip]
The short answer is that 1M of anything is expensive.

I guess what I meant to say was​:

I would expect freeing 1M scalars to take a long time\, but it took
even longer than I expected \(about 100\,000 CPU cycles per sv\_free\(\)
for a simple PV\)\, so note to self​: when you have a free minute\, check
that Perl isn't doing anything silly here\. It probably isn't\, but it
may be worth checking\.

Dave.

It takes 0.1 seconds for me. 32-bit Windows threaded build from
ActivePerl. That doesn't seem unreasonable. What I find interesting is
that C<< split // >> is O(N^2), though.

1,000,000
split and alloc​: 1.4
SV dealloc​: 0.1

5,000,000
split and alloc​: 29.7
SV dealloc​: 0.7

10,000,000
split and alloc​: 118.7
SV dealloc​: 1.3

use strict;
use warnings;

use Time​::HiRes qw( time );

my $x = "x" x 10_000_000;
my $time1 = time;
my @​a = split //, $x;
my $time2 = time;
@​a = ();
my $time3 = time;

printf("split and alloc​: %6.1f\n", $time2-$time1);
printf("SV dealloc​: %6.1f\n", $time3-$time2);

[p5pRT]

From @bulk88

On Sat Apr 21 14​:58​:41 2012, jkeenan wrote​:

Reviewing this ticket today, my impression is that it falls into the
category of "Original poster was doing something inadvisable."

So, is Perl "doing anything silly here"? If not, do we need to keep
this ticket open?
The only way I can think of fixing this would be some kind of scheme
where PVs upto sizeof(void *) or sizeof(IV) get stored in the sv body or
directly in sv head union. Doing a grow above sizeof(void *) or
sizeof(IV) bytes will switch it to a real malloc block. The other fix is
use a bucket allocator similar to *I think* SV heads and/or SV bodys for
PVs under X bytes. The other bug is that the split is quadratic
according to the above. Thankfully the dealloc is linear according to
the above.

I looked at this in C, I think (by eye, not profiler) most of the time
is being spent in

  while (--limit) {
  if (gimme_scalar) {
  iters++;
  } else {
  dstr = newSVpvn(s, 1);

  if (make_mortal)
  sv_2mortal(dstr);

  PUSHs(dstr);
  }

  s++;

  if (s >= strend)
  break;
  }
in pp_split. It would mean the performance of this is basically Perl's
allocators (sv body/head arenas) AND the c lib allocator. It seems
linear superficially, but I'm not sure about Perl's sv allocators. Also
at 100s of MBs of ram which this script takes even though I have 3 GB of
ram on 32 bits, I see alot of "system" cpu time on WinXP something like
30% of my dual core machine (perl is 50%, single thread, max possible).
Im not sure what "system" time is in Windows at the moment and I dont
have time to google it right now.

[p5pRT]

From @bulk88

I thought a bit more. I dont have a Perl build with a C profiler
available, but I thought of NYTProf. But NYTProf doesn't profile all
opcodes, only select opcodes. The quadratic time, it might not be
pp_split to blame. It can be pp_padav or pp_aasign. NYTProf doesn't
provide opcode timings for all opcodes AFAIK. Someone correct me if I am
wrong.

Maybe pp_split should directly write into AVs targ style. But targ is a
Scalar not an Array. I'll throw it out, maybe that can change.

Made with Perl 5.12 and B Concise.

# 7​: my $time1 = time;
8 <;> nextstate(main 408 n13.pl​:7) v​:*,&,{,$
9 <0> pushmark s
a <#> gv[*time] s
b <1> entersub[t5] sKS/TARG,3
c <0> padsv[$time1​:408,412] sRM*/LVINTRO
d <2> sassign vKS/2
# 8​: my @​a = split //, $x;
e <;> nextstate(main 409 n13.pl​:8) v​:*,&,{,$
f <0> pushmark s
g </> pushre(/""/) s/64
h <0> padsv[$x​:407,412] s
i <$> const[IV 0] s
j <@​> split[t7] lK
k <0> pushmark s
l <0> padav[@​a​:409,412] lRM*/LVINTRO
m <2> aassign[t8] vKS
# 9​: my $time2 = time;
n <;> nextstate(main 410 n13.pl​:9) v​:*,&,{,$
o <0> pushmark s
p <#> gv[*time] s
q <1> entersub[t11] sKS/TARG,3
r <0> padsv[$time2​:410,412] sRM*/LVINTRO
s <2> sassign vKS/2
# 10​: @​a = ();
t <;> nextstate(main 411 n13.pl​:10) v​:*,&,{,$
u <0> pushmark s
v <0> pushmark s
w <0> padav[@​a​:409,412] lRM*
x <2> aassign[t12] vKS
# 11​: my $time3 = time;
y <;> nextstate(main 411 n13.pl​:11) v​:*,&,{,$
z <0> pushmark s
10 <#> gv[*time] s
11 <1> entersub[t15] sKS/TARG,3
12 <0> padsv[$time3​:411,412] sRM*/LVINTRO
13 <2> sassign vKS/2
# 13​: printf("split and alloc​: %6.1f\n", $time2-$time1);
14 <;> nextstate(main 412 n13.pl​:13) v​:*,&,{,$
15 <0> pushmark s
16 <$> const[PV "split and alloc​: %6.1f\n"] s
17 <0> padsv[$time2​:410,412] s
18 <0> padsv[$time1​:408,412] s
19 <2> subtract[t17] sK/2
1a <@​> prtf vK

[p5pRT]

From @bulk88

Hacked NYTProf to profile opcodes aassign padav pushmark split.

Long story short. pp_split or a call fron pp_split is the quadratic problem.

6 1 0s my $x = "x" x 1000000;
7 1 0s 2 0s my $time1 = time;
# spent 0s making 1 call to CORE​::pushmark
# spent 0s making 1 call to Time​::HiRes​::time
8 1 5.08s 5 4.53s my @​a = split //, $x;
# spent 3.83s making 1 call to CORE​::split
# spent 703ms making 1 call to CORE​::aassign
# spent 0s making 1 call to CORE​::padav
# spent 0s making 2 calls to CORE​::pushmark, avg 0s/call
9 1 0s 2 0s my $time2 = time;
# spent 0s making 1 call to CORE​::pushmark
# spent 0s making 1 call to Time​::HiRes​::time
10 1 531ms 4 531ms @​a = ();
# spent 531ms making 1 call to CORE​::aassign
# spent 0s making 1 call to CORE​::padav
# spent 0s making 2 calls to CORE​::pushmark, avg 0s/call

6 1 0s my $x = "x" x 2000000;
7 1 0s 2 0s my $time1 = time;
# spent 0s making 1 call to CORE​::pushmark
# spent 0s making 1 call to Time​::HiRes​::time
8 1 15.7s 5 14.6s my @​a = split //, $x;
# spent 13.3s making 1 call to CORE​::split
# spent 1.38s making 1 call to CORE​::aassign
# spent 0s making 1 call to CORE​::padav
# spent 0s making 2 calls to CORE​::pushmark, avg 0s/call
9 1 0s 2 0s my $time2 = time;
# spent 0s making 1 call to CORE​::pushmark
# spent 0s making 1 call to Time​::HiRes​::time
10 1 1.06s 4 1.06s @​a = ();
# spent 1.06s making 1 call to CORE​::aassign
# spent 0s making 1 call to CORE​::padav
# spent 0s making 2 calls to CORE​::pushmark, avg 0s/call

6 1 15.6ms my $x = "x" x 4000000;
7 1 0s 2 0s my $time1 = time;
# spent 0s making 1 call to CORE​::pushmark
# spent 0s making 1 call to Time​::HiRes​::time
8 1 56.5s 5 54.4s my @​a = split //, $x;
# spent 51.6s making 1 call to CORE​::split
# spent 2.78s making 1 call to CORE​::aassign
# spent 0s making 1 call to CORE​::padav
# spent 0s making 2 calls to CORE​::pushmark, avg 0s/call
9 1 0s 2 0s my $time2 = time;
# spent 0s making 1 call to CORE​::pushmark
# spent 0s making 1 call to Time​::HiRes​::time
10 1 2.16s 4 2.16s @​a = ();
# spent 2.16s making 1 call to CORE​::aassign
# spent 0s making 1 call to CORE​::padav
# spent 0s making 2 calls to CORE​::pushmark, avg 0s/call

[p5pRT]

From @bulk88

I made this XS func.

void
SVSpeed()
PPCODE​:
  LARGE_INTEGER my_beg;
  LARGE_INTEGER my_end;
  LARGE_INTEGER my_freq;
  SV * sv;
  int i;
  QueryPerformanceFrequency(&my_freq);
  for(i=0; i < 4000001; i++){
  if(i % 50000 == 0)
  QueryPerformanceCounter(&my_beg);
  sv = newSVpvn("x", 1);
  sv_2mortal(sv);
  if(i % 50000 == 0){
  QueryPerformanceCounter(&my_end);
  printf("time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  }
  }

called it as

use Blah;
Blah​::SVSpeed();

got

C​:\Perl>perl svspeed.pl
time=0.000003
time=0.000002
time=0.000003
time=0.000003
time=0.000005
time=0.000002
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000002
time=0.000003
time=0.000003
time=0.000002
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.009444
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000009
time=0.000003
time=0.000003
time=0.000003
time=0.000002
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000003
time=0.000002
time=0.000003
time=0.000003

C​:\Perl>

So its not those 2 calls, on a PER call basis. I noticed there was 1
spike. Plus I'm not measuring the time for the first quarter of SV
creations vs the last quarter. I'll try cut up the sv generations and
see if later ones take longer as a whole than earlier ones.

[p5pRT]

From @bulk88

rewrote as

void
SVSpeed()
PPCODE​:
  LARGE_INTEGER my_beg;
  LARGE_INTEGER my_end;
  LARGE_INTEGER my_freq;
  SV * sv;
  int i;
  QueryPerformanceFrequency(&my_freq);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv = newSVpvn("x", 1);
  sv_2mortal(sv);
  }
  QueryPerformanceCounter(&my_end);
  printf("time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv = newSVpvn("x", 1);
  sv_2mortal(sv);
  }
  QueryPerformanceCounter(&my_end);
  printf("time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv = newSVpvn("x", 1);
  sv_2mortal(sv);
  }
  QueryPerformanceCounter(&my_end);
  printf("time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv = newSVpvn("x", 1);
  sv_2mortal(sv);
  }
  QueryPerformanceCounter(&my_end);
  printf("time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);

result

C​:\Perl>perl svspeed.pl
time=3.949501
time=10.233058
time=15.953743
time=22.295258

C​:\Perl>

We have the culprit. I am done.

[p5pRT]

From @bulk88

Ok, actually problem is the mortal system.

C​:\Perl>perl svspeed.pl
newsv time=0.587146
mortal time=2.857621
newsv time=0.579447
mortal time=9.141501
newsv time=0.582962
mortal time=15.362363
newsv time=0.585780
mortal time=22.163787

C​:\Perl>

void
SVSpeed()
PPCODE​:
  LARGE_INTEGER my_beg;
  LARGE_INTEGER my_end;
  LARGE_INTEGER my_freq;
  SV * sv;
  int i;
  SV ** arr = malloc(sizeof(SV *) * 1000000);
  QueryPerformanceFrequency(&my_freq);
 
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  arr[i] = newSVpvn("x", 1);
  }
  QueryPerformanceCounter(&my_end);
  printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv_2mortal(arr[i]);
  }
  QueryPerformanceCounter(&my_end);
  printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  arr[i] = newSVpvn("x", 1);
  }
  QueryPerformanceCounter(&my_end);
  printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv_2mortal(arr[i]);
  }
  QueryPerformanceCounter(&my_end);
  printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  arr[i] = newSVpvn("x", 1);
  }
  QueryPerformanceCounter(&my_end);
  printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv_2mortal(arr[i]);
  }
  QueryPerformanceCounter(&my_end);
  printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  arr[i] = newSVpvn("x", 1);
  }
  QueryPerformanceCounter(&my_end);
  printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
  QueryPerformanceCounter(&my_beg);
  for(i=0; i < 1000000; i++){
  sv_2mortal(arr[i]);
  }
  QueryPerformanceCounter(&my_end);
  printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);

[p5pRT]

From @iabyn

On Sun, Apr 22, 2012 at 12​:53​:06AM -0700, bulk 88 via RT wrote​:

Ok, actually problem is the mortal system.

C​:\Perl>perl svspeed.pl
newsv time=0.587146
mortal time=2.857621
newsv time=0.579447
mortal time=9.141501
newsv time=0.582962
mortal time=15.362363
newsv time=0.585780
mortal time=22.163787

C​:\Perl>

void
SVSpeed()
PPCODE​:
LARGE_INTEGER my_beg;
LARGE_INTEGER my_end;
LARGE_INTEGER my_freq;
SV * sv;
int i;
SV ** arr = malloc(sizeof(SV *) * 1000000);
QueryPerformanceFrequency(&my_freq);

QueryPerformanceCounter\(&my\_beg\);
for\(i=0; i \< 1000000; i\+\+\)\{
    arr\[i\] = newSVpvn\("x"\, 1\);
\}
QueryPerformanceCounter\(&my\_end\);
printf\("newsv time=%f\\n"\,

((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
sv_2mortal(arr[i]);
}
QueryPerformanceCounter(&my_end);
printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
arr[i] = newSVpvn("x", 1);
}
QueryPerformanceCounter(&my_end);
printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
sv_2mortal(arr[i]);
}
QueryPerformanceCounter(&my_end);
printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
arr[i] = newSVpvn("x", 1);
}
QueryPerformanceCounter(&my_end);
printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
sv_2mortal(arr[i]);
}
QueryPerformanceCounter(&my_end);
printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
arr[i] = newSVpvn("x", 1);
}
QueryPerformanceCounter(&my_end);
printf("newsv time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);
QueryPerformanceCounter(&my_beg);
for(i=0; i < 1000000; i++){
sv_2mortal(arr[i]);
}
QueryPerformanceCounter(&my_end);
printf("mortal time=%f\n",
((double)(my_end.QuadPart-my_beg.QuadPart))/(double)my_freq.QuadPart);

I don't see similar slowdowns on linux with perl 5.15.9; I presume it must
be something to do with the windows malloc not liking repeated realloc()s
of the tmps stack​:

#include "EXTERN.h"
#include "perl.h"
#include "XSUB.h"

#include "ppport.h"

#include <sys/time.h>

MODULE = Mytest PACKAGE = Mytest

void
hello()
PPCODE​:
  struct timeval t1, t2;
  SV * sv;
  int i;
  int j;
  SV ** arr = malloc(sizeof(SV *) * 1000000);

  for (j=1; j<=5; j++) {
  gettimeofday(&t1, NULL);
  for(i=0; i < 1000000; i++){
  arr[i] = newSVpvn("x", 1);
  }
  gettimeofday(&t2, NULL);
  t2.tv_sec -= t1.tv_sec;
  t2.tv_usec -= t1.tv_usec;
  if (t2.tv_usec < 0) {
  t2.tv_sec--;
  t2.tv_usec += 1000000;
  }
  printf("newsv %d time=%d.%06ds\n", j, t2.tv_sec, t2.tv_usec);

  gettimeofday(&t1, NULL);
  for(i=0; i < 1000000; i++){
  sv_2mortal(arr[i]);
  }
  gettimeofday(&t2, NULL);
  t2.tv_sec -= t1.tv_sec;
  t2.tv_usec -= t1.tv_usec;
  if (t2.tv_usec < 0) {
  t2.tv_sec--;
  t2.tv_usec += 1000000;
  }
  printf("mortal %d time=%d.%06ds\n", j, t2.tv_sec, t2.tv_usec);

  printf("\n");
  }

[davem@​pigeon Mytest]$ perl5159o -Mblib /tmp/p
newsv 1 time=0.194811s
mortal 1 time=0.033377s

newsv 2 time=0.185385s
mortal 2 time=0.033189s

newsv 3 time=0.184901s
mortal 3 time=0.031508s

newsv 4 time=0.185011s
mortal 4 time=0.033563s

newsv 5 time=0.184997s
mortal 5 time=0.032119s

Nor can I see any quadratic slowdown with doing

  @​a = split //, $ling_string,

so again, perhaps its very sensitive to the malloc library?

--
The Enterprise successfully ferries an alien VIP from one place to another
without serious incident.
  -- Things That Never Happen in "Star Trek" #7