Out of metaspace intermittently on Travis

[headius]

Recently a job for PR #6798 failed in the spec:ruby:fast:jit target with OutOfMemoryError: metaspace:

3)
Syslog.close sets the identity to nil ERROR
Java::JavaLang::OutOfMemoryError: Metaspace
java.lang.ClassLoader.defineClass1(Native Method)
java.lang.ClassLoader.defineClass(ClassLoader.java:763)
java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
java.net.URLClassLoader.defineClass(URLClassLoader.java:467)
java.net.URLClassLoader.access$100(URLClassLoader.java:73)
java.net.URLClassLoader$1.run(URLClassLoader.java:368)
java.net.URLClassLoader$1.run(URLClassLoader.java:362)
java.security.AccessController.doPrivileged(Native Method)
java.net.URLClassLoader.findClass(URLClassLoader.java:361)
java.lang.ClassLoader.loadClass(ClassLoader.java:424)
sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:335)
java.lang.ClassLoader.loadClass(ClassLoader.java:357)
org.jruby.ext.ffi.jffi.DefaultMethodFactory$BufferMarshaller.marshal(DefaultMethodFactory.java:661)
org.jruby.ext.ffi.jffi.BufferNativeInvoker.call(BufferNativeInvoker.java:139)
org.jruby.ext.ffi.jffi.NativeInvoker.call(NativeInvoker.java:71)
org.jruby.ext.ffi.jffi.DefaultMethod.call(DefaultMethod.java:106)
org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:226)
org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:222)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:235)
home.travis.build.jruby.jruby.lib.ruby.stdlib.syslog.invokeOther10:open(/home/travis/build/jruby/jruby/lib/ruby/stdlib/syslog.rb:99)

I have not seen this error before or since.

[headius]

It happened again after restarting the job:

https://app.travis-ci.com/github/jruby/jruby/jobs/535115751

This may be a regression from one of the two updated dependencies.

[headius]

I went ahead and merged #6798 since those changes did not seem to be related. We will see if this happens in the master CI builds and proceed from there.

[headius]

It did not happen after the merge of this and a subsequent merge of jruby-openssl update. We will continue to monitor. It may be environmental, or we may be just on the edge of metaspace and recent changes have pushed us closer to that edge.

[ahorek]

mem usage is much lower in dev mode, but I don't see anything useful in logs that could explain a leak.

after forced GC

retained objects

 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:        522874       45356528  [B (java.base@15.0.1)
   2:        325981       22899064  [Ljava.lang.Object; (java.base@15.0.1)
   3:        319016       10208512  java.util.concurrent.ConcurrentHashMap$Node (java.base@15.0.1)
   4:        314167       10053344  java.util.HashMap$Node (java.base@15.0.1)
   5:        371130        8907120  java.lang.String (java.base@15.0.1)
   6:         94409        7072056  [Ljava.util.HashMap$Node; (java.base@15.0.1)
   7:        132708        6369984  java.util.HashMap (java.base@15.0.1)
   8:        142759        5710360  org.jruby.util.ByteList
   9:         54189        5300080  [Ljava.util.concurrent.ConcurrentHashMap$Node; (java.base@15.0.1)
  10:        131911        5276440  org.jruby.runtime.ObjectSpace$WeakReferenceListNode
  11:        186119        5254640  [Lorg.jruby.dirgra.Edge;
  12:        199851        5202056  [Lorg.jruby.ir.operands.Operand;
  13:        210414        5049936  java.util.ArrayList (java.base@15.0.1)
  14:         70521        4513344  java.util.concurrent.ConcurrentHashMap (java.base@15.0.1)
  15:         38946        4191856  [I (java.base@15.0.1)
  16:        172449        4138776  org.jruby.ir.operands.TemporaryClosureVariable
  17:         56833        4091976  org.jruby.ir.instructions.specialized.OneOperandArgNoBlockCallInstr
  18:        101253        4050120  org.jruby.dirgra.Vertex
  19:         28992        3702168  java.lang.Class (java.base@15.0.1)
  20:        148321        3559704  org.jruby.dirgra.Edge
  21:        144716        3473184  org.jruby.ir.operands.Label
  22:        102275        3272800  org.jruby.ir.instructions.CopyInstr
  23:        101253        3240096  org.jruby.ir.representations.BasicBlock
  24:         43867        3158424  java.lang.reflect.Field (java.base@15.0.1)
  25:        193336        3093376  java.lang.Object (java.base@15.0.1)
  26:         40573        2921256  org.jruby.ir.instructions.specialized.ZeroOperandArgNoBlockCallInstr
  27:         66337        2653480  org.jruby.RubyString
  28:        101648        2439552  java.util.LinkedList$Node (java.base@15.0.1)
  29:         72504        2320128  java.lang.ref.WeakReference (java.base@15.0.1)
  30:         45311        2174928  java.lang.invoke.MemberName (java.base@15.0.1)
  31:         67737        2167584  org.jruby.runtime.callsite.MonomorphicCallSite

[headius]

I bumped it up to 768M on master and it made it through one run. We shall see.

[headius]

Have not seen an issue again for a while, across several new PRs. Perhaps we just started using enough metaspace in the spec:ruby:fast:jit run to hit the preset ceiling.