Coastal is very slow when invoked via commandline

[DonatoClun]

Hi guys,

I've been running coastal using the startup script in build/install/coastal/bin and I noticed that is much slower (>10x) than when executed via IDE (I'm using intellij).

Assertions -ea are disabled, the only difference that I've been able to identify is the classpath passed to java, and in fact if I modify the startup script and use the same classpath generated by intellij, it seems to work at normal speed.

Upon further investigation (sampling the execution using VisualVM), it appears that coastal is spending an extremely large amount of time in the method za.ac.sun.cs.coastal.instrument.InstrumentationClassManager.loadFromJar().

I reproduced the issue in a clean docker container, so it should not be related to the specific configuration of my machine.

Any idea or suggestion?

[DonatoClun]

I can confirm that the classpath has an enormous impact on the performance, possibly due to some bug in the handling of .jar files.

Here are two examples of classpath. The same analysis executed with the second one is >100x faster than with the first one.

Slow:

$APP_HOME/lib/coastal-0.0.3.jar
$APP_HOME/lib/commons-beanutils-1.9.3.jar
$APP_HOME/lib/commons-io-2.6.jar
$APP_HOME/lib/SVPABenchmark-0.0.1-CUSTOM.jar
$APP_HOME/lib/SVPAlib-1.0-CUSTOM.jar
$APP_HOME/lib/commons-lang3-3.4.jar
$APP_HOME/lib/log4j-core-2.10.0.jar
$APP_HOME/lib/log4j-api-2.10.0.jar
$APP_HOME/lib/asm-commons-7.2.jar
$APP_HOME/lib/asm-util-7.2.jar
$APP_HOME/lib/asm-analysis-7.2.jar
$APP_HOME/lib/asm-tree-7.2.jar
$APP_HOME/lib/asm-7.2.jar
$APP_HOME/lib/disruptor-3.4.2.jar
$APP_HOME/lib/commons-exec-1.3.jar
$APP_HOME/lib/commons-logging-1.2.jar
$APP_HOME/lib/guava-18.0.jar
$APP_HOME/lib/org.ow2.sat4j.core-2.3.4.jar

Fast:

/home/denny/Documents/research/coastal-learning/build/classes/java/examples
/home/denny/.m2/repository/org/apache/logging/log4j/log4j-api/2.10.0/log4j-api-2.10.0.jar
/home/denny/.m2/repository/commons-beanutils/commons-beanutils/1.9.3/commons-beanutils-1.9.3.jar
/home/denny/.m2/repository/com/google/guava/guava/18.0/guava-18.0.jar
/home/denny/.m2/repository/org/apache/commons/commons-lang3/3.4/commons-lang3-3.4.jar
/home/denny/.m2/repository/commons-collections/commons-collections/3.2.2/commons-collections-3.2.2.jar
/home/denny/.m2/repository/commons-logging/commons-logging/1.2/commons-logging-1.2.jar
/home/denny/.m2/repository/commons-io/commons-io/2.6/commons-io-2.6.jar
/home/denny/.m2/repository/jdd/jdd/1.0/jdd-1.0.jar
/home/denny/.m2/repository/org/apache/commons/commons-exec/1.3/commons-exec-1.3.jar
/home/denny/.m2/repository/org/apache/logging/log4j/log4j-core/2.10.0/log4j-core-2.10.0.jar
/home/denny/.m2/repository/cs/wisc/edu/SVPAlib/1.0-CUSTOM/SVPAlib-1.0-CUSTOM.jar
/home/denny/.m2/repository/org/ow2/sat4j/org.ow2.sat4j.core/2.3.4/org.ow2.sat4j.core-2.3.4.jar
/home/denny/.gradle/caches/modules-2/files-2.1/com.github.green-solver/green/0.2.0/e211154c4f6dd9818b62af7dca4ddec4fa5b9095/green-0.2.0.jar
/home/denny/.gradle/caches/modules-2/files-2.1/org.ow2.asm/asm-commons/7.2/ca2954e8d92a05bacc28ff465b25c70e0f512497/asm-commons-7.2.jar
/home/denny/.gradle/caches/modules-2/files-2.1/org.ow2.asm/asm-util/7.2/a3ae34e57fa8a4040e28247291d0cc3d6b8c7bcf/asm-util-7.2.jar
/home/denny/.gradle/caches/modules-2/files-2.1/org.ow2.asm/asm-analysis/7.2/b6e6abe057f23630113f4167c34bda7086691258/asm-analysis-7.2.jar
/home/denny/.gradle/caches/modules-2/files-2.1/org.ow2.asm/asm-tree/7.2/3a23cc36edaf8fc5a89cb100182758ccb5991487/asm-tree-7.2.jar
/home/denny/.gradle/caches/modules-2/files-2.1/org.ow2.asm/asm/7.2/fa637eb67eb7628c915d73762b681ae7ff0b9731/asm-7.2.jar
/home/denny/.gradle/caches/modules-2/files-2.1/com.lmax/disruptor/3.4.2/e2543a63086b4189fbe418d05d56633bc1a815f7/disruptor-3.4.2.jar
/home/denny/Documents/research/coastal-learning/build/classes/java/main

[DonatoClun]

The uninstrumented classes cache returns null either if loading that class form file was never attempted, or if it was attempted but failed. As a result every time coastal loads a class that cannot be loaded from file (so that has a null entry in the cache) the loadFile method is called again, even though we know it will return null. Pull request #45 is a quick and dirty solution.