Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby) (831 Views)
Reply
Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 1 of 10 (938 Views)
Accepted Solution

Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

[ Edited ]

We're trying to assess if running JRuby on Alpha is practical, and need answers for why resource usage just to start the application on Alpha is so much higher than Itanium for the same minimal test case.

 

Using a vanilla JRuby 1.6.0 from upstream unpacked at JRUBY_ROOT and defining the JRuby command as follows, I am seeing startup times on JRE 1.5 on Alpha that are way out of line with startup times on JRE 1.6 on Itanium. This reflects in a much higher BUFIO time as well. With SET WATCH enabled I see excessive directory scans for non-existent path components on Alpha that aren't happening on IA64. I have tried messing with classpath and bootclasspath (which are equivalent on both systems, i.e. CLASSPATH and JAVA$CLASSPATH are not defined, so it should be set to just what you see in my test command) to try to resolve the issue but so far have been unable to prevent the JRuby on Alpha from making so many useless directory scans. What am I missing? Why the big difference between architectures?

 

$ show sym jruby
JRUBY== "$ SYS$COMMON:[JAVA$150.bin]java$java "-Djruby.home=/jruby_root" "-Djruby.lib=/jruby_root/lib" "-Djruby.script=jr
uby" "-Djruby.memory.max=500m" "-Djruby.stack.max=1024k" "-Xmx500m" "-Xss1024k" "Xbootclasspath/a:/jruby_root/lib/jruby.jar"
"org.jruby.Main" "
$ show log jruby_root
"JRUBY_ROOT" = "DYM$SYS_V:[DYMAX.JRUBY]" (LNM$PROCESS_TABLE)
$ type hworld.rb
puts "hello world"
$ jruby hworld.rb

On IA64, using the above example code, typical resource usage is:

 

Dirio=  6383 Bufio=  1003 Kernel= 44 Exec=  5 User=126 Elapsed=   355

For the above example on Alpha, typical resource usage is:

 

Dirio=  5707 Bufio= 18473 Kernel=786 Exec=311 User=490 Elapsed=  3653

As for the count of failed directory scans on Itanium for the same example above:

 

search rtest_i64.log "directory scan","status: 00000000"/mat=and/stat/out=nl:

Files searched:                 1       Buffered I/O count:         8
Records searched:            6733       Direct I/O count:         418
Characters searched:       853299       Page faults:               26
Records matched:              404       Elapsed CPU time:  0 00:00:00.03
Lines printed:                404       Elapsed time:      0 00:00:00.03

 And on Alpha:

 

search rtest_alp4.log "directory scan","status: 00000000"/mat=and/stat/out=nl:

Files searched:                 1       Buffered I/O count:         8
Records searched:           96908       Direct I/O count:       13541
Characters searched:     12760392       Page faults:               26
Records matched:            13338       Elapsed CPU time:  0 00:00:00.57
Lines printed:              13338       Elapsed time:      0 00:00:00.57 

So, again, orders of magnitude difference.

 

Here are some example failed directory scans that appear on Alpha but not on Itanium:

 

%XQP, Thread #0, Directory scan for: MAIN.CLASS;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN_CLASS.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN_CLASS.DIR;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN$STATUS.CLASS;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN$STATUS_CLASS.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN$STATUS_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN$STATUS_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: MAIN$STATUS_CLASS.DIR;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYTHREAD$S$0$0$MAIN.CLASS;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYTHREAD$S$0$0$MAIN_CLASS.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYTHREAD$S$0$0$MAIN_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYTHREAD$S$0$0$MAIN_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYTHREAD$S$0$0$MAIN_CLASS.DIR;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYNUMERIC$I$1$0$REMAINDER.CLASS;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYNUMERIC$I$1$0$REMAINDER_CLASS.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYNUMERIC$I$1$0$REMAINDER_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYNUMERIC$I$1$0$REMAINDER_CLASS.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: RUBYNUMERIC$I$1$0$REMAINDER_CLASS.DIR;0, Status: 00000000

 We believe if we can get Java from looking all over hell and creation for stuff it's going to fail to find anyway, we could dramatically improve JRuby startup time on Alpha. Can someone who knows what's going on between the two Java implementations please help explain our results? Better yet, please point us in the right direction for resolving the issue.

 

Thanks,

Ben

 

p.s. I did a brief test with JRuby 1.6.5 and the numbers were not significantly different. so I have no reason to believe the latest release, 1.6.6, would be any better either.

 

p.p.s. In case it matters, my Java versions are:

 

java version "1.5.0"
Java(TM) 2 Runtime Environment, Standard Edition
Fast VM (build 1.5.0-6.p1, build J2SDK.v.1.5.0:11/16/2009-20:33, native threads, jit_150)

java version "1.6.0"
Java(TM) SE Runtime Environment
Java HotSpot(TM) 64-Bit Server VM (build 14.3-b01, mixed mode)

 

 

Honored Contributor
Hein van den Heuvel
Posts: 6,588
Registered: ‎05-19-2003
Message 2 of 10 (907 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

 

Well written problem description. Thank you!

 

What does the logical name DYM$SYS_V translate to on the Alpha, versus the Itanium.

As you drill down on that name, maybe one system has a much wider search list than the other?

If a search list is currently involved, can you retry with a simple logical name pointing directly to the right disk/directory?

Java/Ruby will have been installed on an ODS-5 disk.

But that  DYM$SYS_V , is it pointing to volumes with the same file structure level (2 or 5) on Alpha versus Itanium?

Can you somehow make it find what it is looking for in a benign way? (by re-arranging the search lists if those are in play).

 

fwiw,
Hein. 


 

Esteemed Contributor
H.Becker
Posts: 373
Registered: ‎04-09-2009
Message 3 of 10 (891 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

I admit that I don't have access to an Integrity server, nor do I have a 1.5 version of Java on Alpha and I don't have any idea what JRuby (is and) does.
 
The underscore as seen in MAIN_CLASS usually is an effect of what is set in JAVA$FILENAME_CONTROLS to map Unix style names to VMS ones. Is that logical differently defined on both systems?
 
However, with "org.jruby.Main" I would have expected scans for ORG_JRUBY_MAIN. Are there any in the log?
It would be interesting to know, in which directory/directories MAIN.CLASS and all the other variants were searched, and found? With "Xbootclasspath" I would expect in the [.org.jruby] subdirectory of the current working directory: if there is no -classpath and no CLASSPATH then the user class path consists of the current directory. But this would only happen if "Main" can not be found in jruby.jar.
 
You may want to use -verbose:class, which may generate a lot of output, and check from which jar and/or directory  the classes are loaded.
Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 4 of 10 (869 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

DYM$SYS_V is the same on both systems:

 

   "DYM$SYS_V" = "$2$DKC0:" (LNM$SYSTEM_TABLE)

 This is an ODS-5 volume.

 

Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 5 of 10 (867 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

[ Edited ]

There were indeed searches for "ORG_JRUBY_MAIN.". I only showed the paths matching the string "main" that were in the Alpha log but not in the Itanium log. However, on the Itanium those searches were for "org_jruby_Main.". That is due to these settings on Itanium that are not set on Alpha, particularly the case preserve setting:



(LNM$JOB_887817C0)

  "DECC$ARGV_PARSE_STYLE" = "ENABLE"
  "DECC$EFS_CASE_PRESERVE" = "ENABLE"
  "DECC$EFS_CHARSET" = "ENABLE"

 

That makes the Itanium scan for mixed case paths, but it doesn't change which paths are being scanned for. Nor does it influence the timings positively when set on the Alpha. Here is the common set of paths matching the string "main" that are scanned for unsuccessfully on both platforms in a new test with the above settings now applied to the Alpha as well:

 

%XQP, Thread #0, Directory scan for: org_jruby.Main.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby.Main;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby.Main;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.DIR;0, Status: 00000000

 

As for JAVA$FILENAME_CONTROLS, that is set to -1 on both systems.

 

There is nothing in either log matching "main" and "00000001". In fact, there is nothing at all matching the "main" other than the "Status: 00000000" entries shown above that are found in both logs and the now mixed-cased ones from which I showed you an excerpt in my original post (35 lines in all). And all that is consistent with your observation that the additional searches should only happen if "Main" can not be found in jruby.jar (and clearly it is, since the test program works on both systems). That's what I thought, too, so it's a real puzzler.

 

Here are the first several lines of my search for "main" with both SET WATCH and -verbose:class together on the Alpha:

 

%XQP, Thread #0, Directory scan for: org_jruby.Main.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby.Main;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby.Main;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: org_jruby_Main.DIR;0, Status: 00000000
[Loaded java/security/ProtectionDomain.class from /SYS$COMMON/JAVA$150/JRE/lib/rt.jar]
%XQP, Thread #0, Directory scan for: Main.class.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: Main.class;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main.class;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.DIR;0, Status: 00000000
[Loaded org/jruby/Main.class from /jruby_root/lib/jruby.jar]

Ben 

Esteemed Contributor
H.Becker
Posts: 373
Registered: ‎04-09-2009
Message 6 of 10 (862 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

>>>
%XQP, Thread #0, Directory scan for: Main.class.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: Main.class;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main.class;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.DIR;1, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.;0, Status: 00000000
%XQP, Thread #0, Directory scan for: Main_class.DIR;0, Status: 00000000
[Loaded org/jruby/Main.class from /jruby_root/lib/jruby.jar]
 
To me this looks like there is a dot in Xbootclasspath before you append the jruby.jar. Did you try to replace the complete  Xbootclasspath or to prepend the jar file with /p?
Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 7 of 10 (856 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

As per my original post, I used /a ... Looking back at it, I don't know what happened to the "-" in front (maybe a mistake when I un-wrapped the lines by hand) but here is a fresh paste of the definition again:

 

JRUBY == "$ SYS$COMMON:[JAVA$150.bin]java$java  "-Djruby.home=/jruby_root" "-Djruby.lib=/jruby_root/lib" "-Djruby.script=jruby" "-Djruby.memory.max=500m" "-Djruby.stack.max=1024k" "-Xmx500m" "-Xss1024k" "-Djruby.shell=/dyulib/sh.exe" "-Xbootclasspath/a:/jruby_root/lib/jruby.jar:/jna_root/jna.jar"  -verbose:class "org.jruby.Main" "-I/dym$disk/dymax/pro/ruby/lib/site_ruby/dylib" "-I/dym$disk/dymax/pro/ruby/lib/site_ruby" "

 All of this is patterned after what jruby looks like (from 'ps auxwww' output) on Linux:

 

java -client -Djruby.memory.max=-Xmx500m -Djruby.stack.max=-Xss1024k -Xmx500m -Xss1024k -Djffi.boot.library.path=/f/Development/Live/jruby-1.6.2/lib/native/i386-Linux:/f/Development/Live/jruby-1.6.2/lib/native/ppc-Linux:/f/Development/Live/jruby-1.6.2/lib/native/x86_64-Linux -Dfile.encoding=UTF-8 -Xbootclasspath/a:/f/Development/Live/jruby-1.6.2/lib/jruby.jar -classpath : -Djruby.home=/f/Development/Live/jruby-1.6.2 -Djruby.lib=/f/Development/Live/jruby-1.6.2/lib -Djruby.script=jruby -Djruby.shell=/bin/sh org.jruby.Main

 We don't yet have a working jffi for VMS, so that part is missing from our definition. I tried also playing with -classpath : (maybe this nulls out the classpath, if set?) but this made no difference.

 

Ben

 

Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 8 of 10 (854 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

I have now posted the complete log with "SET WATCH" and -verbose:class here: rtest_alp.bg

 

Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 9 of 10 (849 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

Bingo! Prepending instead of appending makes a *huge* difference here:

 

!A:MEDIANET.HARDWARE!> @rtest

                       J R U B Y  Hello World test

java version "1.5.0"
Java(TM) 2 Runtime Environment, Standard Edition
Fast VM (build 1.5.0-6.p1, build J2SDK.v.1.5.0:11/16/2009-20:33, native threads, jit_150)
jruby 1.6.0 (ruby 1.8.7 patchlevel 330) (2011-03-15 f3b6154) (Fast VM 1.5.0) [OpenVMS-alpha-java]

  JRUBYT == "$ SYS$COMMON:[JAVA$150.bin]java$java  "-Djruby.home=/jruby_root" "-Djruby.lib=/jruby_root/lib" "-Djruby.script=jruby" "-Djruby.memory.max=500m" "-Djruby.stack.max=1024k" "-Xmx500m" "-Xss1024k" "-Djruby.shell=/dyulib/sh.exe" "-Xbootclasspath/p:/jruby_root/lib/jruby.jar:/jna_root/jna.jar"  -client "org.jruby.Main" "-I/dym$disk/dymax/pro/ruby/lib/site_ruby/dylib" "-
I/dym$disk/dymax/pro/ruby/lib/site_ruby" "

hello world

Dirio=  2027 Bufio=   793 Kernel= 61 Exec= 11 User=370 Elapsed=   450

 

Frequent Advisor
BenAArmstrong
Posts: 42
Registered: ‎06-30-2011
Message 10 of 10 (831 Views)

Re: Slow Java startup Alpha vs. I64: excessive directory scans (vanilla upstream JRuby)

I have filed this as an issue upstream, xreffing back to this thread:

 

http://jira.codehaus.org/browse/JRUBY-6448

 

Ben

 

The opinions expressed above are the personal opinions of the authors, not of HP. By using this site, you accept the Terms of Use and Rules of Participation.