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.

Sign up for GitHub

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

Jump to bottom

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

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

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

hydrogen18 opened this issue Jul 16, 2015 · 11 comments
Labels
jit JRuby 1.7.x
Milestone
JRuby 1.7.22

Comments

@hydrogen18
Copy link

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
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
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
Copy link
Author

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

@headius
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
Copy link
Author

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

@headius
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
Copy link
Member

headius commented Jul 16, 2015

The build in question: https://projectodd.ci.cloudbees.com/view/JRuby/job/jruby-1.7-dist/324/

@headius
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 as completed Jul 16, 2015
@headius headius added this to the JRuby 1.7.22 milestone Jul 16, 2015
@hydrogen18
Copy link
Author

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
Copy link
Author

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

@hydrogen18
Copy link
Author

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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
jit JRuby 1.7.x
Projects
None yet
Milestone
JRuby 1.7.22
Development

No branches or pull requests
4 participants
@headius @enebo @kares @hydrogen18