openj9
openj9 copied to clipboard
Published
20 hours ago •
eclipse-openj9
eclipse-openj9
cmdLineTester_criu_jitserverAcrossCheckpoint Check no connection in Post-Restore - Connected to a server
trafficstars
https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.functional_x86-64_linux_OMR_testList_1/44 cmdLineTester_criu_jitserverAcrossCheckpoint_0 Testing: JITServer not explicitly enabled Post-Restore: Check no connection in Post-Restore Verbose Log
...
[OUT] #JITServer: Client sending compReq seqNo=1 to server for method jdk/internal/misc/Unsafe.allocateUninitializedArray(Ljava/lang/Class;I)Ljava/lang/Object; @ warm.
[OUT] #JITServer: t= 30 Connected to a server (serverUID=6428268784253193794)
...
[OUT] Outputting previous test output
[OUT] Pre-checkpoint
[OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Wed Jul 05 08:37:12 ADT 2023, System.currentTimeMillis(): 1688557032966, System.nanoTime(): 5347230219643849
[OUT] pie: 11116: Error (criu/pie/restorer.c:1646): Unable to create a thread: 11118
[OUT] pie: 11116: Error (criu/pie/restorer.c:1782): Restorer fail 11116
[OUT] Error (criu/cr-restore.c:2294): Restoring FAILED.
[OUT]
[OUT] Removed test output files
[OUT] finished script
>> Success condition was found: [Output match: CHECKPOINT RESTORE: Ready for restore]
>> Success condition was not found: [Output match: CAT VLOG FORCE PASS]
>> Failure condition was found: [Output match: Connected to a server]
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_x86-64_linux_Nightly_testList_1/584 cmdLineTester_criu_jitserverAcrossCheckpoint_0
Testing: JITServer not explicitly enabled Post-Restore: Check no connection in Post-Restore Verbose Log
Test start time: 2023/08/22 00:38:22 Atlantic Standard Time
Running command: bash /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_x86-64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuCatVlog.sh postRestoreVlog true true
Time spent starting: 3 milliseconds
Time spent executing: 27 milliseconds
Test result: FAILED
Output from test:
[OUT] start running script
[OUT] Outputting vlog postRestoreVlog
[OUT] #CHECKPOINT RESTORE: Start and elapsed time: startTime=458372574, elapsedTime= 1184
[OUT] #CHECKPOINT RESTORE: Reset start and elapsed time: startTime=458376039, elapsedTime= 0
[OUT] #CHECKPOINT RESTORE: Ready for restore
[OUT] (cold) Compiling openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z OrdinaryMethod j9m=00000000001FD608 remote t=20 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=1 to server for method openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ cold.
[OUT] #JITServer: t= 20 Connected to a server (serverUID=170430878905764179)
[OUT] #JITServer: Client successfully loaded method openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ cold following compilation request. [metaData=00007F0EEC3CC238, startPC=00007F0EEE3AB01C]
[OUT] + (cold) openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ 00007F0EEE3AB01C-00007F0EEE3AB166 OrdinaryMethod - Q_SZ=10 Q_SZI=10 QW=11 j9m=00000000001FD608 bcsz=2 JNI remote time=25037us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=13% queueTime=25117us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.open0(JII)I OrdinaryMethod j9m=00000000001397F8 remote t=40 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=2 to server for method sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ cold following compilation request. [metaData=00007F0EEC3CC378, startPC=00007F0EEE3AB19C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ 00007F0EEE3AB19C-00007F0EEE3AB303 OrdinaryMethod - Q_SZ=12 Q_SZI=11 QW=15 j9m=00000000001397F8 bcsz=5 JNI remote time=7134us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=13% queueTime=26290us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.dup(I)I OrdinaryMethod j9m=00000000001397B8 remote t=50 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=3 to server for method sun/nio/fs/UnixNativeDispatcher.dup(I)I @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.dup(I)I @ cold following compilation request. [metaData=00007F0EEC3CC4B8, startPC=00007F0EEE3AB33C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.dup(I)I @ 00007F0EEE3AB33C-00007F0EEE3AB48B OrdinaryMethod - Q_SZ=11 Q_SZI=10 QW=14 j9m=00000000001397B8 bcsz=3 JNI remote time=2723us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=13% queueTime=29208us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J OrdinaryMethod j9m=0000000000139EB8 remote t=50 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=4 to server for method sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ cold following compilation request. [metaData=00007F0EEC3CC5F8, startPC=00007F0EEE3AB4BC]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ 00007F0EEE3AB4BC-00007F0EEE3AB60B OrdinaryMethod - Q_SZ=11 Q_SZI=10 QW=15 j9m=0000000000139EB8 bcsz=3 JNI remote time=2664us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=13% queueTime=32043us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J OrdinaryMethod j9m=000000000018E378 remote t=50 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=5 to server for method openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ cold.
[OUT] #JITSTATE: t= 51 Changing maxIProfilingCount to 3000
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ cold following compilation request. [metaData=00007F0EEC3CC738, startPC=00007F0EEE3AB63C]
[OUT] + (cold) openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ 00007F0EEE3AB63C-00007F0EEE3AB7B8 OrdinaryMethod - Q_SZ=12 Q_SZI=11 QW=16 j9m=000000000018E378 bcsz=5 JNI remote time=4301us mem=[region=192 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=36244us
[OUT] (cold) Compiling java/io/UnixFileSystem.delete0(Ljava/io/File;)Z OrdinaryMethod j9m=00000000000FF628 remote t=51 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=6 to server for method java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ cold.
[OUT] #JITServer: Client successfully loaded method java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ cold following compilation request. [metaData=00007F0EEC3CC878, startPC=00007F0EEE3AB7DC]
[OUT] + (cold) java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ 00007F0EEE3AB7DC-00007F0EEE3AB94D OrdinaryMethod - Q_SZ=11 Q_SZI=10 QW=15 j9m=00000000000FF628 bcsz=3 JNI remote time=4775us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=41163us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.readdir(J)[B OrdinaryMethod j9m=0000000000139EF8 remote t=51 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=7 to server for method sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ cold following compilation request. [metaData=00007F0EEC3CC9B8, startPC=00007F0EEE3AB97C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ 00007F0EEE3AB97C-00007F0EEE3ABAD5 OrdinaryMethod - Q_SZ=10 Q_SZI=9 QW=14 j9m=0000000000139EF8 bcsz=3 JNI remote time=1966us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=43089us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I OrdinaryMethod j9m=000000000016CB18 remote t=51 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=8 to server for method openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ cold following compilation request. [metaData=00007F0EEC3CCAF8, startPC=00007F0EEE3ABAFC]
[OUT] + (cold) openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ 00007F0EEE3ABAFC-00007F0EEE3ABC87 OrdinaryMethod - Q_SZ=9 Q_SZI=8 QW=13 j9m=000000000016CB18 bcsz=5 JNI remote time=2034us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=45070us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I OrdinaryMethod j9m=000000000018E398 remote t=61 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=9 to server for method openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ cold following compilation request. [metaData=00007F0EEC3CCC38, startPC=00007F0EEE3ABCBC]
[OUT] + (cold) openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ 00007F0EEE3ABCBC-00007F0EEE3ABE0D OrdinaryMethod - Q_SZ=8 Q_SZI=7 QW=12 j9m=000000000018E398 bcsz=3 JNI remote time=1710us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=46617us
[OUT] (cold) Compiling java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; OrdinaryMethod j9m=00000000000FF648 remote t=61 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=10 to server for method java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ cold.
[OUT] #JITServer: Client successfully loaded method java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ cold following compilation request. [metaData=00007F0EEC3CCD78, startPC=00007F0EEE3ABE3C]
[OUT] + (cold) java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ 00007F0EEE3ABE3C-00007F0EEE3ABFAF OrdinaryMethod - Q_SZ=7 Q_SZI=6 QW=11 j9m=00000000000FF648 bcsz=3 JNI remote time=1958us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=48011us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.waitSemaphore()I OrdinaryMethod j9m=000000000016CB38 remote t=61 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=11 to server for method openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ cold following compilation request. [metaData=00007F0EEC3CCEB8, startPC=00007F0EEE3ABFDC]
[OUT] + (cold) openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ 00007F0EEE3ABFDC-00007F0EEE3AC120 OrdinaryMethod - Q_SZ=6 Q_SZI=5 QW=10 j9m=000000000016CB38 bcsz=2 JNI remote time=1635us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=48841us
[OUT] (warm) Compiling java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I SharableInvokeExactThunk j9m=00000000000985A0 remote t=61 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=12 to server for method java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I @ warm.
[OUT] #JITServer: Client successfully loaded method java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I @ warm following compilation request. [metaData=00007F0EEC3CCFF8, startPC=00007F0EEE3AC134]
[OUT] + (warm) java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I @ 00007F0EEE3AC134-00007F0EEE3AC4E1 SharableInvokeExactThunk - Q_SZ=5 Q_SZI=5 QW=9 j9m=00000000000985A0 bcsz=54 remote time=35201us mem=[region=256 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=68027us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.closedir(J)V OrdinaryMethod j9m=0000000000139ED8 remote t=101 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=13 to server for method sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ cold following compilation request. [metaData=00007F0EEC3CD238, startPC=00007F0EEE3AC51C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ 00007F0EEE3AC51C-00007F0EEE3AC667 OrdinaryMethod - Q_SZ=4 Q_SZI=4 QW=8 j9m=0000000000139ED8 bcsz=3 JNI remote time=1903us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=56847us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.close0(I)V OrdinaryMethod j9m=0000000000139878 remote t=101 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=14 to server for method sun/nio/fs/UnixNativeDispatcher.close0(I)V @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.close0(I)V @ cold following compilation request. [metaData=00007F0EEC3CD378, startPC=00007F0EEE3AC69C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.close0(I)V @ 00007F0EEE3AC69C-00007F0EEE3AC7E5 OrdinaryMethod - Q_SZ=3 Q_SZI=3 QW=7 j9m=0000000000139878 bcsz=3 JNI remote time=1531us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=58516us
[OUT] (AOT warm) Compiling java/util/Arrays.copyOfRange([BII)[B OrdinaryMethod j9m=00000000000B22B8 remote t=101 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=15 to server for method java/util/Arrays.copyOfRange([BII)[B @ warm.
[OUT] #PERF: Reencoding count=1000 for java/util/Arrays.copyOfRange([BII)[B j9m=00000000000B22B8
[OUT] #JITServer: Client successfully loaded method java/util/Arrays.copyOfRange([BII)[B @ warm following compilation request. [metaData=00007F0EEC3CD4B8, startPC=00007F0013964068]
[OUT] + (AOT warm) java/util/Arrays.copyOfRange([BII)[B @ 00007F0013964068-00007F0013964725 OrdinaryMethod - Q_SZ=2 Q_SZI=2 QW=6 j9m=00000000000B22B8 bcsz=63 remote time=14181us mem=[region=256 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=84358us
[OUT] (AOT warm) Compiling sun/nio/fs/UnixPath.getFileSystem()Ljava/nio/file/FileSystem; OrdinaryMethod j9m=0000000000136968 remote t=111 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=16 to server for method sun/nio/fs/UnixPath.getFileSystem()Ljava/nio/file/FileSystem; @ warm.
[OUT] #PERF: Reencoding count=1000 for sun/nio/fs/UnixPath.getFileSystem()Ljava/nio/file/FileSystem; j9m=0000000000136968
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixPath.getFileSystem()Ljava/nio/file/FileSystem; @ warm following compilation request. [metaData=00007F0EEC3CD738, startPC=00007F0013964060]
[OUT] + (AOT warm) sun/nio/fs/UnixPath.getFileSystem()Ljava/nio/file/FileSystem; @ 00007F0013964060-00007F00139641E4 OrdinaryMethod - Q_SZ=1 Q_SZI=1 QW=4 j9m=0000000000136968 bcsz=5 remote time=7519us mem=[region=192 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=89591us
[OUT] (AOT warm) Compiling sun/nio/fs/UnixDirectoryStream$UnixDirectoryIterator.readNextEntry()Ljava/nio/file/Path; OrdinaryMethod j9m=0000000000206A28 remote t=121 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7163 MB
[OUT] #JITServer: Client sending compReq seqNo=17 to server for method sun/nio/fs/UnixDirectoryStream$UnixDirectoryIterator.readNextEntry()Ljava/nio/file/Path; @ warm.
[OUT] #PERF: Reencoding count=250 for sun/nio/fs/UnixDirectoryStream$UnixDirectoryIterator.readNextEntry()Ljava/nio/file/Path; j9m=0000000000206A28
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixDirectoryStream$UnixDirectoryIterator.readNextEntry()Ljava/nio/file/Path; @ warm following compilation request. [metaData=00007F0EEC3CD8B8, startPC=00007F0013964060]
[OUT] + (AOT warm) sun/nio/fs/UnixDirectoryStream$UnixDirectoryIterator.readNextEntry()Ljava/nio/file/Path; @ 00007F0013964060-00007F00139652B4 OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=2 j9m=0000000000206A28 bcsz=185 remote time=71169us mem=[region=256 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=148% queueTime=153767us
[OUT] #JITSTATE: t= 1555 JIT changed state from STARTUP to IDLE cSmpl= 0 iSmpl= 3 comp= 10 recomp= 0, Q_SZ= 0 CLP=OFF jvmCPU=0%
[OUT] (cold) Compiling jdk/internal/misc/Unsafe.freeMemory0(J)V OrdinaryMethod j9m=000000000006CD60 remote t=2045 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7156 MB
[OUT] #JITServer: Client sending compReq seqNo=18 to server for method jdk/internal/misc/Unsafe.freeMemory0(J)V @ cold.
[OUT] #JITServer: Client successfully loaded method jdk/internal/misc/Unsafe.freeMemory0(J)V @ cold following compilation request. [metaData=00007F0EEC3CE038, startPC=00007F0EEE3AC81C]
[OUT] + (cold) jdk/internal/misc/Unsafe.freeMemory0(J)V @ 00007F0EEE3AC81C-00007F0EEE3AC96C OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=1 j9m=000000000006CD60 bcsz=3 JNI remote time=5660us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=258% queueTime=8597us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I OrdinaryMethod j9m=000000000016CB58 remote t=2055 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7156 MB
[OUT] #JITServer: Client sending compReq seqNo=19 to server for method openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I @ cold following compilation request. [metaData=00007F0EEC3CE178, startPC=00007F0EEE3AC99C]
[OUT] + (cold) openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I @ 00007F0EEE3AC99C-00007F0EEE3ACB32 OrdinaryMethod - Q_SZ=1 Q_SZI=1 QW=2 j9m=000000000016CB58 bcsz=6 JNI remote time=9760us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=258% queueTime=9870us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.closeSemaphore()V OrdinaryMethod j9m=000000000016CB98 remote t=2065 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7156 MB
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000022500, thread ID 2
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000002DA00, thread ID 5
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001AC00, thread ID 0
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000029E00, thread ID 4
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000026100, thread ID 3
[OUT] ! (cold) openj9/internal/tools/attach/target/IPC.closeSemaphore()V Q_SZ=0 Q_SZI=0 QW=1 j9m=000000000016CB98 time=879us compilationInterrupted memLimit=262144 KB freePhysicalMemory=7156 MB mem=[region=64 system=2048]KB compThreadID=6
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001E800, thread ID 1
[OUT] #PERF: Time spent in compilation thread =70 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000031700, thread ID 6
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000053700, thread ID 15
[OUT] #JITServer: Sent clientSessionTerminate message
[OUT]
[OUT] Outputting previous test output
[OUT] Pre-checkpoint
[OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Tue Aug 22 00:38:17 ADT 2023, System.currentTimeMillis(): 1692675497582, System.nanoTime(): 9465694835830561
[OUT] pie: 21217: Error (criu/pie/restorer.c:1646): Unable to create a thread: 21220
[OUT] pie: 21217: Error (criu/pie/restorer.c:1782): Restorer fail 21217
[OUT] Error (criu/cr-restore.c:2294): Restoring FAILED.
[OUT]
[OUT] CAT VLOG FORCE PASS
[OUT] Removed test output files
[OUT] finished script
>> Success condition was found: [Output match: CHECKPOINT RESTORE: Ready for restore]
>> Success condition was found: [Output match: CAT VLOG FORCE PASS]
>> Failure condition was found: [Output match: Connected to a server]
>> Failure condition was not found: [Output match: User requested Java dump using]
I think this is because the previous test's postRestoreVlog wasn't deleted 😭 ; I guess when the restore succeeds, the restore JVM overwrites postRestoreVlog.
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_x86-64_linux_Nightly_testList_1/81
cmdLineTester_criu_jitserverAcrossCheckpoint_0
Testing: JITServer not explicitly enabled Post-Restore: Check no connection in Post-Restore Verbose Log
Failure condition was found: [Output match: Connected to a server]
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_aarch64_linux_Nightly_testList_0/588 cmdLineTester_criu_jitserverAcrossCheckpoint_0
Testing: JITServer not explicitly enabled Post-Restore: Check no connection in Post-Restore Verbose Log
Test start time: 2024/01/22 22:09:49 Eastern Standard Time
Running command: bash /home/jenkins/workspace/Test_openjdk11_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuCatVlog.sh postRestoreVlog true true
Time spent starting: 1 milliseconds
Time spent executing: 19 milliseconds
Test result: FAILED
Output from test:
[OUT] start running script
[OUT] Outputting vlog postRestoreVlog
[OUT] #CHECKPOINT RESTORE: Start and elapsed time: startTime=877359346, elapsedTime= 561
[OUT] #CHECKPOINT RESTORE: Reset start and elapsed time: startTime=877361508, elapsedTime= 561
[OUT] #CHECKPOINT RESTORE: Resuming Sampler Thread from Checkpoint
[OUT] #CHECKPOINT RESTORE: Resetting Sampling Thread Lifetime State
[OUT] #CHECKPOINT RESTORE: Ready for restore
[OUT] (cold) Compiling openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z OrdinaryMethod j9m=00000000001D1AA8 remote t=561 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=1 to server for method openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ cold.
[OUT] #JITServer: t= 561 Connected to a server (serverUID=4742164625873374884)
[OUT] #JITServer: Client successfully loaded method openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ cold following compilation request. [metaData=0000FFFF7C02CCF8, startPC=0000FFFF7D4F0FA4]
[OUT] + (cold) openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ 0000FFFF7D4F0FA4-0000FFFF7D4F10D0 OrdinaryMethod - Q_SZ=13 Q_SZI=12 QW=14 j9m=00000000001D1AA8 bcsz=2 JNI remote time=12101us mem=[region=128 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=12170us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.open0(JII)I OrdinaryMethod j9m=000000000011FDF8 remote t=571 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=2 to server for method sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ cold following compilation request. [metaData=0000FFFF7C02CE38, startPC=0000FFFF7D4F10EC]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ 0000FFFF7D4F10EC-0000FFFF7D4F1234 OrdinaryMethod - Q_SZ=12 Q_SZI=11 QW=13 j9m=000000000011FDF8 bcsz=5 JNI remote time=3205us mem=[region=128 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=13117us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.dup(I)I OrdinaryMethod j9m=000000000011FDB8 remote t=571 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=3 to server for method sun/nio/fs/UnixNativeDispatcher.dup(I)I @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.dup(I)I @ cold following compilation request. [metaData=0000FFFF7C02CF78, startPC=0000FFFF7D4F1254]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.dup(I)I @ 0000FFFF7D4F1254-0000FFFF7D4F1384 OrdinaryMethod - Q_SZ=11 Q_SZI=10 QW=12 j9m=000000000011FDB8 bcsz=3 JNI remote time=1308us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=14442us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J OrdinaryMethod j9m=00000000001204B8 remote t=571 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=4 to server for method sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ cold following compilation request. [metaData=0000FFFF7C02D0B8, startPC=0000FFFF7D4F13A4]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ 0000FFFF7D4F13A4-0000FFFF7D4F14D4 OrdinaryMethod - Q_SZ=10 Q_SZI=9 QW=11 j9m=00000000001204B8 bcsz=3 JNI remote time=6869us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=21339us
[OUT] (cold) Compiling java/io/UnixFileSystem.delete0(Ljava/io/File;)Z OrdinaryMethod j9m=00000000000E84F8 remote t=581 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=5 to server for method java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ cold.
[OUT] #JITServer: Client successfully loaded method java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ cold following compilation request. [metaData=0000FFFF7C02D1F8, startPC=0000FFFF7D4F14F4]
[OUT] + (cold) java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ 0000FFFF7D4F14F4-0000FFFF7D4F1638 OrdinaryMethod - Q_SZ=9 Q_SZI=8 QW=10 j9m=00000000000E84F8 bcsz=3 JNI remote time=1825us mem=[region=128 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=23131us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.readdir(J)[B OrdinaryMethod j9m=00000000001204F8 remote t=581 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=6 to server for method sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ cold following compilation request. [metaData=0000FFFF7C02D338, startPC=0000FFFF7D4F1654]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ 0000FFFF7D4F1654-0000FFFF7D4F178C OrdinaryMethod - Q_SZ=8 Q_SZI=7 QW=9 j9m=00000000001204F8 bcsz=3 JNI remote time=1247us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=24355us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J OrdinaryMethod j9m=000000000016EBE8 remote t=581 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=7 to server for method openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ cold following compilation request. [metaData=0000FFFF7C02D478, startPC=0000FFFF7D4F17AC]
[OUT] + (cold) openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ 0000FFFF7D4F17AC-0000FFFF7D4F1900 OrdinaryMethod - Q_SZ=7 Q_SZI=6 QW=8 j9m=000000000016EBE8 bcsz=5 JNI remote time=2005us mem=[region=192 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=25918us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I OrdinaryMethod j9m=0000000000163018 remote t=591 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=8 to server for method openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ cold following compilation request. [metaData=0000FFFF7C02D5B8, startPC=0000FFFF7D4F191C]
[OUT] + (cold) openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ 0000FFFF7D4F191C-0000FFFF7D4F1A7C OrdinaryMethod - Q_SZ=6 Q_SZI=5 QW=7 j9m=0000000000163018 bcsz=5 JNI remote time=1144us mem=[region=128 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=26909us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I OrdinaryMethod j9m=000000000016EC08 remote t=591 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=9 to server for method openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ cold following compilation request. [metaData=0000FFFF7C02D6F8, startPC=0000FFFF7D4F1A9C]
[OUT] + (cold) openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ 0000FFFF7D4F1A9C-0000FFFF7D4F1BCC OrdinaryMethod - Q_SZ=5 Q_SZI=4 QW=6 j9m=000000000016EC08 bcsz=3 JNI remote time=1119us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=27846us
[OUT] (cold) Compiling java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; OrdinaryMethod j9m=00000000000E8518 remote t=591 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=10 to server for method java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ cold.
[OUT] #JITServer: Client successfully loaded method java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ cold following compilation request. [metaData=0000FFFF7C02D838, startPC=0000FFFF7D4F1BEC]
[OUT] + (cold) java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ 0000FFFF7D4F1BEC-0000FFFF7D4F1D30 OrdinaryMethod - Q_SZ=4 Q_SZI=3 QW=5 j9m=00000000000E8518 bcsz=3 JNI remote time=3508us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=31006us
[OUT] (warm) Compiling java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I SharableInvokeExactThunk j9m=00000000000808A0 remote t=591 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=11 to server for method java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I @ warm.
[OUT] #JITServer: Client successfully loaded method java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I @ warm following compilation request. [metaData=0000FFFF7C02D978, startPC=0000FFFF7D4F1D44]
[OUT] + (warm) java/lang/invoke/DirectHandle.invokeExact_thunkArchetype_I(Ljava/lang/Object;IILjava/lang/Object;)I @ 0000FFFF7D4F1D44-0000FFFF7D4F20D0 SharableInvokeExactThunk - Q_SZ=3 Q_SZI=3 QW=4 j9m=00000000000808A0 bcsz=54 remote time=13194us mem=[region=320 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=43661us
[OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.waitSemaphore()I OrdinaryMethod j9m=0000000000163038 remote t=611 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6428 MB
[OUT] #JITServer: Client sending compReq seqNo=12 to server for method openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ cold.
[OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ cold following compilation request. [metaData=0000FFFF7C02DBF8, startPC=0000FFFF7D4F20EC]
[OUT] + (cold) openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ 0000FFFF7D4F20EC-0000FFFF7D4F2210 OrdinaryMethod - Q_SZ=2 Q_SZI=2 QW=3 j9m=0000000000163038 bcsz=2 JNI remote time=1020us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=44309us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.closedir(J)V OrdinaryMethod j9m=00000000001204D8 remote t=611 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6428 MB
[OUT] #JITServer: Client sending compReq seqNo=13 to server for method sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ cold following compilation request. [metaData=0000FFFF7C02DD38, startPC=0000FFFF7D4F222C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ 0000FFFF7D4F222C-0000FFFF7D4F235C OrdinaryMethod - Q_SZ=1 Q_SZI=1 QW=2 j9m=00000000001204D8 bcsz=3 JNI remote time=720us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=42302us
[OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.close0(I)V OrdinaryMethod j9m=000000000011FE78 remote t=611 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6428 MB
[OUT] #JITServer: Client sending compReq seqNo=14 to server for method sun/nio/fs/UnixNativeDispatcher.close0(I)V @ cold.
[OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.close0(I)V @ cold following compilation request. [metaData=0000FFFF7C02DE78, startPC=0000FFFF7D4F241C]
[OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.close0(I)V @ 0000FFFF7D4F241C-0000FFFF7D4F254C OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=1 j9m=000000000011FE78 bcsz=3 JNI remote time=738us mem=[region=64 system=2048]KB compThreadID=0 CpuLoad=0%(0%avg) JvmCpu=45% queueTime=43055us
[OUT] #JITSTATE: t= 1008 Changing maxIProfilingCount to 3000
[OUT] #JITSTATE: t= 2026 JIT changed state from STARTUP to IDLE cSmpl= 0 iSmpl= 3 comp= 27 recomp= 0, Q_SZ= 0 CLP=OFF jvmCPU=0%
[OUT] (cold) Compiling jdk/internal/misc/Unsafe.freeMemory0(J)V OrdinaryMethod j9m=00000000000548D0 remote t=2565 compThreadID=0 memLimit=262144 KB freePhysicalMemory=6432 MB
[OUT] #JITServer: Client sending compReq seqNo=15 to server for method jdk/internal/misc/Unsafe.freeMemory0(J)V @ cold.
[OUT] #PERF: Time spent in compilation thread =5 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000020100, thread ID 2
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000022600, thread ID 3
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001DC00, thread ID 1
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000029500, thread ID 6
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000027000, thread ID 5
[OUT] #PERF: Time spent in compilation thread =0 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000024B00, thread ID 4
[OUT] #FAILURE: Interrupting remote compilation (interruptReason 2) in handleServerMessage(ResolvedMethod_startAddressForJNIMethod) for jdk/internal/misc/Unsafe.freeMemory0(J)V @ cold
[OUT] ! (cold) jdk/internal/misc/Unsafe.freeMemory0(J)V Q_SZ=0 Q_SZI=0 QW=1 j9m=00000000000548D0 time=11370us compilationInterrupted memLimit=262144 KB freePhysicalMemory=6432 MB mem=[region=64 system=2048]KB compThreadID=0
[OUT] #PERF: Time spent in compilation thread =29 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001B700, thread ID 0
[OUT] #PERF: Time spent in compilation thread =1 ms
[OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000003E100, thread ID 15
[OUT] #JITServer: Sent clientSessionTerminate message
[OUT]
[OUT] Outputting previous test output
[OUT] Pre-checkpoint
[OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Mon Jan 22 22:09:44 EST 2024, System.currentTimeMillis(): 1705979384886, System.nanoTime(): 1686909796255362
[OUT] pie: 3607531: Error (criu/pie/restorer.c:1833): Unable to create a thread: 3607540
[OUT] pie: 3607540: Error (criu/pie/restorer.c:598): Thread pid mismatch 3607540/3607539
[OUT] pie: 3607540: Error (criu/pie/restorer.c:651): Restorer abnormal termination for 3607531
[OUT] Error (criu/cr-restore.c:2536): Restoring FAILED.
[OUT]
[OUT] CAT VLOG FORCE PASS
[OUT] Removed test output files
[OUT] finished script
>> Success condition was found: [Output match: CHECKPOINT RESTORE: Ready for restore]
>> Success condition was found: [Output match: CAT VLOG FORCE PASS]
>> Failure condition was found: [Output match: Connected to a server]
>> Failure condition was not found: [Output match: User requested Java dump using]
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_aarch64_linux_Nightly_testList_0/623 cmdLineTester_criu_jitserverAcrossCheckpoint_0
21:16:45 Testing: JITServer not explicitly enabled Post-Restore: Check no connection in Post-Restore Verbose Log
21:16:45 Test start time: 2024/02/07 02:16:44 Coordinated Universal Time
21:16:45 Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_aarch64_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuCatVlog.sh postRestoreVlog true true
21:16:45 Time spent starting: 3 milliseconds
21:16:45 Time spent executing: 12 milliseconds
21:16:45 Test result: FAILED
21:16:45 Output from test:
21:16:45 [OUT] start running script
21:16:45 [OUT] Outputting vlog postRestoreVlog
21:16:45 [OUT] #CHECKPOINT RESTORE: Start and elapsed time: startTime=2170171805, elapsedTime= 1813
21:16:45 [OUT] #CHECKPOINT RESTORE: Reset start and elapsed time: startTime=2170174329, elapsedTime= 1813
21:16:45 [OUT] #CHECKPOINT RESTORE: Resuming Sampler Thread from Checkpoint
21:16:45 [OUT] #CHECKPOINT RESTORE: Resetting Sampling Thread Lifetime State
21:16:45 [OUT] #CHECKPOINT RESTORE: Ready for restore
21:16:45 [OUT] #CHECKPOINT RESTORE: Resuming IProfiler Thread from Checkpoint
21:16:45 [OUT] #CHECKPOINT RESTORE: Resetting IProfier Thread Lifetime State
21:16:45 [OUT] (cold) Compiling openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z OrdinaryMethod j9m=00000000001FD2F8 remote t=1823 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7107 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=1 to server for method openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ cold.
21:16:45 [OUT] #JITServer: t= 1843 Connected to a server (serverUID=2077153462241449363)
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ cold following compilation request. [metaData=0000FFFF81A21DB8, startPC=0000FFFF832C1F8C]
21:16:45 [OUT] + (cold) openj9/internal/criu/InternalCRIUSupport.isCheckpointAllowedImpl()Z @ 0000FFFF832C1F8C-0000FFFF832C20B8 OrdinaryMethod - Q_SZ=15 Q_SZI=15 QW=27 j9m=00000000001FD2F8 bcsz=2 JNI remote time=29885us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=30123us
21:16:45 [OUT] (cold) Compiling openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J OrdinaryMethod j9m=000000000016D078 remote t=1853 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7107 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=2 to server for method openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ cold following compilation request. [metaData=0000FFFF81A21EF8, startPC=0000FFFF832C20D4]
21:16:45 [OUT] + (cold) openj9/internal/tools/attach/target/FileLock.lockFileImpl(Ljava/lang/String;IZ)J @ 0000FFFF832C20D4-0000FFFF832C2228 OrdinaryMethod - Q_SZ=14 Q_SZI=14 QW=26 j9m=000000000016D078 bcsz=5 JNI remote time=6987us mem=[region=256 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=34962us
21:16:45 [OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.open0(JII)I OrdinaryMethod j9m=000000000011B6B8 remote t=1863 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=3 to server for method sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ cold following compilation request. [metaData=0000FFFF81A22038, startPC=0000FFFF832C2244]
21:16:45 [OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.open0(JII)I @ 0000FFFF832C2244-0000FFFF832C238C OrdinaryMethod - Q_SZ=13 Q_SZI=13 QW=25 j9m=000000000011B6B8 bcsz=5 JNI remote time=4125us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=32490us
21:16:45 [OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.dup(I)I OrdinaryMethod j9m=000000000011B678 remote t=1863 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=4 to server for method sun/nio/fs/UnixNativeDispatcher.dup(I)I @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.dup(I)I @ cold following compilation request. [metaData=0000FFFF81A22178, startPC=0000FFFF832C23AC]
21:16:45 [OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.dup(I)I @ 0000FFFF832C23AC-0000FFFF832C24DC OrdinaryMethod - Q_SZ=12 Q_SZI=12 QW=24 j9m=000000000011B678 bcsz=3 JNI remote time=2521us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=35064us
21:16:45 [OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J OrdinaryMethod j9m=000000000011BD78 remote t=1863 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=5 to server for method sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ cold following compilation request. [metaData=0000FFFF81A222B8, startPC=0000FFFF832C24FC]
21:16:45 [OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.fdopendir(I)J @ 0000FFFF832C24FC-0000FFFF832C262C OrdinaryMethod - Q_SZ=11 Q_SZI=11 QW=23 j9m=000000000011BD78 bcsz=3 JNI remote time=2270us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=37392us
21:16:45 [OUT] (cold) Compiling java/io/UnixFileSystem.delete0(Ljava/io/File;)Z OrdinaryMethod j9m=00000000000EA868 remote t=1873 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=6 to server for method java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ cold following compilation request. [metaData=0000FFFF81A223F8, startPC=0000FFFF832C264C]
21:16:45 [OUT] + (cold) java/io/UnixFileSystem.delete0(Ljava/io/File;)Z @ 0000FFFF832C264C-0000FFFF832C2790 OrdinaryMethod - Q_SZ=10 Q_SZI=10 QW=22 j9m=00000000000EA868 bcsz=3 JNI remote time=6713us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=44012us
21:16:45 [OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.readdir(J)[B OrdinaryMethod j9m=000000000011BDB8 remote t=1873 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=7 to server for method sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ cold following compilation request. [metaData=0000FFFF81A22538, startPC=0000FFFF832C27AC]
21:16:45 [OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.readdir(J)[B @ 0000FFFF832C27AC-0000FFFF832C28E4 OrdinaryMethod - Q_SZ=9 Q_SZI=9 QW=21 j9m=000000000011BDB8 bcsz=3 JNI remote time=3545us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=47616us
21:16:45 [OUT] (cold) Compiling java/io/RandomAccessFile.open0(Ljava/lang/String;I)V OrdinaryMethod j9m=000000000017C668 remote t=1883 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=8 to server for method java/io/RandomAccessFile.open0(Ljava/lang/String;I)V @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method java/io/RandomAccessFile.open0(Ljava/lang/String;I)V @ cold following compilation request. [metaData=0000FFFF81A22678, startPC=0000FFFF832C2904]
21:16:45 [OUT] + (cold) java/io/RandomAccessFile.open0(Ljava/lang/String;I)V @ 0000FFFF832C2904-0000FFFF832C2A4C OrdinaryMethod - Q_SZ=8 Q_SZI=8 QW=20 j9m=000000000017C668 bcsz=4 JNI remote time=2906us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=50395us
21:16:45 [OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.closedir(J)V OrdinaryMethod j9m=000000000011BD98 remote t=1883 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=9 to server for method sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ cold following compilation request. [metaData=0000FFFF81A227B8, startPC=0000FFFF832C2A6C]
21:16:45 [OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.closedir(J)V @ 0000FFFF832C2A6C-0000FFFF832C2B9C OrdinaryMethod - Q_SZ=7 Q_SZI=7 QW=19 j9m=000000000011BD98 bcsz=3 JNI remote time=2482us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=38891us
21:16:45 [OUT] (cold) Compiling sun/nio/fs/UnixNativeDispatcher.close0(I)V OrdinaryMethod j9m=000000000011B738 remote t=1883 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=10 to server for method sun/nio/fs/UnixNativeDispatcher.close0(I)V @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/UnixNativeDispatcher.close0(I)V @ cold following compilation request. [metaData=0000FFFF81A228F8, startPC=0000FFFF832C2BBC]
21:16:45 [OUT] + (cold) sun/nio/fs/UnixNativeDispatcher.close0(I)V @ 0000FFFF832C2BBC-0000FFFF832C2CEC OrdinaryMethod - Q_SZ=6 Q_SZI=6 QW=18 j9m=000000000011B738 bcsz=3 JNI remote time=2393us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=41341us
21:16:45 [OUT] (cold) Compiling sun/nio/ch/NativeThread.current()J OrdinaryMethod j9m=000000000029EAE0 remote t=1883 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=11 to server for method sun/nio/ch/NativeThread.current()J @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/ch/NativeThread.current()J @ cold following compilation request. [metaData=0000FFFF81A22A38, startPC=0000FFFF832C2D0C]
21:16:45 [OUT] + (cold) sun/nio/ch/NativeThread.current()J @ 0000FFFF832C2D0C-0000FFFF832C2E30 OrdinaryMethod - Q_SZ=5 Q_SZI=5 QW=17 j9m=000000000029EAE0 bcsz=2 JNI remote time=2630us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=42703us
21:16:45 [OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I OrdinaryMethod j9m=0000000000158618 remote t=1893 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=12 to server for method openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ cold following compilation request. [metaData=0000FFFF81A22B78, startPC=0000FFFF832C2E4C]
21:16:45 [OUT] + (cold) openj9/internal/tools/attach/target/IPC.openSemaphore(Ljava/lang/String;Ljava/lang/String;Z)I @ 0000FFFF832C2E4C-0000FFFF832C2FAC OrdinaryMethod - Q_SZ=4 Q_SZI=4 QW=16 j9m=0000000000158618 bcsz=5 JNI remote time=2671us mem=[region=128 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=45177us
21:16:45 [OUT] (cold) Compiling java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; OrdinaryMethod j9m=00000000000EA888 remote t=1893 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=13 to server for method java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ cold following compilation request. [metaData=0000FFFF81A22CB8, startPC=0000FFFF832C2FCC]
21:16:45 [OUT] + (cold) java/io/UnixFileSystem.list(Ljava/io/File;)[Ljava/lang/String; @ 0000FFFF832C2FCC-0000FFFF832C3110 OrdinaryMethod - Q_SZ=3 Q_SZI=3 QW=15 j9m=00000000000EA888 bcsz=3 JNI remote time=2582us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=46670us
21:16:45 [OUT] (cold) Compiling openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I OrdinaryMethod j9m=000000000016D098 remote t=1893 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=14 to server for method openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ cold following compilation request. [metaData=0000FFFF81A22DF8, startPC=0000FFFF832C312C]
21:16:45 [OUT] + (cold) openj9/internal/tools/attach/target/FileLock.unlockFileImpl(J)I @ 0000FFFF832C312C-0000FFFF832C325C OrdinaryMethod - Q_SZ=2 Q_SZI=2 QW=14 j9m=000000000016D098 bcsz=3 JNI remote time=2072us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=48373us
21:16:45 [OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.waitSemaphore()I OrdinaryMethod j9m=0000000000158638 remote t=1893 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=15 to server for method openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ cold following compilation request. [metaData=0000FFFF81A22F38, startPC=0000FFFF832C327C]
21:16:45 [OUT] + (cold) openj9/internal/tools/attach/target/IPC.waitSemaphore()I @ 0000FFFF832C327C-0000FFFF832C33A0 OrdinaryMethod - Q_SZ=1 Q_SZI=1 QW=13 j9m=0000000000158638 bcsz=2 JNI remote time=1980us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=50389us
21:16:45 [OUT] (AOT warm) Compiling sun/nio/fs/NativeBuffers.releaseNativeBuffer(Lsun/nio/fs/NativeBuffer;)V OrdinaryMethod j9m=0000000000123D40 remote t=1907 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7098 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=16 to server for method sun/nio/fs/NativeBuffers.releaseNativeBuffer(Lsun/nio/fs/NativeBuffer;)V @ warm.
21:16:45 [OUT] #PERF: Reencoding count=250 for sun/nio/fs/NativeBuffers.releaseNativeBuffer(Lsun/nio/fs/NativeBuffer;)V j9m=0000000000123D40
21:16:45 [OUT] #JITServer: Client successfully loaded method sun/nio/fs/NativeBuffers.releaseNativeBuffer(Lsun/nio/fs/NativeBuffer;)V @ warm following compilation request. [metaData=0000FFFF81A23078, startPC=0000FFFF8D9F9058]
21:16:45 [OUT] + (AOT warm) sun/nio/fs/NativeBuffers.releaseNativeBuffer(Lsun/nio/fs/NativeBuffer;)V @ 0000FFFF8D9F9058-0000FFFF8D9F9808 OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=12 j9m=0000000000123D40 bcsz=97 remote time=31515us mem=[region=256 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=66% queueTime=94775us
21:16:45 [OUT] #JITSTATE: t= 3020 JIT changed state from STARTUP to IDLE cSmpl= 0 iSmpl= 5 comp= 18 recomp= 0, Q_SZ= 0 CLP=OFF jvmCPU=0%
21:16:45 [OUT] (cold) Compiling jdk/internal/misc/Unsafe.freeMemory0(J)V OrdinaryMethod j9m=000000000004FBF0 remote t=3851 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7102 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=17 to server for method jdk/internal/misc/Unsafe.freeMemory0(J)V @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method jdk/internal/misc/Unsafe.freeMemory0(J)V @ cold following compilation request. [metaData=0000FFFF81A23338, startPC=0000FFFF832C33BC]
21:16:45 [OUT] + (cold) jdk/internal/misc/Unsafe.freeMemory0(J)V @ 0000FFFF832C33BC-0000FFFF832C34EC OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=1 j9m=000000000004FBF0 bcsz=3 JNI remote time=8045us mem=[region=256 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=25% queueTime=9371us
21:16:45 [OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I OrdinaryMethod j9m=0000000000158658 remote t=3861 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7102 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=18 to server for method openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I @ cold following compilation request. [metaData=0000FFFF81A23478, startPC=0000FFFF832C350C]
21:16:45 [OUT] + (cold) openj9/internal/tools/attach/target/IPC.notifyVm(Ljava/lang/String;Ljava/lang/String;IZ)I @ 0000FFFF832C350C-0000FFFF832C3678 OrdinaryMethod - Q_SZ=1 Q_SZI=1 QW=2 j9m=0000000000158658 bcsz=6 JNI remote time=3572us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=25% queueTime=3892us
21:16:45 [OUT] (cold) Compiling openj9/internal/tools/attach/target/IPC.closeSemaphore()V OrdinaryMethod j9m=0000000000158698 remote t=3861 compThreadID=6 memLimit=262144 KB freePhysicalMemory=7102 MB
21:16:45 [OUT] #JITServer: Client sending compReq seqNo=19 to server for method openj9/internal/tools/attach/target/IPC.closeSemaphore()V @ cold.
21:16:45 [OUT] #JITServer: Client successfully loaded method openj9/internal/tools/attach/target/IPC.closeSemaphore()V @ cold following compilation request. [metaData=0000FFFF81A235B8, startPC=0000FFFF832C3694]
21:16:45 [OUT] + (cold) openj9/internal/tools/attach/target/IPC.closeSemaphore()V @ 0000FFFF832C3694-0000FFFF832C37B8 OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=1 j9m=0000000000158698 bcsz=2 JNI remote time=1762us mem=[region=64 system=2048]KB compThreadID=6 CpuLoad=0%(0%avg) JvmCpu=25% queueTime=2936us
21:16:45 [OUT] #PERF: Time spent in compilation thread =2 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001A600, thread ID 3
21:16:45 [OUT] #PERF: Time spent in compilation thread =0 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001F000, thread ID 5
21:16:45 [OUT] #PERF: Time spent in compilation thread =1 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000018100, thread ID 2
21:16:45 [OUT] #PERF: Time spent in compilation thread =2 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000013700, thread ID 0
21:16:45 [OUT] #PERF: Time spent in compilation thread =1 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000015C00, thread ID 1
21:16:45 [OUT] #PERF: Time spent in compilation thread =1 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 000000000001CB00, thread ID 4
21:16:45 [OUT] #PERF: Time spent in compilation thread =66 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000021500, thread ID 6
21:16:45 [OUT] #PERF: Time spent in compilation thread =0 ms
21:16:45 [OUT] #INFO: Stopping compilation thread, vmThread pointer 0000000000036300, thread ID 15
21:16:45 [OUT] #JITServer: Sent clientSessionTerminate message
21:16:45 [OUT]
21:16:45 [OUT] Outputting previous test output
21:16:45 [OUT] Pre-checkpoint
21:16:45 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Wed Feb 07 02:16:39 UTC 2024, System.currentTimeMillis(): 1707272199556, System.nanoTime(): 2979736369489905
21:16:45 [OUT] pie: 456041: Error (criu/pie/restorer.c:1833): Unable to create a thread: 456043
21:16:45 [OUT] pie: 456041: Error (criu/pie/restorer.c:1968): Restorer fail 456041
21:16:45 [OUT] Error (criu/cr-restore.c:2536): Restoring FAILED.
21:16:45 [OUT]
21:16:45 [OUT] CAT VLOG FORCE PASS
21:16:45 [OUT] Removed test output files
21:16:45 [OUT] finished script
21:16:45 >> Success condition was found: [Output match: CHECKPOINT RESTORE: Ready for restore]
21:16:45 >> Success condition was found: [Output match: CAT VLOG FORCE PASS]
21:16:45 >> Failure condition was found: [Output match: Connected to a server]
21:16:45 >> Failure condition was not found: [Output match: User requested Java dump using]
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_aarch64_linux_OMR_testList_1/465 - cent8-aarch64-1 cmdLineTester_criu_jitserverAcrossCheckpoint_0
06:11:15 Testing: JITServer not explicitly enabled Post-Restore: Check no connection in Post-Restore Verbose Log
...
06:11:15 [OUT] pie: 1615453: Error (criu/pie/restorer.c:1966): Unable to create a thread: 1615467
06:11:15 [OUT] pie: 1615467: Error (criu/pie/restorer.c:704): Thread pid mismatch 1615467/1615466
06:11:15 [OUT] pie: 1615453: Error (criu/pie/restorer.c:2102): Restorer fail 1615453
06:11:15 [OUT] pie: 1615467: Error (criu/pie/restorer.c:766): Restorer abnormal termination for 1615453
06:11:15 [OUT] Error (criu/cr-restore.c:2547): Restoring FAILED.