Serious slowdown in 1.9 mode vs 1.8 mode

Ruby JRuby
1

Hi,

this is seen on Windows 7-x86-java, using Java HotSpot™ Client VM
1.6.0_31 and jruby 1.6.7…

I’ve a bunch of files, pretty big, packed into zip files. I’ve many of
these zip files.

My script consists in opening all these files on the fly in the zip,
unpack the lines, make some storage on a SQL db.

I’ve noticed a huge slowdown in 1.9 mode vs 1.8 mode. ~51 seconds
instead of ~3 seconds.

I’ve put the code snippet on pastie: http://pastie.org/3816201

1/ run it at least once to create a zip file (~30Mb, a random file
repeated 25 times in the archive)
I strongly suggest to stay in 1.8 mode…

2/ run it in 1.8 mode
c:\jruby>jruby -b ziptest.rb
I, [2012-04-19T13:41:54.262000 #840] INFO – : START
I, [2012-04-19T13:41:54.431000 #840] INFO – : PROCESSED lorems-1.txt
FROM out.zip
I, [2012-04-19T13:41:54.506000 #840] INFO – : PROCESSED
lorems-10.txt FROM out.zip
I, [2012-04-19T13:41:54.586000 #840] INFO – : PROCESSED
lorems-11.txt FROM out.zip
I, [2012-04-19T13:41:54.659000 #840] INFO – : PROCESSED
lorems-12.txt FROM out.zip
I, [2012-04-19T13:41:54.730000 #840] INFO – : PROCESSED
lorems-13.txt FROM out.zip
I, [2012-04-19T13:41:54.807000 #840] INFO – : PROCESSED
lorems-14.txt FROM out.zip
I, [2012-04-19T13:41:54.887000 #840] INFO – : PROCESSED
lorems-15.txt FROM out.zip
I, [2012-04-19T13:41:54.959000 #840] INFO – : PROCESSED
lorems-16.txt FROM out.zip
I, [2012-04-19T13:41:55.032000 #840] INFO – : PROCESSED
lorems-17.txt FROM out.zip
I, [2012-04-19T13:41:55.108000 #840] INFO – : PROCESSED
lorems-18.txt FROM out.zip
I, [2012-04-19T13:41:55.181000 #840] INFO – : PROCESSED
lorems-19.txt FROM out.zip
I, [2012-04-19T13:41:55.261000 #840] INFO – : PROCESSED lorems-2.txt
FROM out.zip
I, [2012-04-19T13:41:55.348000 #840] INFO – : PROCESSED
lorems-20.txt FROM out.zip
I, [2012-04-19T13:41:55.404000 #840] INFO – : PROCESSED
lorems-21.txt FROM out.zip
I, [2012-04-19T13:41:55.474000 #840] INFO – : PROCESSED
lorems-22.txt FROM out.zip
I, [2012-04-19T13:41:55.544000 #840] INFO – : PROCESSED
lorems-23.txt FROM out.zip
I, [2012-04-19T13:41:55.624000 #840] INFO – : PROCESSED
lorems-24.txt FROM out.zip
I, [2012-04-19T13:41:55.694000 #840] INFO – : PROCESSED
lorems-25.txt FROM out.zip
I, [2012-04-19T13:41:55.750000 #840] INFO – : PROCESSED lorems-3.txt
FROM out.zip
I, [2012-04-19T13:41:55.828000 #840] INFO – : PROCESSED lorems-4.txt
FROM out.zip
I, [2012-04-19T13:41:55.901000 #840] INFO – : PROCESSED lorems-5.txt
FROM out.zip
I, [2012-04-19T13:41:55.973000 #840] INFO – : PROCESSED lorems-6.txt
FROM out.zip
I, [2012-04-19T13:41:56.046000 #840] INFO – : PROCESSED lorems-7.txt
FROM out.zip
I, [2012-04-19T13:41:56.118000 #840] INFO – : PROCESSED lorems-8.txt
FROM out.zip
I, [2012-04-19T13:41:56.197000 #840] INFO – : PROCESSED lorems-9.txt
FROM out.zip
I, [2012-04-19T13:41:56.198000 #840] INFO – : END
Runtime: 2903 ms

3/ run it in 1.9 mode
c:\jruby>jruby --1.9 -b ziptest.rb
I, [2012-04-19T13:42:03.296000 #4972] INFO – : START
I, [2012-04-19T13:42:05.417000 #4972] INFO – : PROCESSED
lorems-1.txt FROM out.zip
I, [2012-04-19T13:42:07.412000 #4972] INFO – : PROCESSED
lorems-10.txt FROM out.zip
I, [2012-04-19T13:42:09.392000 #4972] INFO – : PROCESSED
lorems-11.txt FROM out.zip
I, [2012-04-19T13:42:11.431000 #4972] INFO – : PROCESSED
lorems-12.txt FROM out.zip
I, [2012-04-19T13:42:13.424000 #4972] INFO – : PROCESSED
lorems-13.txt FROM out.zip
I, [2012-04-19T13:42:15.470000 #4972] INFO – : PROCESSED
lorems-14.txt FROM out.zip
I, [2012-04-19T13:42:17.460000 #4972] INFO – : PROCESSED
lorems-15.txt FROM out.zip
I, [2012-04-19T13:42:19.443000 #4972] INFO – : PROCESSED
lorems-16.txt FROM out.zip
I, [2012-04-19T13:42:21.451000 #4972] INFO – : PROCESSED
lorems-17.txt FROM out.zip
I, [2012-04-19T13:42:23.472000 #4972] INFO – : PROCESSED
lorems-18.txt FROM out.zip
I, [2012-04-19T13:42:25.498000 #4972] INFO – : PROCESSED
lorems-19.txt FROM out.zip
I, [2012-04-19T13:42:27.534000 #4972] INFO – : PROCESSED
lorems-2.txt FROM out.zip
I, [2012-04-19T13:42:29.559000 #4972] INFO – : PROCESSED
lorems-20.txt FROM out.zip
I, [2012-04-19T13:42:31.555000 #4972] INFO – : PROCESSED
lorems-21.txt FROM out.zip
I, [2012-04-19T13:42:33.605000 #4972] INFO – : PROCESSED
lorems-22.txt FROM out.zip
I, [2012-04-19T13:42:35.604000 #4972] INFO – : PROCESSED
lorems-23.txt FROM out.zip
I, [2012-04-19T13:42:37.602000 #4972] INFO – : PROCESSED
lorems-24.txt FROM out.zip
I, [2012-04-19T13:42:39.585000 #4972] INFO – : PROCESSED
lorems-25.txt FROM out.zip
I, [2012-04-19T13:42:41.576000 #4972] INFO – : PROCESSED
lorems-3.txt FROM out.zip
I, [2012-04-19T13:42:43.563000 #4972] INFO – : PROCESSED
lorems-4.txt FROM out.zip
I, [2012-04-19T13:42:45.555000 #4972] INFO – : PROCESSED
lorems-5.txt FROM out.zip
I, [2012-04-19T13:42:47.554000 #4972] INFO – : PROCESSED
lorems-6.txt FROM out.zip
I, [2012-04-19T13:42:49.551000 #4972] INFO – : PROCESSED
lorems-7.txt FROM out.zip
I, [2012-04-19T13:42:51.555000 #4972] INFO – : PROCESSED
lorems-8.txt FROM out.zip
I, [2012-04-19T13:42:53.557000 #4972] INFO – : PROCESSED
lorems-9.txt FROM out.zip
I, [2012-04-19T13:42:53.557000 #4972] INFO – : END
Runtime: 50976 ms

I do not know if this is worth putting it in JIRA yet. Can someone
else confirm these results first?

Thanks.

–
Christian

2

I see a similar slowdown between JRuby 1.8 and JRuby 1.9, but more
importantly the slowdown is the same between MRI 1.8 and 1.9. So this is
nothing specific to JRuby.

Some quick profiling tells me most of the extra time in 1.9 mode is
spent inside zip-2.0.2/lib/zip/ioextras.rb AbstractInputStream#gets:

def gets(aSepString=$/)
  @lineno = @lineno.next
  return read if aSepString == nil
  aSepString="#{$/}#{$/}" if aSepString == ""

  bufferIndex=0
  while ((matchIndex = @outputBuffer.index(aSepString, bufferIndex))

== nil)
[email protected]
if input_finished?
return @outputBuffer.empty? ? nil : flush
end
@outputBuffer << produce_input
end
sepIndex=matchIndex + aSepString.length
return @outputBuffer.slice!(0…sepIndex)
end

I’m not sure why this is so much slower under 1.9, but it is. Have you
tried using any other zip libraries to see if they perform better under
1.9?

Ben

3

On Thu, Apr 19, 2012 at 3:36 PM, Benjamin B.
[email protected] wrote:

I see a similar slowdown between JRuby 1.8 and JRuby 1.9, but more importantly
the slowdown is the same between MRI 1.8 and 1.9. So this is nothing specific to
JRuby.

(…)
I’m not sure why this is so much slower under 1.9, but it is. Have you tried
using any other zip libraries to see if they perform better under 1.9?

Hi Ben,

No I’m currently using rubyzip-0.9.5 (forgot to mention it earlier on).

I believe looking at java.util.zip may solve this. Experimenting right
now. Thanks for the suggestions and profiling.

–
Christian

4

On Thu, Apr 19, 2012 at 3:58 PM, Christian MICHON
[email protected] wrote:

I believe looking at java.util.zip may solve this. Experimenting right
now. Thanks for the suggestions and profiling.

Indeed using java.util.zip coupled with java.io buffering does help…

New code at http://pastie.org/3816909

c:\jruby>jruby -b newziptest.rb
I, [2012-04-19T16:16:12.256000 #808] INFO – : START
I, [2012-04-19T16:16:12.441000 #808] INFO – : PROCESSED lorems-1.txt
FROM out.zip
I, [2012-04-19T16:16:12.560000 #808] INFO – : PROCESSED lorems-2.txt
FROM out.zip
I, [2012-04-19T16:16:12.671000 #808] INFO – : PROCESSED lorems-3.txt
FROM out.zip
I, [2012-04-19T16:16:12.785000 #808] INFO – : PROCESSED lorems-4.txt
FROM out.zip
I, [2012-04-19T16:16:12.906000 #808] INFO – : PROCESSED lorems-5.txt
FROM out.zip
I, [2012-04-19T16:16:13.017000 #808] INFO – : PROCESSED lorems-6.txt
FROM out.zip
I, [2012-04-19T16:16:13.129000 #808] INFO – : PROCESSED lorems-7.txt
FROM out.zip
I, [2012-04-19T16:16:13.245000 #808] INFO – : PROCESSED lorems-8.txt
FROM out.zip
I, [2012-04-19T16:16:13.362000 #808] INFO – : PROCESSED lorems-9.txt
FROM out.zip
I, [2012-04-19T16:16:13.479000 #808] INFO – : PROCESSED
lorems-10.txt FROM out.zip
I, [2012-04-19T16:16:13.595000 #808] INFO – : PROCESSED
lorems-11.txt FROM out.zip
I, [2012-04-19T16:16:13.707000 #808] INFO – : PROCESSED
lorems-12.txt FROM out.zip
I, [2012-04-19T16:16:13.836000 #808] INFO – : PROCESSED
lorems-13.txt FROM out.zip
I, [2012-04-19T16:16:13.946000 #808] INFO – : PROCESSED
lorems-14.txt FROM out.zip
I, [2012-04-19T16:16:14.056000 #808] INFO – : PROCESSED
lorems-15.txt FROM out.zip
I, [2012-04-19T16:16:14.176000 #808] INFO – : PROCESSED
lorems-16.txt FROM out.zip
I, [2012-04-19T16:16:14.296000 #808] INFO – : PROCESSED
lorems-17.txt FROM out.zip
I, [2012-04-19T16:16:14.409000 #808] INFO – : PROCESSED
lorems-18.txt FROM out.zip
I, [2012-04-19T16:16:14.519000 #808] INFO – : PROCESSED
lorems-19.txt FROM out.zip
I, [2012-04-19T16:16:14.629000 #808] INFO – : PROCESSED
lorems-20.txt FROM out.zip
I, [2012-04-19T16:16:14.749000 #808] INFO – : PROCESSED
lorems-21.txt FROM out.zip
I, [2012-04-19T16:16:14.855000 #808] INFO – : PROCESSED
lorems-22.txt FROM out.zip
I, [2012-04-19T16:16:14.971000 #808] INFO – : PROCESSED
lorems-23.txt FROM out.zip
I, [2012-04-19T16:16:15.081000 #808] INFO – : PROCESSED
lorems-24.txt FROM out.zip
I, [2012-04-19T16:16:15.194000 #808] INFO – : PROCESSED
lorems-25.txt FROM out.zip
I, [2012-04-19T16:16:15.194000 #808] INFO – : END
Runtime: 3184 ms

c:\jruby>jruby --1.9 -b newziptest.rb
I, [2012-04-19T16:16:03.242000 #4880] INFO – : START
I, [2012-04-19T16:16:03.424000 #4880] INFO – : PROCESSED
lorems-1.txt FROM out.zip
I, [2012-04-19T16:16:03.536000 #4880] INFO – : PROCESSED
lorems-2.txt FROM out.zip
I, [2012-04-19T16:16:03.646000 #4880] INFO – : PROCESSED
lorems-3.txt FROM out.zip
I, [2012-04-19T16:16:03.755000 #4880] INFO – : PROCESSED
lorems-4.txt FROM out.zip
I, [2012-04-19T16:16:03.871000 #4880] INFO – : PROCESSED
lorems-5.txt FROM out.zip
I, [2012-04-19T16:16:03.982000 #4880] INFO – : PROCESSED
lorems-6.txt FROM out.zip
I, [2012-04-19T16:16:04.097000 #4880] INFO – : PROCESSED
lorems-7.txt FROM out.zip
I, [2012-04-19T16:16:04.208000 #4880] INFO – : PROCESSED
lorems-8.txt FROM out.zip
I, [2012-04-19T16:16:04.318000 #4880] INFO – : PROCESSED
lorems-9.txt FROM out.zip
I, [2012-04-19T16:16:04.429000 #4880] INFO – : PROCESSED
lorems-10.txt FROM out.zip
I, [2012-04-19T16:16:04.538000 #4880] INFO – : PROCESSED
lorems-11.txt FROM out.zip
I, [2012-04-19T16:16:04.645000 #4880] INFO – : PROCESSED
lorems-12.txt FROM out.zip
I, [2012-04-19T16:16:04.754000 #4880] INFO – : PROCESSED
lorems-13.txt FROM out.zip
I, [2012-04-19T16:16:04.875000 #4880] INFO – : PROCESSED
lorems-14.txt FROM out.zip
I, [2012-04-19T16:16:04.986000 #4880] INFO – : PROCESSED
lorems-15.txt FROM out.zip
I, [2012-04-19T16:16:05.097000 #4880] INFO – : PROCESSED
lorems-16.txt FROM out.zip
I, [2012-04-19T16:16:05.206000 #4880] INFO – : PROCESSED
lorems-17.txt FROM out.zip
I, [2012-04-19T16:16:05.313000 #4880] INFO – : PROCESSED
lorems-18.txt FROM out.zip
I, [2012-04-19T16:16:05.422000 #4880] INFO – : PROCESSED
lorems-19.txt FROM out.zip
I, [2012-04-19T16:16:05.531000 #4880] INFO – : PROCESSED
lorems-20.txt FROM out.zip
I, [2012-04-19T16:16:05.639000 #4880] INFO – : PROCESSED
lorems-21.txt FROM out.zip
I, [2012-04-19T16:16:05.748000 #4880] INFO – : PROCESSED
lorems-22.txt FROM out.zip
I, [2012-04-19T16:16:05.872000 #4880] INFO – : PROCESSED
lorems-23.txt FROM out.zip
I, [2012-04-19T16:16:05.981000 #4880] INFO – : PROCESSED
lorems-24.txt FROM out.zip
I, [2012-04-19T16:16:06.094000 #4880] INFO – : PROCESSED
lorems-25.txt FROM out.zip
I, [2012-04-19T16:16:06.094000 #4880] INFO – : END
Runtime: 3076 ms

But I still believe this is an issue for jruby 1.6.7 in 1.9 mode… At
least now I should be able to run my full application in 1.9 mode with
java.util.zip

Thanks for the suggestions!

–
Christian