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

Very high load in 1.9 mode #1713

Closed
ocher opened this issue May 22, 2014 · 9 comments
Closed

Very high load in 1.9 mode #1713

ocher opened this issue May 22, 2014 · 9 comments

Comments

@ocher
Copy link

ocher commented May 22, 2014

After porting my Rails app to 1.9 mode I noticed a very high load compared to 1.8 mode.

It's not a GC problem (we were talking about that on #jruby). Also JRuby 1.7.11 and 1.7.4 versions were checked (1.7.4 version was checked because of more complex encoding code in 1.7.11), and both have the same problem in 1.9 mode.

Also, as you can see on the attached load chart, there is a place (compared to the previous day) when load should go down, but still there is something running which uses a lot of CPU.

Load Chart

CPU samples (-Xrunhprof:cpu=samples):

CPU SAMPLES BEGIN (total = 56024520) Thu May 22 09:18:45 2014
rank   self  accum   count trace method
   1 32.66% 32.66% 18295044 300444 java.net.PlainSocketImpl.socketAccept
   2 17.67% 50.33% 9899674 306608 sun.nio.ch.EPollArrayWrapper.epollWait
   3 10.88% 61.20% 6094589 307597 sun.nio.ch.ServerSocketChannelImpl.accept0
   4  5.31% 66.51% 2974356 413630 sun.nio.cs.Surrogate$Parser.parse
   5  5.27% 71.79% 2953717 355160 java.nio.charset.CoderResult$Cache.get
   6  4.92% 76.70% 2754455 354138 java.nio.charset.CoderResult$Cache.access$200
   7  3.35% 80.06% 1879193 306723 java.net.SocketInputStream.socketRead0
   8  1.57% 81.62%  878793 308355 sun.nio.ch.FileDispatcherImpl.read0
   9  1.33% 82.95%  742625 306688 java.net.SocketOutputStream.socketWrite0
  10  1.25% 84.20%  702788 308579 rubyjit$ActiveRecord::Reflection::AssociationReflection$$autodetect_inverse_bc8fa0baf756399a1ecad8d1ea2fccede993ab6b1514204209$block_0$RUBY$__file__.call
  11  1.21% 85.41%  677688 342055 sun.nio.cs.UnicodeEncoder.encodeLoop
  12  0.90% 86.32%  504707 308540 org.jruby.runtime.CompiledBlock19.yield
  13  0.76% 87.07%  425150 342057 sun.nio.cs.UnicodeEncoder.encodeLoop
  14  0.64% 87.72%  361021 342060 org.jruby.util.encoding.CharsetTranscoder$TranscoderEngine.encode
  15  0.55% 88.27%  308108 342058 sun.nio.cs.UnicodeEncoder.encodeLoop
  16  0.53% 88.80%  298387 308534 java.lang.String.intern
  17  0.39% 89.19%  217155 342059 java.nio.charset.CharsetEncoder.encode
  18  0.36% 89.55%  201197 308965 org.jruby.ast.executable.AbstractScript.__file__
  19  0.33% 89.88%  184700 342056 java.nio.charset.CharsetEncoder.encode
  20  0.29% 90.17%  161374 342054 java.nio.charset.CoderResult.malformedForLength
  21  0.28% 90.44%  156531 307657 java.net.Inet6AddressImpl.lookupAllHostAddr
  22  0.24% 90.68%  132732 342061 org.jruby.util.encoding.CharsetTranscoder$TranscoderEngine.encode
  23  0.20% 90.88%  109603 308964 org.jruby.internal.runtime.methods.JittedMethod.call
  24  0.19% 91.07%  105859 342064 org.jruby.util.encoding.CharsetTranscoder$TranscoderEngine.encode
  25  0.15% 91.21%   83025 307026 org.jruby.runtime.DynamicScope.newDynamicScope
  26  0.11% 91.33%   62017 355165 java.nio.charset.CoderResult$Cache.get
  27  0.10% 91.43%   57078 306860 org.jruby.runtime.CompiledBlock19.yield
  28  0.08% 91.51%   45594 306286 org.jruby.RubyHash.allocFirst
  29  0.08% 91.59%   44221 308042 java.lang.StringCoding$StringDecoder.decode
  30  0.08% 91.67%   44178 308447 org.jruby.runtime.Helpers.constructObjectArray
  31  0.07% 91.73%   37472 315821 rubyjit$HTML::Tokenizer$$consume_quoted_regions_ec6beb527e53ece8eff0f455054756fe4d2710b71514204209$block_0$RUBY$__file__.call
  32  0.07% 91.80%   37215 306937 java.net.PlainSocketImpl.socketAvailable
  33  0.06% 91.86%   34238 306414 java.lang.Throwable.fillInStackTrace
  34  0.06% 91.92%   32825 310226 org.jruby.runtime.Block.yieldSpecific
  35  0.06% 91.98%   32634 305322 java.lang.System.identityHashCode
  36  0.06% 92.03%   32124 308720 org.jruby.runtime.CompiledBlock19.yieldSpecificInternal
  37  0.05% 92.09%   29359 311079 org.jruby.RubyModule.hasModuleInHierarchy
  38  0.05% 92.14%   29277 310772 org.jruby.runtime.callsite.CachingCallSite.callBlock
  39  0.05% 92.19%   28435 306847 java.net.PlainSocketImpl.socketAvailable
  40  0.05% 92.24%   28072 308231 org.jruby.RubyHash.internalGetEntry
  41  0.05% 92.29%   27885 309885 org.jruby.runtime.CompiledBlock19.yieldSpecific
  42  0.05% 92.34%   27825 311360 org.jruby.RubyModule$KindOf.isKindOf
  43  0.04% 92.38%   24675 305798 java.lang.System.identityHashCode
  44  0.04% 92.43%   24264 314317 java.lang.Class.getClassLoader0
  45  0.04% 92.47%   24248 316770 org.jruby.RubyKernel$INVOKER$s$0$0$loop.call
  46  0.04% 92.51%   23667 306918 org.jruby.runtime.CompiledBlock19.setupBlockArgs
  47  0.04% 92.55%   23217 307379 sun.nio.cs.ThreadLocalCoders$1.hasName
  48  0.04% 92.59%   21898 308458 org.jruby.internal.runtime.methods.JittedMethod.pre
  49  0.03% 92.63%   18715 306812 org.jruby.runtime.Block.yield
  50  0.03% 92.66%   18186 306650 java.util.concurrent.ConcurrentHashMap.get
  51  0.03% 92.69%   17927 310357 org.jruby.ast.executable.AbstractScript.__file__
  52  0.03% 92.72%   17746 311643 org.jruby.runtime.Helpers.prepareMethodMissingArgs
  53  0.03% 92.75%   17578 308249 org.jruby.RubyString.isComparableWith
  54  0.03% 92.78%   17097 307661 org.jruby.RubyRange.begLenInt
  55  0.03% 92.81%   16045 306659 org.jruby.RubyModule.searchMethodInner
  56  0.03% 92.84%   16044 305802 org.jruby.internal.runtime.methods.DynamicMethod.call
  57  0.03% 92.87%   16001 307638 org.jruby.ast.executable.AbstractScript.__file__
  58  0.03% 92.90%   15890 308882 org.jruby.RubyHash.internalGetEntry
  59  0.03% 92.93%   15426 315337 rubyjit.Time$$find_zone!_e398a10ba5788b1d05e554d4fe9482e46ce502881514204209.__file__
  60  0.03% 92.95%   15365 311030 org.jruby.RubyString.newAllocatedString
  61  0.03% 92.98%   15072 305214 java.lang.Throwable.getStackTraceElement
  62  0.03% 93.01%   15010 308493 sun.nio.cs.UTF_8$Encoder.encodeBufferLoop
  63  0.03% 93.03%   14642 310759 org.jruby.ast.executable.AbstractScript.__file__
  64  0.03% 93.06%   14504 308967 org.jruby.internal.runtime.methods.JittedMethod.call
  65  0.02% 93.08%   13829 308110 org.jruby.runtime.ThreadContext.getRubyClass
  66  0.02% 93.11%   13796 317632 org.jruby.ast.executable.RuntimeCache.getVariable
  67  0.02% 93.13%   13293 307008 org.jruby.runtime.CompiledBlock19.yield
  68  0.02% 93.16%   12807 307854 java.util.concurrent.ConcurrentHashMap.get
  69  0.02% 93.18%   12729 313512 org.jruby.runtime.Helpers.preOpAsgnWithOrAnd
  70  0.02% 93.20%   12725 308220 org.jruby.RubyModule.findImplementer
  71  0.02% 93.22%   12659 305110 java.lang.Throwable.fillInStackTrace
  72  0.02% 93.25%   12112 308924 sun.nio.ch.NativeThread.current
  73  0.02% 93.27%   11918 309336 org.jruby.Ruby.getCurrentContext
  74  0.02% 93.29%   11139 305684 java.lang.Object.hashCode
  75  0.02% 93.31%   10730 310770 rubyjit.HTML::Tokenizer$$consume_quoted_regions_ec6beb527e53ece8eff0f455054756fe4d2710b71514204209.block_0$RUBY$__file__
  76  0.02% 93.32%   10685 306741 org.jruby.runtime.Block.yield
  77  0.02% 93.34%   10542 312450 java.lang.Class.getClassLoader0
  78  0.02% 93.36%   10274 308282 org.jruby.runtime.Helpers.constructObjectArray
  79  0.02% 93.38%   10134 303788 java.lang.Throwable.fillInStackTrace
  80  0.02% 93.40%    9872 311033 java.lang.StringCoding$StringEncoder.encode
  81  0.02% 93.41%    9691 314373 org.jruby.util.ByteList.equal
  82  0.02% 93.43%    9324 320278 org.jruby.runtime.JavaInternalBlockBody.yield
  83  0.02% 93.45%    9283 305121 java.util.zip.ZipFile.getEntry
  84  0.02% 93.46%    9273 312281 org.jruby.runtime.ThreadContext.postYieldLight
  85  0.02% 93.48%    9131 308247 org.jruby.runtime.ThreadContext.preYieldSpecificBlock
  86  0.02% 93.50%    9128 311425 org.jruby.runtime.Helpers.constructRubyArray
  87  0.02% 93.51%    9027 331232 rubyjit$Journey::Formatter$$generate_8df394c2d624203b35ddcd3f65e2ca82eaaabe741514204209$block_0$RUBY$__file__.call
  88  0.02% 93.53%    8834 308390 java.lang.System.identityHashCode
  89  0.02% 93.54%    8808 308287 org.jruby.runtime.Helpers.argsCatToArgumentsCommon
  90  0.02% 93.56%    8635 313152 org.jruby.util.io.EncodingUtils.encCrStrBufCat
  91  0.02% 93.58%    8523 306757 sun.nio.cs.US_ASCII$Decoder.decodeLoop
  92  0.01% 93.59%    8378 304979 java.io.UnixFileSystem.getBooleanAttributes0
  93  0.01% 93.61%    8367 308920 org.jruby.ast.executable.RuntimeCache.cacheAndGet
  94  0.01% 93.62%    8301 315038 org.jruby.runtime.Helpers.constructSmallHash
  95  0.01% 93.63%    8237 310126 java.lang.Object.hashCode
  96  0.01% 93.65%    8057 308506 com.mysql.jdbc.ResultSetImpl.checkColumnBounds
  97  0.01% 93.66%    7843 315727 org.jruby.runtime.callsite.CachingCallSite.call
  98  0.01% 93.68%    7841 310765 org.jruby.runtime.Helpers.constructObjectArray
  99  0.01% 93.69%    7784 308215 org.jruby.RubyHash.internalGetEntry
 100  0.01% 93.70%    7744 310840 org.jruby.runtime.Block.yield
 101  0.01% 93.72%    7707 308633 org.joni.SearchAlgorithm$7.search
 102  0.01% 93.73%    7639 305153 sun.misc.Unsafe.unpark
 103  0.01% 93.75%    7557 309357 org.jruby.RubyString.splitCommon19
 104  0.01% 93.76%    7508 309788 java.util.concurrent.ConcurrentHashMap.get
 105  0.01% 93.77%    7422 312078 org.jruby.ast.executable.AbstractScript.__file__
 106  0.01% 93.79%    7345 310818 org.jruby.Ruby.execRecursiveOuter
 107  0.01% 93.80%    7238 308039 org.jruby.runtime.callsite.CachingCallSite.call
 108  0.01% 93.81%    7202 307414 com.mysql.jdbc.ResultSetImpl.checkColumnBounds
 109  0.01% 93.82%    7058 311283 org.jruby.runtime.Helpers.invokedynamic
 110  0.01% 93.84%    7045 311432 org.jruby.RubyClass.finvoke
 111  0.01% 93.85%    6947 308694 sun.nio.ch.FileDispatcherImpl.write0
 112  0.01% 93.86%    6904 310147 org.joni.StackMachine.pushAlt
 113  0.01% 93.87%    6720 308011 java.io.FileOutputStream.writeBytes
 114  0.01% 93.88%    6671 337551 rubyjit$TZInfo::DataTimezoneInfo$$period_for_utc_0e53647ab1bd78b2dba2fca2178ac5e53bea1a7d1514204209$block_0$RUBY$__file__.call
 115  0.01% 93.90%    6538 306114 java.lang.Throwable.fillInStackTrace
 116  0.01% 93.91%    6453 309054 java.lang.System.arraycopy
 117  0.01% 93.92%    6344 310468 org.jruby.runtime.CompiledBlock19.yield
 118  0.01% 93.93%    6340 309329 java.util.HashMap.hash
 119  0.01% 93.94%    6322 305254 java.io.UnixFileSystem.getBooleanAttributes0
 120  0.01% 93.95%    6271 310638 org.jruby.runtime.Helpers.constructRubyArray
 121  0.01% 93.96%    6259 311310 org.jruby.util.io.EncodingUtils.encCrStrBufCat
 122  0.01% 93.98%    6152 312943 org.jruby.internal.runtime.methods.JittedMethod.call
 123  0.01% 93.99%    6135 310294 org.jruby.runtime.Helpers.constructRubyArray
 124  0.01% 94.00%    6086 312786 org.jruby.runtime.Helpers.preOpAsgnWithOrAnd
 125  0.01% 94.01%    6046 311528 com.mysql.jdbc.ConnectionImpl.getCharacterSetMetadata
 126  0.01% 94.02%    6019 370955 org.jruby.Ruby.getCurrentContext
 127  0.01% 94.03%    5874 311004 org.jruby.RubyModule.getConstant
 128  0.01% 94.04%    5800 311926 org.jruby.runtime.callsite.CachingCallSite.call
 129  0.01% 94.05%    5725 305662 org.jruby.ast.executable.AbstractScript.__file__
 130  0.01% 94.06%    5692 308229 org.jruby.RubyString$INVOKER$i$0$0$to_s.call
 131  0.01% 94.07%    5643 325367 java.net.SocketOutputStream.socketWrite
 132  0.01% 94.08%    5640 312272 org.jruby.runtime.CompiledBlock19.yield
 133  0.01% 94.09%    5632 309484 org.jruby.runtime.CompiledBlock19.yield
CPU SAMPLES END
@chrisseaton
Copy link
Contributor

Sorry nobody has gotten back to you. Do you still have this problem with later versions of JRuby? I would expect that 1.9 mode would have higher load than 1.8, as with things like encoding the language is simply more complicated. JRuby uses the same optimisations for both 1.8 and 1.9, so there aren't extra optimisations to compensation, like there are in MRI 1.8 to 1.9.

@ocher
Copy link
Author

ocher commented Oct 17, 2014

Hi Chris,

Thank you for the response. I deployed again my app, this time using the latest JRuby (1.7.16) to a server with a very low load (very few users use this machine). Unfortunately, the problem is still there. And it looks like it's not related to just higher load related to more complicated String operations, and other Ruby 1.9 features. It's working fine, and then, after some time suddenly it's starting using 100% of one CPU core, and than in random point of times it's using even more cores, and it never ends.

Below are attached two images. One shows CPU usage from the last 24 hours after I switched to the latest JRuby. The other shows load from the last month and you can see what I described above (more cores getting used, until the app gets restarted). There is no such problem at all with 1.8 mode.

graphs_-__tree_mode
banners_and_alerts_i_graphs_-__tree_mode

@chrisseaton
Copy link
Contributor

Just checking I'm reading the graph right - you switch from 1.8 to 1.9 mode in the middle of the 24 graph you just posted?

@ocher
Copy link
Author

ocher commented Oct 17, 2014

No, I just updated JRuby to the latest version before the 24 hours graph starts, so the load was low, because app was freshly restarted. Both graphs show load in 1.9 mode. As you can see the problem is that suddenly, out of nowhere, after some time, load surges and JRuby uses 100% of CPU (one core). After more time also it may start using further cores (1 month graph). Nothing like this happens when the app uses 1.8 mode.

@chrisseaton
Copy link
Contributor

What size heap are you running with? Can you try doubling it and see if that makes a difference? Eg -J-Xmx2G. See if it takes longer to go crazy, if nothing else. Maybe it spends all of its time in GC after a certain point - that would explain using all the cores.

Sent from my iPhone

On 17 Oct 2014, at 14:09, Michal Ochman notifications@github.com wrote:

No, I just updated JRuby to the latest version before the 24 hours graph starts, so the load was low, because app was freshly restarted. Both graphs show load in 1.9 mode. As you can see the problem is that suddenly, out of nowhere, after some time, load surges and JRuby uses 100% of CPU (one core). After more time also it may start using further cores (1 month graph). Nothing like this happens when the app uses 1.8 mode.


Reply to this email directly or view it on GitHub.

@enebo
Copy link
Member

enebo commented Oct 17, 2014

@ocher I would also examine a few heap dumps to see if something obvious is being executed on running threads. If it is callMethod or something like that it is Ruby code perhaps going in a tight loop. If you see some nio select logic then some internal IO logic is going crazy. Even posting a typical set of stacks from a dump might help shed some light on this.

@ocher
Copy link
Author

ocher commented Oct 17, 2014

@chrisseaton I think that it's not a problem with GC. I've got a full GC log (you can check it yourself here: https://www.dropbox.com/s/b9oz1jyyzxa5nof/kirk_gc_jruby_1-7-16.log.gz?dl=0) and there aren't too many full GCs performed.

@enebo For now I can provide you -Xrunhprof:cpu=samples log file. As you will see in the file, there are many threads created by: site_target_ranking.rb:42 file. This line invokes HTTPClient#delete method. I had to change HTTPClient because of this bug: #1891, but as far as I remember it shouldn't be a source of the problem described in the current issue, because the high load was there even before I patched HTTPClient (here is the patch I'm using: https://gist.github.com/ocher/750f5628241dcf25a6fe)

@kares
Copy link
Member

kares commented May 23, 2017

interesting piece esp. since there's smt of the same at elastic/logstash#3989 "resolved" by avoiding encode.

wonder if it would manifest the same under JRuby 9K ... or if @ocher managed to get it working with 1.7.x ?

@kares
Copy link
Member

kares commented Mar 1, 2018

no feedback in a few months. if anyone lands here please try to provide detailed input against JRuby 9K

@kares kares closed this as completed Mar 1, 2018
@kares kares added this to the Won't Fix milestone Mar 1, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants