JRuby

Marshal.load takes forever when deserializing Rails unicode db in WEBrick

Details

  • Number of attachments :
    3

Description

There is a very long delay (~100 seconds) when deserializing the Rails unicode DB using Marshal.load running in WEBrick.

File.open(ActiveSupport::Multibyte::Unicode::UnicodeDatabase.filename, 'rb')

{ |f| puts 'start loading unicode db' Marshal.load f.read puts 'finished loading unicode db' }

This is a 800kb binary file, the issue appears to be WEBrick specific, as it does not occur in Rails Console or when running the JRuby app using winstone.

Please see attached file with sample app, and refer to "home/index" action.

Thanks,
Keith

  3. File
    marshal_output
    06/Jun/12 4:02 PM
    116 kB
    Xavier Shay

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Charles Oliver Nutter added a comment -

I am so far unable to reproduce this...it runs in well under a second for me on JRuby master and 1.6.7, on Java 6 and 7.

A few things for you to try:

  • Try setting JAVA_OPTS=-Xprof in the server's environment. The JVM will dump a sampled profile.
  • When it's in the middle of the long loading period you see, hit Control+\ to get a thread dump (or use the "jstack <pid>" command). This will show us what the threads are doing.
Show
Charles Oliver Nutter added a comment - I am so far unable to reproduce this...it runs in well under a second for me on JRuby master and 1.6.7, on Java 6 and 7. A few things for you to try: Try setting JAVA_OPTS=-Xprof in the server's environment. The JVM will dump a sampled profile. When it's in the middle of the long loading period you see, hit Control+\ to get a thread dump (or use the "jstack <pid>" command). This will show us what the threads are doing.
Hide
Permalink
Keith Gaputis added a comment - - edited

Charles, thank you for looking into this. I missed the notification email from your response a couple weeks back.

I have recreated this problem on both my win7 x64 development machines. Please see attached zip file for server and jstack output from both machines when using -Xprof.

  • Execution 1 in both cases is a Ctrl+\ during hanging request followed by Ctrl+C once it finally finishes
  • Execution 2 in both cases is a Ctrl+C during hanging request

Thanks, please let me know what I can do to help further if you cannot recreate this.

Show
Keith Gaputis added a comment - - edited Charles, thank you for looking into this. I missed the notification email from your response a couple weeks back. I have recreated this problem on both my win7 x64 development machines. Please see attached zip file for server and jstack output from both machines when using -Xprof. Execution 1 in both cases is a Ctrl+\ during hanging request followed by Ctrl+C once it finally finishes Execution 2 in both cases is a Ctrl+C during hanging request Thanks, please let me know what I can do to help further if you cannot recreate this.
Hide
Permalink
Xavier Shay added a comment -

I am seeing this in development mode also, but only when the database is loaded within the context of a web request using webrick.

If I load it on server startup it works fine.
I cannot reproduce using thin.

Still trying to cut down a minimal test case. Attaching jstack output.

On OSX.

Show
Xavier Shay added a comment - I am seeing this in development mode also, but only when the database is loaded within the context of a web request using webrick. If I load it on server startup it works fine. I cannot reproduce using thin. Still trying to cut down a minimal test case. Attaching jstack output. On OSX.
Hide
Permalink
Xavier Shay added a comment -

jstack output when JRuby is taking forever to Marshal load unicode database.

Show
Xavier Shay added a comment - jstack output when JRuby is taking forever to Marshal load unicode database.
Hide
Permalink
Xavier Shay added a comment - - edited

Confirm I can reproduce with Keith's stripped down test case on jruby-1.6.7.2.

It occurs in both 1.8 and 1.9 modes, takes about twice as long in 1.9.

Show
Xavier Shay added a comment - - edited Confirm I can reproduce with Keith's stripped down test case on jruby-1.6.7.2. It occurs in both 1.8 and 1.9 modes, takes about twice as long in 1.9.
Hide
Permalink
Charles Oliver Nutter added a comment -

From the -Xprof dumps it looks like transcoding is to blame here. It's possible we are (or were) transcoding too much or too often or unnecessarily.

I'll try to reproduce again on master today.

Show
Charles Oliver Nutter added a comment - From the -Xprof dumps it looks like transcoding is to blame here. It's possible we are (or were) transcoding too much or too often or unnecessarily. I'll try to reproduce again on master today.
Hide
Permalink
Charles Oliver Nutter added a comment -

Well it's hard to tell, but it seems to be ok on master. In 1.9 mode, I did bundle exec rails s, which started up WEBrick. I hit /home/index, and after chewing for a second it returned. Subsequent requests sped up.

I'll call this resolved. If someone else can reproduce the slowness, reopen and we'll try to investigate further.

Show
Charles Oliver Nutter added a comment - Well it's hard to tell, but it seems to be ok on master. In 1.9 mode, I did bundle exec rails s, which started up WEBrick. I hit /home/index, and after chewing for a second it returned. Subsequent requests sped up. I'll call this resolved. If someone else can reproduce the slowness, reopen and we'll try to investigate further.

People

  • Assignee:
    Charles Oliver Nutter
    Reporter:
    Keith Gaputis
Vote (0)
Watch (4)

Dates

  • Created:
    Updated:
    Resolved: