Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JRuby trying to load jit'd code from Jars #3147

Closed
hydrogen18 opened this Issue Jul 16, 2015 · 11 comments

Comments

Projects
None yet
4 participants
@hydrogen18
Copy link

hydrogen18 commented Jul 16, 2015

Hi, I'm using JRuby to run a rails app.

I traced JRuby 1.7.19 with InTrace. Each request I see many attempts to load classes from Jars like this. This is just one of the classes. None of them are ever found in a Jar. This doesn't seem like something that would be found in a jar file ever.

Is this a behavior of JRuby or of Java? Is there anyway I can suppress it searching the filesystem for these classes?

[12:21:31.346]:[38]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.346]:[38]:java.util.jar.JarFile:getEntry: {
[12:21:31.346]:[38]:java.util.jar.JarFile:getEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.346]:[38]:java.util.jar.JarFile:getEntry: Return: null
[12:21:31.346]:[38]:java.util.jar.JarFile:getEntry: }
[12:21:31.346]:[38]:java.util.jar.JarFile:getJarEntry: Return: null
[12:21:31.346]:[38]:java.util.jar.JarFile:getJarEntry: }
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: {
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: {
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: Return: null
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: }
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: Return: null
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: }
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: {
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: {
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: Return: null
[12:21:31.347]:[38]:java.util.jar.JarFile:getEntry: }
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: Return: null
[12:21:31.347]:[38]:java.util.jar.JarFile:getJarEntry: }
[12:21:31.348]:[38]:java.util.jar.JarFile:getJarEntry: {
[12:21:31.348]:[38]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: {
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: Return: null
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: }
[12:21:31.348]:[38]:java.util.jar.JarFile:getJarEntry: Return: null
[12:21:31.348]:[38]:java.util.jar.JarFile:getJarEntry: }
[12:21:31.348]:[38]:java.util.jar.JarFile:getJarEntry: {
[12:21:31.348]:[38]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: {
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: Arg: rubyjit/ActiveSupport::SafeBuffer$$initialize_0ea9367670c26c377238e8757312acfa98a148f41697085528.class
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: Return: null
[12:21:31.348]:[38]:java.util.jar.JarFile:getEntry: }
@headius

This comment has been minimized.

Copy link
Member

headius commented Jul 16, 2015

Hmm...this looks like logic to try to load a dumped version of each jitted method. It should not be doing this normally.

Thanks for this report; this could indicate a lot of slow searching for classes that will never be found, bogging down the JIT. I will investigate.

@headius

This comment has been minimized.

Copy link
Member

headius commented Jul 16, 2015

Is it possible to get a backtrace from one of these searches? I can probably fix this in seconds with that, but I'm having trouble locating where these loads might be happening.

@hydrogen18

This comment has been minimized.

Copy link
Author

hydrogen18 commented Jul 16, 2015

I can trace based off class names, including with a wildcard. What classes would you like to see ?

@headius

This comment has been minimized.

Copy link
Member

headius commented Jul 16, 2015

Actually nevermind, I think I've found it!

It appears we have code in ClassCache that attempts to load previously-dumped jitted methods from classloaders. If that fails, it proceeds on to define the jitted code as a new class. If it succeeds...it proceeds on to define the jitted code as a new class. So this searching is completely unnecessary, and never worked anyway because JIT dumping was never really finished as a concept in 1.7.

I think our best move would be to simply remove all half-baked JIT dumping and this logic will disappear along with it.

@hydrogen18

This comment has been minimized.

Copy link
Author

hydrogen18 commented Jul 16, 2015

Sounds great, let me know if there is any way I can help you with testing out the fix.

@headius

This comment has been minimized.

Copy link
Member

headius commented Jul 16, 2015

I have started a snapshot build of JRuby 1.7.22 (1.7 HEAD) that has the fix. Basically I just removed all JIT code cache logic because it was half-baked and not working anyway (but it still attempted the classloader search).

When the 1.7.22-SNAPSHOT builds update on ci.jruby.org, grab it and confirm it's working.

@headius

This comment has been minimized.

Copy link
Member

headius commented Jul 16, 2015

@headius

This comment has been minimized.

Copy link
Member

headius commented Jul 16, 2015

Optimistically marking this one as fixed. Do let us know when you're able to confirm it.

@headius headius closed this Jul 16, 2015

@headius headius added this to the JRuby 1.7.22 milestone Jul 16, 2015

@hydrogen18

This comment has been minimized.

Copy link
Author

hydrogen18 commented Jul 17, 2015

I downloaded your snapshot and changed my Gemfile to '1.7.22-SNAPSHOT'. Then I did

rvm use system
export PATH=..../jruby-snapshot/bin:$PATH
gem install bundler --version 1.9.9
bundle install
trinidad

During trinidad startup I see I am using your snapshot

[ericu-destroyer-of-worlds] community$ PATH=$HOME/Downloads/jruby-1.7.22-SNAPSHOT/bin:$PATH JRUBY_OPTS="-J-javaagent:/home/ericu/Downloads/intrace-agent.jar $JRUBY_OPTS" trinidad
## Loaded InTrace Agent.
## InTrace Agent listening on port 9123
Initializing ProtocolHandler ["http-bio-8443"]
Initializing ProtocolHandler ["http-bio-8080"]
Starting Servlet Engine: Apache Tomcat/7.0.42
jruby 1.7.22-SNAPSHOT (1.9.3p551) 2015-07-16 1c3cdaa on Java HotSpot(TM) 64-Bit Server VM 1.7.0_75-b13 +jit [linux-amd64]

Using intrace I am still seeing calls to load rubyjit$ classes from jars.

[07:16:29.526]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.526]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.526]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.526]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.526]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.526]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.526]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.526]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.526]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.526]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.526]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.527]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: {
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Arg: rubyjit$Journey::Route$$score_e63894ac720b252220b096ecd154889f8a2ba8821506933368$block_0$RUBY$__file__.class
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getEntry: }
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: Return: null
[07:16:29.528]:[36]:java.util.jar.JarFile:getJarEntry: }

@hydrogen18

This comment has been minimized.

Copy link
Author

hydrogen18 commented Jul 19, 2015

I should clarify: I'm seeing less class loading of rubyjit$. In fact, what I pasted in was the only instance I saw.

@hydrogen18

This comment has been minimized.

Copy link
Author

hydrogen18 commented Jul 22, 2015

Is there a chance of this getting fixed for 1.7.22 ? It seems as though perhaps there is just one last section of code trying to load a rubyjit$ class.

@kares kares reopened this Jul 23, 2015

@headius headius closed this in 1c3cdaa Jul 25, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.