Beefy Boxes and Bandwidth Generously Provided by pair Networks Cowboy Neal with Hat
Keep It Simple, Stupid
 
PerlMonks  

Garbage collection problem??

by tcarmeli (Beadle)
on Dec 26, 2006 at 16:54 UTC ( #591724=perlquestion: print w/ replies, xml ) Need Help??
tcarmeli has asked for the wisdom of the Perl Monks concerning the following question:

Hi Monks,
I'm having a problem with the attached script. When calling the function two times in a row, the 2nd time is by far slower.
The memory usage stays roughly the same, and it does not seem to be an issue of paging either. I wonder if it has to do with some fragmentation?
Is my data structure "too complicated"??
I use it on an XP OS with 2G RAM. Perl 5.8.8 Build 819
#!/usr/bin/perl -w use strict; use warnings; CheckAllPairs(); CheckAllPairs(); sub CheckAllPairs{ my $abs_time_res=50; my $max_peak_time=2050; my $subj_num; my $region; my $region1; my $region2; my $time; my $peaks; my @act_list1; my @act_list2; my $i; my $j; my $key; my $delta; my %map; my $start_A; my $end_A; my $start_B; my $end_B; my @region_list = (1..38); my @main_subjects_list = (1..38); $start_A = (times)[0]; foreach $region (@region_list) { foreach $subj_num (@main_subjects_list){ for $time (0..$max_peak_time){ if(rand(1000)<3){ push(@{$peaks->{$region}{$subj +_num}}, $time); } } } } $end_A = (times)[0]; printf "Section A took %.4f CPU seconds\n", $end_A - $start_A; $start_B = (times)[0]; foreach $region1 (@region_list) { foreach $region2 (@region_list) { if($region2<$region1){ next; } $key=$region1 . ':' . $region2; foreach $subj_num (@main_subjects_list){ if(!exists($peaks->{$region1}{$subj_nu +m}) || !exists($peaks->{$region2}{$subj_num})){ next; } @act_list1=@{$peaks->{$region1}{$subj_ +num}}; @act_list2=@{$peaks->{$region2}{$subj_ +num}}; foreach $i (@act_list1){ foreach $j (@act_list2){ $time=int($i/$abs_time +_res); $delta=int(($j-$i)/$ab +s_time_res)+int($max_peak_time/$abs_time_res); $map{$key}{$subj_num}[ +$time][$delta]=1; } } } } } $end_B = (times)[0]; printf "Section B took %.4f CPU seconds\n", $end_B - $start_B; return; }

Comment on Garbage collection problem??
Download Code
Re: Garbage collection problem??
by chromatic (Archbishop) on Dec 26, 2006 at 17:43 UTC

    Every time I ran it on my machine, the second time through was faster. That's what I expected; Perl had to do less work allocating memory for the lexical variables thanks to the same optimization that makes my $lexical if 0; so dangerous.

      Hi Chromatic. If I understand you correctly, you are saying that an optimization like  my $i if 0 occurs in this code. I suppose you mean that some construct will infer a runtime penalty (as opposed to compile-time penalty). Just a bit puzzled, would you care to explain a bit more?

      Personally I don't like  my $i if 0; (I would even call it "dangerous" in the sense of not {truly} maintainable) as I prefer the idiom of true shared variables  { my $shared; sub f1 { ... # use $shared } sub f2 {...} }

      In any case I fail to see some optimization kicking in on cygwin. How much faster is the second run on your system? aren't my-allocations very fast with respect to a foreach loop anyway? again seems that all "my slots" will be reserved at compile-time, no?

      The only thing I see is that could be flagged as non-pbp is the construct  my $region; for $region {...} that can be transformed into for my ... for recent enough perl (I wonder what is the best way to handle all versions of perl though...).

      cheers --stephan

        I actually meant that Perl won't free all of the memory used by lexicals when it leaves the scope because of an optimization. The idea is that the next time control enters the scope, the memory requirements will be similar. Avoiding malloc() calls can improve performance.

Re: Garbage collection problem??
by BrowserUk (Pope) on Dec 26, 2006 at 22:15 UTC

    Can't say why (yet), but I can confirm your findings on 5.8.6 under XP.

    c:\test>junk6 Section A took 1.0150 CPU seconds Section B took 3.3750 CPU seconds Section A took 1.0150 CPU seconds Section B took 5.1410 CPU seconds c:\test>junk6 Section A took 1.0310 CPU seconds Section B took 3.4540 CPU seconds Section A took 1.0000 CPU seconds Section B took 5.0780 CPU seconds :\test>junk6 Section A took 1.0470 CPU seconds Section B took 3.5470 CPU seconds Section A took 0.9690 CPU seconds Section B took 4.8910 CPU seconds c:\test>junk6 Section A took 1.0310 CPU seconds Section B took 3.4690 CPU seconds Section A took 1.0160 CPU seconds Section B took 5.1560 CPU seconds

    Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
    "Science is about questioning the status quo. Questioning authority".
    In the absence of evidence, opinion is indistinguishable from prejudice.
      On a 360MHz/1024MB ultrasparc running homegrown linux with Perl 5.8.0 :

      Section A took 10.5400 CPU seconds
      Section B took 22.2800 CPU seconds
      Section A took 12.8400 CPU seconds
      Section B took 22.3900 CPU seconds


      ciao.
Re: Garbage collection problem??
by wjw (Hermit) on Dec 27, 2006 at 03:16 UTC
    Was curious about this. So ran it as follows...
    • winxp 2002 Svc Pack 2
    • on
    • Toshiba Satellite 1.8Ghz/504MB Ram
    • ActiveState Perl 5.8.8
    • Section A took 0.7340 CPU seconds
    • Section B took 2.5000 CPU seconds
    • section A took 0.7500 CPU seconds
    • Section B took 16.4530 CPU seconds
    • Section A took 0.7660 CPU seconds
    • Section B took 2.6400 CPU seconds
    • Section A took 0.7650 CPU seconds
    • Section B took 15.3440 CPU seconds
    • Section A took 0.7340 CPU seconds
    • Section B took 2.5630 CPU seconds
    • Section A took 0.7340 CPU seconds
    • Section B took 16.2030 CPU seconds
    • Section A took 0.7340 CPU seconds
    • Section B took 2.5630 CPU seconds
    • Section A took 0.7340 CPU seconds
    • Section B took 16.2030 CPU seconds
    ####################################################
    • On Suse 10.1
    • Same Toshiba as mentioned above
    • Perl 5.8.8
    • Section A took 1.1700 CPU seconds
    • Section B took 2.3800 CPU seconds
    • Section A took 0.9700 CPU seconds
    • Section B took 2.3700 CPU seconds
    • Section A took 1.2800 CPU seconds
    • Section B took 2.4200 CPU seconds
    • Section A took 1.0300 CPU seconds
    • Section B took 2.4100 CPU seconds
    • Section A took 1.2600 CPU seconds
    • Section B took 2.4400 CPU seconds
    • Section A took 0.9800 CPU seconds
    • Section B took 2.4500 CPU seconds
    • Section A took 1.2200 CPU seconds
    • Section B took 2.4300 CPU seconds
    • Section A took 1.0100 CPU seconds
    • Section B took 2.4500 CPU seconds

    Leaves me to wonder: Is this the OS? The way perl is compiled for the OS? Both OS's use ~ the same amount of memory (90Meg) during the run based on TaskManager readings on XP and top readings on linux, each set to .5 second update. The B second run on XP is about 6.6 times slower than on linux. The A first run is about 1.6 times faster on XP than on linux.

    This is very rough data, but interesting none-the-less.

    ...the majority is always wrong, and always the last to know about it...

Re: Garbage collection problem??
by alpha (Scribe) on Dec 27, 2006 at 14:14 UTC
    So much foreach loops make me sick =:[]
Re: Garbage collection problem??
by creamygoodness (Curate) on Dec 27, 2006 at 14:25 UTC

    I can't confirm this with the stock Perl 5.8.6 on OS X 10.4 -- the second run seems to be consistently as fast as the first.

    However, I have experienced similar phenomena on this system before which I figured were a result of memory pool fragmentation. I have an indexing benchmarker script which inverts around 20000 Reuters news stories. In the initial version, once the script had been run a time or two (warming up the OS hard disk read cache) the first run was consistently faster than all subsequent runs by a few percentage points. I wound up launching a child process for each run to defeat the effect.

    --
    Marvin Humphrey
    Rectangular Research ― http://www.rectangular.com
Re: Garbage collection problem??
by Herkum (Parson) on Dec 27, 2006 at 14:26 UTC
    I justed to had to run it after everyone else. This is Ubuntu 6.10 with Dell Optiplex GX620.
    sgkirkup@72sp691lin:~$ ./performance-test.pl Section A took 0.8600 CPU seconds Section B took 2.1800 CPU seconds Section A took 0.8800 CPU seconds Section B took 2.2200 CPU seconds sgkirkup@72sp691lin:~$ ./performance-test.pl Section A took 0.8200 CPU seconds Section B took 2.1300 CPU seconds Section A took 0.8500 CPU seconds Section B took 2.1800 CPU seconds sgkirkup@72sp691lin:~$ ./performance-test.pl Section A took 0.8300 CPU seconds Section B took 2.2100 CPU seconds Section A took 0.8600 CPU seconds Section B took 2.1900 CPU seconds sgkirkup@72sp691lin:~$ perl -v This is perl, v5.8.8 built for i486-linux-gnu-thread-multi Copyright 1987-2006, Larry Wall Perl may be copied only under the terms of either the Artistic License + or the GNU General Public License, which may be found in the Perl 5 source ki +t. Complete documentation for Perl, including FAQ lists, should be found +on this system using "man perl" or "perldoc perl". If you have access to + the Internet, point your browser at http://www.perl.org/, the Perl Home Pa +ge.
Re: Garbage collection problem??
by alpha (Scribe) on Dec 27, 2006 at 14:32 UTC
    W2k sp4, celeron ~750 MHZ 256 RAM:
    C:\pl>stuff.pl Section A took 3.5450 CPU seconds Section B took 12.5380 CPU seconds Section A took 3.5350 CPU seconds Section B took 44.2540 CPU seconds C:\pl>
      on HP-Unix
      bash-2.00$ monk.pl
      Section A took 5.4500 CPU seconds
      Section B took 9.7100 CPU seconds
      Section A took 5.4700 CPU seconds
      Section B took 9.9800 CPU seconds
      See you got over the initial sickness ;-)
Re: Garbage collection problem??
by roboticus (Canon) on Dec 27, 2006 at 15:21 UTC
    Results for Win2K SP4 using cygwin v1.5.18 and perl v5.8.7 on an AMD Sempron 2500+ with 512K RAM:

    root@swill ~/PerlMonks $ ./591724.pl Section A took 1.7040 CPU seconds Section B took 3.7960 CPU seconds Section A took 1.7030 CPU seconds Section B took 3.7500 CPU seconds root@swill ~/PerlMonks $ ./591724.pl Section A took 1.6880 CPU seconds Section B took 3.7970 CPU seconds Section A took 1.6870 CPU seconds Section B took 3.6090 CPU seconds

    --roboticus

    Update: If anyone's interested, here's

Re: Garbage collection problem??
by sgt (Chaplain) on Dec 27, 2006 at 16:20 UTC

    I see the same speed for both runs on cygwin 1.5.21-2 with perl 5.8.7

    % stephan@labaule (/home/stephan) % % cygcheck -s | grep ^cygwin' ' cygwin 1.5.22-1 % stephan@labaule (/home/stephan) % % perl -v | head -n 3; perl -W perf_test.px This is perl, v5.8.7 built for cygwin-thread-multi-64int (with 1 registered patch, see perl -V for more detail) Section A took 1.5920 CPU seconds Section B took 3.3950 CPU seconds Section A took 1.6030 CPU seconds Section B took 3.4550 CPU seconds % stephan@labaule (/home/stephan) % % perl -W perf_test.px Section A took 1.5920 CPU seconds Section B took 3.3650 CPU seconds Section A took 1.6030 CPU seconds Section B took 3.4350 CPU seconds % stephan@labaule (/home/stephan) % % perl -W perf_test.px Section A took 1.6020 CPU seconds Section B took 3.5250 CPU seconds Section A took 1.6120 CPU seconds Section B took 3.3850 CPU seconds
    hth --stephan
Re: Garbage collection problem??
by alpha (Scribe) on Dec 27, 2006 at 16:58 UTC
    Then it's probably the OS..
Re: Garbage collection problem??
by monarch (Priest) on Dec 27, 2006 at 17:00 UTC
    On a dual duo-core Intel Xeon with perl v5.8.8 on x86_64-linux-gnu-thread-multi on Ubuntu 6.10 I got:
    Section A took 0.3200 CPU seconds Section B took 1.1300 CPU seconds Section A took 0.3400 CPU seconds Section B took 1.1800 CPU seconds
Re: Garbage collection problem??
by EvanK (Chaplain) on Dec 27, 2006 at 17:10 UTC
    sweet criminy...dont you just love windows activeperl for windows?

    windows xp home sp2
    amd 64 x2 3800+
    2gb ram
    activestate 5.8.8 build 819

    C:\Documents and Settings\Evan>perl c:\benchtest.pl Section A took 1.0470 CPU seconds Section B took 2.8910 CPU seconds Section A took 1.0470 CPU seconds Section B took 10.9220 CPU seconds C:\Documents and Settings\Evan>perl c:\benchtest.pl Section A took 1.0310 CPU seconds Section B took 2.8440 CPU seconds Section A took 1.0310 CPU seconds Section B took 11.2190 CPU seconds C:\Documents and Settings\Evan>perl c:\benchtest.pl Section A took 1.0470 CPU seconds Section B took 2.7340 CPU seconds Section A took 1.0310 CPU seconds Section B took 10.6410 CPU seconds
    edit: forgot my perl version :o

    __________
    The trouble with having an open mind, of course, is that people will insist on coming along and trying to put things in it.
    - Terry Pratchett

      EvanK:

      It doesn't appear to be windows. My results show the expected behaviour under Windows. I'm suspecting it may be ActiveState related: Are you running that, or the cygwin perl?

      --roboticus

Re: Garbage collection problem??
by Anonymous Monk on Dec 27, 2006 at 18:07 UTC
    pretty clear from the results that this phenomenon only occurs in ActivePerl...

      No, I don't think the problem has anything to do with ActiveState nor their version of Perl. Though I don't see any reports using ActivePerl other than on Win32 (yes, they make such), I doubt that the problem would appear there.

      My guess based on the results is that the blame can likely be placed on the malloc() of Win32's CRTL and that cygwin-built Perls doesn't use that version of malloc().

      In any case, testing with my non-ActiveState Perl on Win32 gives:

      C:\> perl checkpairs.pl Section A took 0.7500 CPU seconds Section B took 2.5470 CPU seconds Section A took 0.7340 CPU seconds Section B took 13.8280 CPU seconds

      Which certainly disproves that it "only occurs in ActivePerl". (:

      And I've certainly seen Win32's malloc() cause performance problems. I haven't read the code for it recently but I'm quite familiar with some of the memory use patterns that it produces and those clearly show a very naive algorithm.

      Anyone got a Win32 (non-cygwin) Perl built with profiling?

      - tye        

        Which version of cygwin are you using? My results are using cygwin (v1.5.18) and Perl 5.8.7, and don't show the slowdown on the second run....

        --roboticus

        If you look at my tests, they are not using Windows at all nor is it using ActivePerl. Some people have said that it is not an issue on their system but have not posted what type of system they are running (except for OS X).

        Update: You are correct, I misread your post, sorry about that...

        Actually, it appears to be more to do with realloc and/or free rather than malloc per se, but also there seem to be some pretty strange things going on with respect to error handling.

        I get the impression, but haven't got proof yet, that it may be something to do with the way Perl is using the CRT, possibly to do with how it handles errors.

        Has anyone tried the OP code on a non-threaded 5.8.x Win32 build? There are lots ( literally millions) of repetitions of the call sequence:

        ... [T1868] GetLastError(2845dc, 18f5ca4, 77c35292, 2803000e, ...) = 3 [T1868] TlsGetValue(0, 2845dc, 18f5ca4, 77c35292, ...) = 281ea0 [T1868] SetLastError(3, 2845dc, 18f5ca4, 77c35292, ...) = 7ffde000 [T1868] GetLastError(2845dc, 18f5ca4, 77c35292, 2803000e, ...) = 3 [T1868] TlsGetValue(0, 2845dc, 18f5ca4, 77c35292, ...) = 281ea0 [T1868] SetLastError(3, 2845dc, 18f5ca4, 77c35292, ...) = 7ffde000 ...

        Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
        "Science is about questioning the status quo. Questioning authority".
        In the absence of evidence, opinion is indistinguishable from prejudice.
Re: Garbage collection problem??
by sgt (Chaplain) on Dec 27, 2006 at 19:58 UTC

    I have put systematically my in the foreach (or in the smallest possible scope), and guess what 'for my' is actually consistently slower in case B. Somehow it surprised me :(

    % stephan@labaule (/home/stephan) % % for _i in {1..5} > do > echo ===$_i==== > perl -W perf_test_allmy.px > echo --- > perl -W perf_test.px > done ===1==== Section A took 1.7020 CPU seconds Section B took 3.9560 CPU seconds Section A took 1.7330 CPU seconds Section B took 3.9660 CPU seconds --- Section A took 1.7020 CPU seconds Section B took 3.6850 CPU seconds Section A took 1.7420 CPU seconds Section B took 3.7760 CPU seconds ===2==== Section A took 1.7220 CPU seconds Section B took 4.0160 CPU seconds Section A took 1.7030 CPU seconds Section B took 4.0860 CPU seconds --- Section A took 1.7220 CPU seconds Section B took 3.7850 CPU seconds Section A took 1.7230 CPU seconds Section B took 3.6750 CPU seconds ===3==== Section A took 1.7120 CPU seconds Section B took 4.0960 CPU seconds Section A took 1.7220 CPU seconds Section B took 4.0460 CPU seconds --- Section A took 1.7320 CPU seconds Section B took 3.5250 CPU seconds Section A took 1.7220 CPU seconds Section B took 3.6450 CPU seconds ===4==== Section A took 1.7020 CPU seconds Section B took 4.1260 CPU seconds Section A took 1.7120 CPU seconds Section B took 3.9360 CPU seconds --- Section A took 1.7020 CPU seconds Section B took 3.8560 CPU seconds Section A took 1.7430 CPU seconds Section B took 3.6350 CPU seconds ===5==== Section A took 1.7020 CPU seconds Section B took 4.1560 CPU seconds Section A took 1.7120 CPU seconds Section B took 3.9760 CPU seconds --- Section A took 1.7220 CPU seconds Section B took 3.7350 CPU seconds Section A took 1.7330 CPU seconds Section B took 3.5850 CPU seconds
    hth --stephan
Re: Garbage collection problem??
by tcarmeli (Beadle) on Dec 28, 2006 at 09:31 UTC
    Something that does not solve the issue, but makes it less painfull, it to replace the "push" with "unshift".
    It causes the high values of $time to be used first, so there's one first large memory allocation rather than many extensions on the existing amount.
Re: Garbage collection problem??
by alpha (Scribe) on Dec 28, 2006 at 12:10 UTC
    I've added third CheckAllPairs(); into script and results are strange imo ;/
    C:\pl>stuff.pl Section A took 2.9140 CPU seconds Section B took 13.4890 CPU seconds Section A took 3.6350 CPU seconds Section B took 44.2330 CPU seconds Section A took 3.6450 CPU seconds Section B took 46.9980 CPU seconds
    oh, and I run perl v5.8.8 built for MSWin32-x86-multi-thread with 25 registered patches.

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://591724]
Approved by planetscape
Front-paged by holli
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others taking refuge in the Monastery: (8)
As of 2014-04-19 17:59 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    April first is:







    Results (483 votes), past polls