OS: Ubuntu 19.04
JVM: openjdk8
Kotlin: 1.3.70 (also observed on earlier kotlins)
Test running environment: IDEA 2019.3
I’ve observed some odd, long running memory creep in a production application that uses dynamic kotlin “script” to define rules on the fly, and frequent kotlin script compilation is one of the targets that has initially concerned me.
I’ve spent some time lookng for similar memory issues, and in most cases, the prevailing recommendation was to allow for the script engine to go out of scope, thus offering history and compilation artifacts for GC.
The following code, however, demonstrates what seems to me to be an acute problem.
package rules
import org.jetbrains.kotlin.cli.common.repl.KotlinJsr223JvmScriptEngineFactoryBase
import org.jetbrains.kotlin.cli.common.repl.ScriptArgsWithTypes
import org.jetbrains.kotlin.script.jsr223.KotlinJsr223JvmLocalScriptEngine
import org.jetbrains.kotlin.script.jsr223.KotlinStandardJsr223ScriptTemplate
import org.junit.Test
import java.io.File
import java.net.URLClassLoader
import javax.script.Bindings
import javax.script.ScriptContext
import javax.script.ScriptEngine
class RulePerformance {
private val generalScript = """
val x = 1
println("Hello ${'$'}x")
""".trimIndent()
@Test
fun `run rules repeatedly`() {
while(true) {
ENGINE_FACTORY.scriptEngine.eval(
generalScript
)
Thread.sleep(1500)
}
}
companion object {
private val ENGINE_FACTORY by lazy { ClasspathAwareScriptEngineFactory() }
private val ENGINE by lazy { ENGINE_FACTORY.scriptEngine }
}
class ClasspathAwareScriptEngineFactory : KotlinJsr223JvmScriptEngineFactoryBase() {
override fun getScriptEngine(): ScriptEngine {
val searchClassLoader = Thread.currentThread().contextClassLoader as URLClassLoader
val classpath = searchClassLoader.urLs.map { File(it.file) }
return KotlinJsr223JvmLocalScriptEngine(
this,
classpath,
KotlinStandardJsr223ScriptTemplate::class.qualifiedName!!,
{ ctx, types ->
ScriptArgsWithTypes(arrayOf(ctx.getBindings(ScriptContext.ENGINE_SCOPE)), types ?: emptyArray())
},
arrayOf(Bindings::class))
}
}
}
Nothing that interesting, just a simple kotlin script with no binding variable inside an endless loop with the creation of a new script engine on each loop.
Interesting Point #1
This is what shows up in “non heap – Memory Pool Code Cache”
this mirrors what I’ve seen in production, a slow, but inexorable creep up in something called code cache. No explicit calls to GC help, although given that this is non heap, this is not surprising.
Interesting Point #2
In production, this memory creep becomes a problem after 10 days or so. Locally, however,
the program eventually crashed after a mere 1.5 hours, slightly unusually…
ERROR: Exception while analyzing expression at (2,1) in /Line_1.kts
org.jetbrains.kotlin.utils.KotlinExceptionWithAttachments: Exception while analyzing expression at (2,1) in /Line_1.kts
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.logOrThrowException(ExpressionTypingVisitorDispatcher.java:234)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.lambda$getTypeInfo$0(ExpressionTypingVisitorDispatcher.java:212)
at org.jetbrains.kotlin.util.PerformanceCounter.time(PerformanceCounter.kt:91)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.getTypeInfo(ExpressionTypingVisitorDispatcher.java:162)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.getTypeInfo(ExpressionTypingVisitorDispatcher.java:133)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorForStatements.visitExpression(ExpressionTypingVisitorForStatements.java:373)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorForStatements.visitExpression(ExpressionTypingVisitorForStatements.java:62)
at org.jetbrains.kotlin.psi.KtVisitor.visitReferenceExpression(KtVisitor.java:198)
at org.jetbrains.kotlin.psi.KtVisitor.visitCallExpression(KtVisitor.java:278)
at org.jetbrains.kotlin.psi.KtCallExpression.accept(KtCallExpression.java:35)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.lambda$getTypeInfo$0(ExpressionTypingVisitorDispatcher.java:173)
at org.jetbrains.kotlin.util.PerformanceCounter.time(PerformanceCounter.kt:91)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.getTypeInfo(ExpressionTypingVisitorDispatcher.java:162)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingVisitorDispatcher.getTypeInfo(ExpressionTypingVisitorDispatcher.java:146)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingServices.getTypeInfo(ExpressionTypingServices.java:118)
at org.jetbrains.kotlin.types.expressions.ExpressionTypingServices.getTypeInfo(ExpressionTypingServices.java:93)
at org.jetbrains.kotlin.resolve.BodyResolver.resolveAnonymousInitializer(BodyResolver.java:665)
at org.jetbrains.kotlin.resolve.BodyResolver.resolveAnonymousInitializers(BodyResolver.java:651)
at org.jetbrains.kotlin.resolve.BodyResolver.resolveBehaviorDeclarationBodies(BodyResolver.java:120)
at org.jetbrains.kotlin.resolve.BodyResolver.resolveBodies(BodyResolver.java:243)
at org.jetbrains.kotlin.resolve.LazyTopDownAnalyzer.analyzeDeclarations(LazyTopDownAnalyzer.kt:225)
at org.jetbrains.kotlin.resolve.LazyTopDownAnalyzer.analyzeDeclarations$default(LazyTopDownAnalyzer.kt:60)
at org.jetbrains.kotlin.scripting.repl.ReplCodeAnalyzer.doAnalyze(ReplCodeAnalyzer.kt:109)
at org.jetbrains.kotlin.scripting.repl.ReplCodeAnalyzer.analyzeReplLine(ReplCodeAnalyzer.kt:93)
at org.jetbrains.kotlin.scripting.repl.GenericReplCompiler.compile(GenericReplCompiler.kt:74)
at org.jetbrains.kotlin.cli.common.repl.GenericReplCompilingEvaluatorBase.compileAndEval(GenericReplCompilingEvaluator.kt:38)
at org.jetbrains.kotlin.cli.common.repl.ReplAtomicEvalAction$DefaultImpls.compileAndEval$default(ReplApi.kt:175)
at org.jetbrains.kotlin.cli.common.repl.KotlinJsr223JvmScriptEngineBase.compileAndEval(KotlinJsr223JvmScriptEngineBase.kt:61)
at org.jetbrains.kotlin.cli.common.repl.KotlinJsr223JvmScriptEngineBase.eval(KotlinJsr223JvmScriptEngineBase.kt:31)
at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
at rules.RulePerformance.run rules repeatedly(RulePerformance.kt:16)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:230)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:58)
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
at org.jetbrains.kotlin.metadata.ProtoBuf$Type$1.parsePartialFrom(ProtoBuf.java:4977)
at org.jetbrains.kotlin.metadata.ProtoBuf$Type$1.parsePartialFrom(ProtoBuf.java:4972)
at org.jetbrains.kotlin.protobuf.CodedInputStream.readMessage(CodedInputStream.java:495)
at org.jetbrains.kotlin.metadata.ProtoBuf$ValueParameter.<init>(ProtoBuf.java:18110)
at org.jetbrains.kotlin.metadata.ProtoBuf$ValueParameter.<init>(ProtoBuf.java:18047)
at org.jetbrains.kotlin.metadata.ProtoBuf$ValueParameter$1.parsePartialFrom(ProtoBuf.java:18165)
at org.jetbrains.kotlin.metadata.ProtoBuf$ValueParameter$1.parsePartialFrom(ProtoBuf.java:18160)
at org.jetbrains.kotlin.protobuf.CodedInputStream.readMessage(CodedInputStream.java:495)
at org.jetbrains.kotlin.metadata.ProtoBuf$Function.<init>(ProtoBuf.java:14410)
at org.jetbrains.kotlin.metadata.ProtoBuf$Function.<init>(ProtoBuf.java:14313)
at org.jetbrains.kotlin.metadata.ProtoBuf$Function$1.parsePartialFrom(ProtoBuf.java:14508)
at org.jetbrains.kotlin.metadata.ProtoBuf$Function$1.parsePartialFrom(ProtoBuf.java:14503)
at org.jetbrains.kotlin.protobuf.CodedInputStream.readMessage(CodedInputStream.java:495)
at org.jetbrains.kotlin.metadata.ProtoBuf$Package.<init>(ProtoBuf.java:11611)
at org.jetbrains.kotlin.metadata.ProtoBuf$Package.<init>(ProtoBuf.java:11558)
at org.jetbrains.kotlin.metadata.ProtoBuf$Package$1.parsePartialFrom(ProtoBuf.java:11689)
at org.jetbrains.kotlin.metadata.ProtoBuf$Package$1.parsePartialFrom(ProtoBuf.java:11684)
at org.jetbrains.kotlin.protobuf.AbstractParser.parsePartialFrom(AbstractParser.java:192)
at org.jetbrains.kotlin.protobuf.AbstractParser.parseFrom(AbstractParser.java:209)
at org.jetbrains.kotlin.protobuf.AbstractParser.parseFrom(AbstractParser.java:49)
at org.jetbrains.kotlin.metadata.ProtoBuf$Package.parseFrom(ProtoBuf.java:11972)
at org.jetbrains.kotlin.metadata.jvm.deserialization.JvmProtoBufUtil.readPackageDataFrom(JvmProtoBufUtil.kt:40)
at org.jetbrains.kotlin.metadata.jvm.deserialization.JvmProtoBufUtil.readPackageDataFrom(JvmProtoBufUtil.kt:35)
at org.jetbrains.kotlin.load.kotlin.DeserializedDescriptorResolver.createKotlinPackagePartScope(DeserializedDescriptorResolver.kt:63)
at org.jetbrains.kotlin.load.java.lazy.descriptors.JvmPackageScope$kotlinScopes$2.invoke(JvmPackageScope.kt:45)
at org.jetbrains.kotlin.load.java.lazy.descriptors.JvmPackageScope$kotlinScopes$2.invoke(JvmPackageScope.kt:36)
at org.jetbrains.kotlin.storage.LockBasedStorageManager$LockBasedLazyValue.invoke(LockBasedStorageManager.java:346)
at org.jetbrains.kotlin.storage.LockBasedStorageManager$LockBasedNotNullLazyValue.invoke(LockBasedStorageManager.java:402)
at org.jetbrains.kotlin.storage.StorageKt.getValue(storage.kt:42)
at org.jetbrains.kotlin.load.java.lazy.descriptors.JvmPackageScope.getKotlinScopes(JvmPackageScope.kt)
at org.jetbrains.kotlin.load.java.lazy.descriptors.JvmPackageScope.getClassifierNames(JvmPackageScope.kt:81)
at org.jetbrains.kotlin.resolve.scopes.MemberScopeKt.flatMapClassifierNamesOrNull(MemberScope.kt:62)
This bothers me, and makes me worry about the viability of building any application around the regular invocation of the embeddable compiler. Any help would be gratefully received.