[2025-12-16T08:45:34.583Z] Running test renaissance-als_0 ... [2025-12-16T08:45:34.583Z] =============================================== [2025-12-16T08:45:34.920Z] renaissance-als_0 Start Time: Tue Dec 16 08:45:34 2025 Epoch Time (ms): 1765874734619 [2025-12-16T08:45:34.920Z] variation: NoOptions [2025-12-16T08:45:34.920Z] JVM_OPTIONS: [2025-12-16T08:45:34.920Z] { \ [2025-12-16T08:45:34.920Z] echo ""; echo "TEST SETUP:"; \ [2025-12-16T08:45:34.920Z] echo "Nothing to be done for setup."; \ [2025-12-16T08:45:34.920Z] mkdir -p "C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/\\TKG\\output_17658743907010\\renaissance-als_0"; \ [2025-12-16T08:45:34.920Z] cd "C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/\\TKG\\output_17658743907010\\renaissance-als_0"; \ [2025-12-16T08:45:34.920Z] echo ""; echo "TESTING:"; \ [2025-12-16T08:45:34.920Z] "c:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/jdkbinary/j2sdk-image\\bin\\java" --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.base/java.util.concurrent=ALL-UNNAMED --add-opens java.base/java.nio=ALL-UNNAMED --add-opens java.base/sun.nio.ch=ALL-UNNAMED --add-opens java.base/java.lang.invoke=ALL-UNNAMED -jar "C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests///..//jvmtest\\perf\\renaissance\\renaissance.jar" --json ""C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/\\TKG\\output_17658743907010\\renaissance-als_0"\\als.json" als; \ [2025-12-16T08:45:34.920Z] if [ $? -eq 0 ]; then echo "-----------------------------------"; echo "renaissance-als_0""_PASSED"; echo "-----------------------------------"; cd C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/; rm -f -r "C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/\\TKG\\output_17658743907010\\renaissance-als_0"; else echo "-----------------------------------"; echo "renaissance-als_0""_FAILED"; echo "-----------------------------------"; fi; \ [2025-12-16T08:45:34.920Z] echo ""; echo "TEST TEARDOWN:"; \ [2025-12-16T08:45:34.920Z] echo "Nothing to be done for teardown."; \ [2025-12-16T08:45:34.920Z] } 2>&1 | tee -a "C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/\\TKG\\output_17658743907010\\TestTargetResult"; [2025-12-16T08:45:35.272Z] [2025-12-16T08:45:35.272Z] TEST SETUP: [2025-12-16T08:45:35.272Z] Nothing to be done for setup. [2025-12-16T08:45:35.272Z] [2025-12-16T08:45:35.272Z] TESTING: [2025-12-16T08:45:36.039Z] WARNING: A terminally deprecated method in sun.misc.Unsafe has been called [2025-12-16T08:45:36.039Z] WARNING: sun.misc.Unsafe::objectFieldOffset has been called by scala.runtime.LazyVals$ (file:/C:/jenkins/workspace/Test_openjdk25_hs_extended.perf_x86-64_windows/aqa-tests/TKG/output_17658743907010/renaissance-als_0/launcher-084535-16761014518785641774/renaissance-harness_3/lib/scala3-library_3-3.3.4.jar) [2025-12-16T08:45:36.039Z] WARNING: Please consider reporting this to the maintainers of class scala.runtime.LazyVals$ [2025-12-16T08:45:36.039Z] WARNING: sun.misc.Unsafe::objectFieldOffset will be removed in a future release [2025-12-16T08:45:55.701Z] NOTE: 'als' benchmark uses Spark local executor with 2 (out of 2) threads. [2025-12-16T08:45:58.725Z] ====== als (apache-spark) [default], iteration 0 started ====== [2025-12-16T08:45:58.725Z] GC before operation: completed in 64.334 ms, heap usage 53.500 MB -> 35.416 MB. [2025-12-16T08:46:49.711Z] ====== als (apache-spark) [default], iteration 0 completed (49868.939 ms) ====== [2025-12-16T08:46:49.711Z] ====== als (apache-spark) [default], iteration 1 started ====== [2025-12-16T08:46:49.711Z] GC before operation: completed in 243.013 ms, heap usage 231.675 MB -> 61.910 MB. [2025-12-16T08:47:18.287Z] ====== als (apache-spark) [default], iteration 1 completed (28071.309 ms) ====== [2025-12-16T08:47:18.287Z] ====== als (apache-spark) [default], iteration 2 started ====== [2025-12-16T08:47:18.788Z] GC before operation: completed in 324.358 ms, heap usage 226.835 MB -> 62.841 MB. [2025-12-16T08:47:53.552Z] ====== als (apache-spark) [default], iteration 2 completed (29910.063 ms) ====== [2025-12-16T08:47:53.552Z] ====== als (apache-spark) [default], iteration 3 started ====== [2025-12-16T08:47:53.552Z] GC before operation: completed in 131.856 ms, heap usage 225.567 MB -> 63.460 MB. [2025-12-16T08:48:20.099Z] ====== als (apache-spark) [default], iteration 3 completed (28441.401 ms) ====== [2025-12-16T08:48:20.099Z] ====== als (apache-spark) [default], iteration 4 started ====== [2025-12-16T08:48:20.099Z] GC before operation: completed in 135.597 ms, heap usage 247.617 MB -> 64.019 MB. [2025-12-16T08:48:49.182Z] ====== als (apache-spark) [default], iteration 4 completed (28183.461 ms) ====== [2025-12-16T08:48:49.182Z] ====== als (apache-spark) [default], iteration 5 started ====== [2025-12-16T08:48:49.182Z] GC before operation: completed in 139.525 ms, heap usage 213.216 MB -> 64.884 MB. [2025-12-16T08:49:18.795Z] ====== als (apache-spark) [default], iteration 5 completed (28760.730 ms) ====== [2025-12-16T08:49:18.795Z] ====== als (apache-spark) [default], iteration 6 started ====== [2025-12-16T08:49:18.795Z] GC before operation: completed in 142.610 ms, heap usage 137.238 MB -> 65.053 MB. [2025-12-16T08:49:48.219Z] ====== als (apache-spark) [default], iteration 6 completed (27440.476 ms) ====== [2025-12-16T08:49:48.219Z] ====== als (apache-spark) [default], iteration 7 started ====== [2025-12-16T08:49:48.219Z] GC before operation: completed in 1258.083 ms, heap usage 450.077 MB -> 65.978 MB. [2025-12-16T08:50:13.098Z] ====== als (apache-spark) [default], iteration 7 completed (27750.146 ms) ====== [2025-12-16T08:50:13.098Z] ====== als (apache-spark) [default], iteration 8 started ====== [2025-12-16T08:50:13.710Z] GC before operation: completed in 169.563 ms, heap usage 103.178 MB -> 66.497 MB. [2025-12-16T08:50:43.440Z] ====== als (apache-spark) [default], iteration 8 completed (28208.482 ms) ====== [2025-12-16T08:50:43.440Z] ====== als (apache-spark) [default], iteration 9 started ====== [2025-12-16T08:50:43.440Z] GC before operation: completed in 168.198 ms, heap usage 475.070 MB -> 67.042 MB. [2025-12-16T08:51:12.270Z] ====== als (apache-spark) [default], iteration 9 completed (27453.045 ms) ====== [2025-12-16T08:51:12.270Z] ====== als (apache-spark) [default], iteration 10 started ====== [2025-12-16T08:51:12.270Z] GC before operation: completed in 153.562 ms, heap usage 101.746 MB -> 66.402 MB. [2025-12-16T08:51:40.590Z] ====== als (apache-spark) [default], iteration 10 completed (27360.424 ms) ====== [2025-12-16T08:51:40.590Z] ====== als (apache-spark) [default], iteration 11 started ====== [2025-12-16T08:51:40.590Z] GC before operation: completed in 135.376 ms, heap usage 168.507 MB -> 67.159 MB. [2025-12-16T08:52:09.820Z] ====== als (apache-spark) [default], iteration 11 completed (27989.023 ms) ====== [2025-12-16T08:52:09.820Z] ====== als (apache-spark) [default], iteration 12 started ====== [2025-12-16T08:52:09.820Z] GC before operation: completed in 148.341 ms, heap usage 119.544 MB -> 67.516 MB. [2025-12-16T08:52:37.823Z] ====== als (apache-spark) [default], iteration 12 completed (27755.585 ms) ====== [2025-12-16T08:52:37.823Z] ====== als (apache-spark) [default], iteration 13 started ====== [2025-12-16T08:52:37.823Z] GC before operation: completed in 141.830 ms, heap usage 470.746 MB -> 68.137 MB. [2025-12-16T08:53:06.150Z] ====== als (apache-spark) [default], iteration 13 completed (27702.319 ms) ====== [2025-12-16T08:53:06.150Z] ====== als (apache-spark) [default], iteration 14 started ====== [2025-12-16T08:53:06.150Z] GC before operation: completed in 142.706 ms, heap usage 192.131 MB -> 67.951 MB. [2025-12-16T08:53:34.992Z] ====== als (apache-spark) [default], iteration 14 completed (28201.379 ms) ====== [2025-12-16T08:53:34.992Z] ====== als (apache-spark) [default], iteration 15 started ====== [2025-12-16T08:53:34.992Z] GC before operation: completed in 142.184 ms, heap usage 198.967 MB -> 68.283 MB. [2025-12-16T08:53:59.551Z] ====== als (apache-spark) [default], iteration 15 completed (27070.082 ms) ====== [2025-12-16T08:53:59.551Z] ====== als (apache-spark) [default], iteration 16 started ====== [2025-12-16T08:53:59.551Z] GC before operation: completed in 196.856 ms, heap usage 430.640 MB -> 68.856 MB. [2025-12-16T08:54:29.029Z] ====== als (apache-spark) [default], iteration 16 completed (27350.695 ms) ====== [2025-12-16T08:54:29.029Z] ====== als (apache-spark) [default], iteration 17 started ====== [2025-12-16T08:54:29.029Z] GC before operation: completed in 133.912 ms, heap usage 372.547 MB -> 68.841 MB. [2025-12-16T08:54:54.465Z] ====== als (apache-spark) [default], iteration 17 completed (27303.953 ms) ====== [2025-12-16T08:54:54.465Z] ====== als (apache-spark) [default], iteration 18 started ====== [2025-12-16T08:54:55.481Z] GC before operation: completed in 146.360 ms, heap usage 359.085 MB -> 69.125 MB. [2025-12-16T08:55:24.419Z] ====== als (apache-spark) [default], iteration 18 completed (27470.270 ms) ====== [2025-12-16T08:55:24.419Z] ====== als (apache-spark) [default], iteration 19 started ====== [2025-12-16T08:55:24.419Z] GC before operation: completed in 136.584 ms, heap usage 444.363 MB -> 69.636 MB. [2025-12-16T08:55:52.753Z] ====== als (apache-spark) [default], iteration 19 completed (28542.765 ms) ====== [2025-12-16T08:55:52.753Z] ====== als (apache-spark) [default], iteration 20 started ====== [2025-12-16T08:55:52.753Z] GC before operation: completed in 150.550 ms, heap usage 500.752 MB -> 69.844 MB. [2025-12-16T08:56:21.179Z] ====== als (apache-spark) [default], iteration 20 completed (27877.854 ms) ====== [2025-12-16T08:56:21.179Z] ====== als (apache-spark) [default], iteration 21 started ====== [2025-12-16T08:56:21.179Z] GC before operation: completed in 151.331 ms, heap usage 472.317 MB -> 70.105 MB. [2025-12-16T08:56:49.702Z] ====== als (apache-spark) [default], iteration 21 completed (27854.389 ms) ====== [2025-12-16T08:56:49.702Z] ====== als (apache-spark) [default], iteration 22 started ====== [2025-12-16T08:56:49.702Z] GC before operation: completed in 130.785 ms, heap usage 287.981 MB -> 70.065 MB. [2025-12-16T08:57:18.411Z] ====== als (apache-spark) [default], iteration 22 completed (28031.854 ms) ====== [2025-12-16T08:57:18.411Z] ====== als (apache-spark) [default], iteration 23 started ====== [2025-12-16T08:57:18.411Z] GC before operation: completed in 216.795 ms, heap usage 399.114 MB -> 70.413 MB. [2025-12-16T08:57:47.188Z] ====== als (apache-spark) [default], iteration 23 completed (27993.163 ms) ====== [2025-12-16T08:57:47.188Z] ====== als (apache-spark) [default], iteration 24 started ====== [2025-12-16T08:57:47.188Z] GC before operation: completed in 131.698 ms, heap usage 386.839 MB -> 70.749 MB. [2025-12-16T08:58:15.873Z] ====== als (apache-spark) [default], iteration 24 completed (28294.376 ms) ====== [2025-12-16T08:58:15.873Z] ====== als (apache-spark) [default], iteration 25 started ====== [2025-12-16T08:58:15.873Z] GC before operation: completed in 132.715 ms, heap usage 374.341 MB -> 70.988 MB. [2025-12-16T08:58:44.443Z] ====== als (apache-spark) [default], iteration 25 completed (27811.159 ms) ====== [2025-12-16T08:58:44.443Z] ====== als (apache-spark) [default], iteration 26 started ====== [2025-12-16T08:58:44.443Z] GC before operation: completed in 150.218 ms, heap usage 374.942 MB -> 71.198 MB. [2025-12-16T08:59:12.907Z] ====== als (apache-spark) [default], iteration 26 completed (27803.078 ms) ====== [2025-12-16T08:59:12.907Z] ====== als (apache-spark) [default], iteration 27 started ====== [2025-12-16T08:59:12.907Z] GC before operation: completed in 135.952 ms, heap usage 474.932 MB -> 71.714 MB. [2025-12-16T08:59:41.178Z] ====== als (apache-spark) [default], iteration 27 completed (28681.184 ms) ====== [2025-12-16T08:59:41.178Z] ====== als (apache-spark) [default], iteration 28 started ====== [2025-12-16T08:59:41.178Z] GC before operation: completed in 134.930 ms, heap usage 377.327 MB -> 71.719 MB. [2025-12-16T09:00:09.660Z] ====== als (apache-spark) [default], iteration 28 completed (27689.012 ms) ====== [2025-12-16T09:00:09.660Z] ====== als (apache-spark) [default], iteration 29 started ====== [2025-12-16T09:00:09.660Z] GC before operation: completed in 135.333 ms, heap usage 253.305 MB -> 71.414 MB. [2025-12-16T09:00:34.241Z] ====== als (apache-spark) [default], iteration 29 completed (27113.674 ms) ====== [2025-12-16T09:00:34.241Z] 09:00:34.089 WARN [Thread-1] org.renaissance.core - Error deleting scratch directory C:\jenkins\workspace\Test_openjdk25_hs_extended.perf_x86-64_windows\aqa-tests\TKG\output_17658743907010\renaissance-als_0\harness-084535-6161284493909155195: harness-084535-6161284493909155195\apache-spark\als\hadoop\bin\hadoop.dll [2025-12-16T09:00:34.241Z] [2025-12-16T09:00:33.972+0000] org.renaissance.core (org.renaissance.core.DirUtils lambda$createScratchDirectory$1) [2025-12-16T09:00:34.241Z] WARNING: Error deleting scratch directory C:\jenkins\workspace\Test_openjdk25_hs_extended.perf_x86-64_windows\aqa-tests\TKG\output_17658743907010\renaissance-als_0\harness-084535-6161284493909155195: harness-084535-6161284493909155195\apache-spark\als\hadoop\bin\hadoop.dll [2025-12-16T09:00:34.241Z] [2025-12-16T09:00:34.104+0000] org.renaissance.core (org.renaissance.core.DirUtils lambda$createScratchDirectory$1) [2025-12-16T09:00:34.241Z] WAR09:00:34.106 WARN [Thread-0] org.renaissance.core - Error deleting scratch directory C:\jenkins\workspace\Test_openjdk25_hs_extended.perf_x86-64_windows\aqa-tests\TKG\output_17658743907010\renaissance-als_0\launcher-084535-16761014518785641774: launcher-084535-16761014518785641774\renaissance-harness_3\lib\renaissance-harness_3-0.16.0.jar: The process cannot access the file because it is being used by another process [2025-12-16T09:00:34.241Z] NING: Error deleting scratch directory C:\jenkins\workspace\Test_openjdk25_hs_extended.perf_x86-64_windows\aqa-tests\TKG\output_17658743907010\renaissance-als_0\launcher-084535-16761014518785641774: launcher-084535-16761014518785641774\renaissance-harness_3\lib\renaissance-harness_3-0.16.0.jar: The process cannot access the file because it is being used by another process [2025-12-16T09:00:34.576Z] ----------------------------------- [2025-12-16T09:00:34.576Z] renaissance-als_0_PASSED [2025-12-16T09:00:34.576Z] ----------------------------------- [2025-12-16T09:00:34.576Z] [2025-12-16T09:00:34.576Z] TEST TEARDOWN: [2025-12-16T09:00:34.576Z] Nothing to be done for teardown. [2025-12-16T09:00:34.576Z] renaissance-als_0 Finish Time: Tue Dec 16 09:00:34 2025 Epoch Time (ms): 1765875634547