From: Ron Mayer <rm_rails@...>
Date: 2009-01-20T21:48:36+09:00
Subject: [ruby-core:21460] Array concat loops sometimes taking large amounts of "system" time.

On both ruby1.8 and ruby1.9, about half the time when I run loops like this:
   a = [1,2,3,4,5];
   b=[];
   puts Benchmark.measure{ (1..10000000).each{b.concat(a)}}
they go reasonably quickly.    The other half of the
time they take about an order of magnitude longer; which
virtually all the time as "system" time.  For example
here's an IRB script showing the problem:

irb(main):076:0> a = [1,2,3,4,5]; b=[]; puts Benchmark.measure{ (1..10000000).each{b.concat(a)}}
  7.140000   6.840000  13.980000 ( 14.679623)
=> nil
irb(main):077:0> a = [1,2,3,4,5]; b=[]; puts Benchmark.measure{ (1..10000000).each{b.concat(a)}}
  7.450000 129.210000 136.660000 (136.597793)
=> nil
irb(main):078:0> a = [1,2,3,4,5]; b=[]; puts Benchmark.measure{ (1..10000000).each{b.concat(a)}}
  7.500000   1.850000   9.350000 (  9.375319)
=> nil
irb(main):079:0> a = [1,2,3,4,5]; b=[]; puts Benchmark.measure{ (1..10000000).each{b.concat(a)}}
  7.340000  45.640000  52.980000 ( 53.512928)
=> nil

It seems quite strange to me that 2 of the 4 runs were
much slower than the other two.


If I don't use IRB but rather use a standalone ruby script,
it's harder to reproduce; but on a large script I have,
I believe I see this effect too.


During the slow runs, strace with Ruby 1.9 tells me it's doing a whole
lot (about 50,000) of mremap system calls where the "old" and "new"
sizes are barely changing:
 mremap(0x9815b000, 90927104, 90931200, MREMAP_MAYMOVE) = 0x85763000
 mremap(0x85763000, 90931200, 90935296, MREMAP_MAYMOVE) = 0x98159000
 mremap(0x98159000, 90935296, 90939392, MREMAP_MAYMOVE) = 0x85761000
 mremap(0x85761000, 90939392, 90943488, MREMAP_MAYMOVE) = 0x98157000
With ruby 1.8 it looks similar, but with a whole lot of
"sigprocmask(SIG_BLOCK, NULL, [])        = 0" syscalls mixed in
among the mremaps.


Is a workaround, I can rewrite the script using .push(*a) instead of .concat(a)
  a = [1,2,3,4,5]; b=[]; puts Benchmark.measure{ (1..10000000).each{b.push(*a)}}
    8.770000   0.370000   9.140000 ( 10.080302)
which does far fewer (about 20 instead of 50,000) mremaps(), but with bigger
differences between the old and new sizes:

 mremap(0xa9fe7000, 16412672, 24616960, MREMAP_MAYMOVE) = 0xa9fe7000
 mremap(0xa9fe7000, 24616960, 36921344, MREMAP_MAYMOVE) = 0x9b4dc000
 mremap(0x9b4dc000, 36921344, 55382016, MREMAP_MAYMOVE) = 0x9800b000
 mremap(0x9800b000, 55382016, 83070976, MREMAP_MAYMOVE) = 0x9800b000


All these were using the debian and ubuntu packages of ruby.