Я портирую код в своем приложении от Rhino до Nashorn (в основном, чтобы не отставать от современной моды, а не от недостатка функциональности в Rhino), и я получаю очень плохую производительность с Nashorn.Nashorn в 3 раза медленнее Rhino, как оптимизировать?
Мое приложение имеет набор файлов LESS, скомпилированных во время выполнения (контент является динамическим и не может быть предварительно скомпилирован). Это делается один раз при запуске и каждый раз, когда изменения обнаруживаются во время выполнения.
Rhino дает довольно стабильную производительность около 4-5 секунд (сценарий JS загружается с максимальной оптимизацией Rhino).
Nashorn дает некоторые абсолютно странные результаты - около 15-17 секунд, но после 10-й итерации и около 10 минут времени производительность становится довольно хорошей - около 3 секунд. Но из-за начальной медленности мое приложение с Nashorn начинается в общем примерно на 30 секунд дольше, чем с Rhino (есть и другие файлы LESS, скомпилированные).
Так что вопрос:
Что я могу сделать для обеспечения Nashorn выполнять самую высокую оптимизацию сценария сразу, а не после того, как 10-20th итерации?
Ниже тайминги из файла журнала
2015-11-11 09:29:16,419 compile(less, styles.less) = 15179ms
--------------------------------------------------------------
15.179 % compile (styles.less)
--------------------------------------------------------------
13.940 91.8% less-rhino-ji.js lessFileToCss(styles.less)
1.227 8.0% YUICompressor minify(styles.less)
2015-11-11 09:30:12,900 compile(less, styles.less) = 13274ms
--------------------------------------------------------------
13.274 % compile (styles.less)
--------------------------------------------------------------
11.605 87.4% less-rhino-ji.js lessFileToCss(styles.less)
1.664 12.5% YUICompressor minify(styles.less)
2015-11-11 09:30:43,705 compile(less, styles.less) = 6906ms
--------------------------------------------------------------
6.906 % compile (styles.less)
--------------------------------------------------------------
5.695 82.4% less-rhino-ji.js lessFileToCss(styles.less)
1.205 17.4% YUICompressor minify(styles.less)
2015-11-11 09:31:09,194 compile(less, styles.less) = 6041ms
--------------------------------------------------------------
6.041 % compile (styles.less)
--------------------------------------------------------------
4.622 76.5% less-rhino-ji.js lessFileToCss(styles.less)
1.412 23.3% YUICompressor minify(styles.less)
2015-11-11 09:31:49,558 compile(less, styles.less) = 7619ms
--------------------------------------------------------------
7.619 % compile (styles.less)
--------------------------------------------------------------
3.056 40.1% less-rhino-ji.js lessFileToCss(styles.less)
4.555 59.7% YUICompressor minify(styles.less)
2015-11-11 09:36:25,586 compile(less, styles.less) = 5226ms
--------------------------------------------------------------
5.226 % compile (styles.less)
--------------------------------------------------------------
4.104 78.5% less-rhino-ji.js lessFileToCss(styles.less)
1.116 21.3% YUICompressor minify(styles.less)
2015-11-11 09:36:40,745 compile(less, styles.less) = 3839ms
--------------------------------------------------------------
3.839 % compile (styles.less)
--------------------------------------------------------------
2.664 69.3% less-rhino-ji.js lessFileToCss(styles.less)
1.169 30.4% YUICompressor minify(styles.less)
2015-11-11 09:37:02,876 compile(less, styles.less) = 3074ms
--------------------------------------------------------------
3.074 % compile (styles.less)
--------------------------------------------------------------
1.948 63.3% less-rhino-ji.js lessFileToCss(styles.less)
1.120 36.4% YUICompressor minify(styles.less)
2015-11-11 09:37:29,140 compile(less, styles.less) = 4773ms
--------------------------------------------------------------
4.773 % compile (styles.less)
--------------------------------------------------------------
3.682 77.1% less-rhino-ji.js lessFileToCss(styles.less)
1.085 22.7% YUICompressor minify(styles.less)
2015-11-11 09:37:51,768 compile(less, styles.less) = 2761ms
--------------------------------------------------------------
2.761 % compile (styles.less)
--------------------------------------------------------------
1.661 60.1% less-rhino-ji.js lessFileToCss(styles.less)
1.094 39.6% YUICompressor minify(styles.less)
2015-11-11 09:38:19,053 compile(less, styles.less) = 2743ms
--------------------------------------------------------------
2.743 % compile (styles.less)
--------------------------------------------------------------
1.639 59.7% less-rhino-ji.js lessFileToCss(styles.less)
1.098 40.0% YUICompressor minify(styles.less)
Update: По рекомендации от Olipro я начал процесс со следующими аргументами:
java -XX:+UnlockDiagnosticVMOptions -XX:+PrintCompilation ...
Результат является не совсем понятно - имена класса es, генерируемые Nashorn, похожи на jdk.nashorn.internal.scripts.Script$Recompilation$438$121292A$\^eval\_::L:3187$toCSS
, однако только по имени метода я вижу, что во время самой длинной компиляции файла CSS (4.4 секунды) в этом тестовом прогоне метод toCSS()
был перекомпилирован 5 раз и кажется, что 2 фоновых потока составляли разные версии одного и того же метода параллельно (немного странно для меня) - скорее всего, это действительно основная причина плохой производительности.
Тем не менее - ни намек, как улучшить производительность при запуске :(
строки из журнала (1st column = мс от начала Jvm):
11100 5677 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes)
11119 5682 jdk.nas...tion$446$150019A$\^eval\_::L:4147$toCSS (137 bytes)
11377 5677 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes) made not entrant
11507 5677 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes) made zombie
11932 5798 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes)
13381 5798 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes) made not entrant
14272 5798 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes) made zombie
14778 5682 jdk.nas...tion$446$150019A$\^eval\_::L:4147$toCSS (137 bytes) made not entrant
14860 6049 jdk.nas...tion$438$121292A$\^eval\_::L:3187$toCSS (103 bytes)
14890 6056 jdk.nas...tion$446$150019A$\^eval\_::L:4147$toCSS (137 bytes)
15019 5682 jdk.nas...tion$446$150019A$\^eval\_::L:4147$toCSS (137 bytes) made zombie
15223 6162 jdk.nas...tion$457$121460$\^eval\_::L:3187$toCSS$isEmpty (31 bytes)
Я попытался использовать '-Xcomp' - конечный результат значительно хуже.Общее время запуска увеличилось с 1:40 минут до 15:30. Итак, не уверен, что происходит в JVM за кулисами, но '-Xcomp' ничего не оптимизирует в моем случае. –
Правильно, '-Xcomp' приводит к тому, что JVM компилирует * все * в собственный машинный код и поэтому не рекомендуется. Я бы предложил просмотреть варианты здесь: https://docs.oracle.com/javase/8/docs/technotes/tools/windows/java.html#BABDDFII и включить регистрацию активности компиляции, чтобы вы могли получить представление о том, как Java ускоряет процесс. – Olipro