Verbose GC CRIU Support

[RSalman]

Files opened by Verbose GC must be excluded from the CRIU dump. Opened logs can be problematic as the restore file validation can fail if the logs change between checkpoint and restore (e.g. file contents/metadata changed or file not available at restore time, which is typical for CRIU use cases). Hence, Verbose GC file writers/streams must be closed prior to creating a check point image and reopened for restore.

• Introduced openStream for Verbose Writers
  • Used to openFile associated with file writers , only required for buffered and synchronous file logging, base class MM_VerboseWriterFileLogging
• Introduced openStreams for Verbose Manager
  • To walk the set of verbose writers and open streams (complementary to existing closeStreams routine)
• Introduced prepareForCheckpoint and reinitializeForRestore for Verbose Manager
  • Calls Manager's Close/OpenStreams

Signed-off-by: Salman Rana salman.rana@ibm.com

[RSalman]

Please review @amicic @dmitripivkine

cc @tajila

[RSalman]

Other verbose GC related CRIU work (e.g Reprinting the Initialized header) will be done in subsequent PRs. This PR only addresses the immediate issues with VerboseGC + CRIU.

[RSalman]

openFile routines updated to account for a for restore use cases. During restore, If a file to be opened already exists, verbose gc appends output rather than truncating the file first as is done for existing uses.

This seems like the correct approach to me, but I can also see verbose restore act as a fresh init (e.g truncate existing file and reinit params for rotation logs).

With the approach implemented, in a rotating log scenario, we would start from the same file opened at the time of checkpoint. For example, if we're rotating between 4 logs

-Xverbosegclog:verbose.log,4,10 

verbose.log.001
verbose.log.002
verbose.log.003 <-- checkpoint/restore
verbose.log.004

and vgc is on log 3 at the time of checkpoint, then restore will start at 3 again and append to that. If at the time of restore, none of the logs are present it will create log 3

[amicic]

openFile routines updated to account for a for restore use cases. During restore, If a file to be opened already exists, verbose gc appends output rather than truncating the file first as is done for existing uses.

This seems like the correct approach to me, but I can also see verbose restore act as a fresh init (e.g truncate existing file and reinit params for rotation logs).

With the approach implemented, in a rotating log scenario, we would start from the same file opened at the time of checkpoint. For example, if we're rotating between 4 logs

-Xverbosegclog:verbose.log,4,10 

verbose.log.001
verbose.log.002
verbose.log.003 <-- checkpoint/restore
verbose.log.004

and vgc is on log 3 at the time of checkpoint, then restore will start at 3 again and append to that. If at the time of restore, none of the logs are present it will create log 3

What about a scenario where VGC was enabled at checkpoint VM, but files were physically removed before doing a restore.... will everything work as if VGC was never enabled, what will be the file index (in your example)?

[amicic]

and vgc is on log 3 at the time of checkpoint, then restore will start at 3 again and append to that. If at the time of restore, none of the logs are present it will create log 3

What about a scenario where VGC was enabled at checkpoint VM, but files were physically removed before doing a restore.... will everything work as if VGC was never enabled, what will be the file index (in your example)?

After re-reading, seems like you've already had an answer to my question.

Anyhow, I'm a bit more inclined that

• we don't append to the last file if one was present (but continue with the next index),
• and if none was present and rotating logs were originally specified, the first index should be 1.

Also restore VM should be able to override rotating log parameters.

@dmitripivkine and @tajila might have their own opinion....

In short, I'm just looking from a perspective that a user of a restore VM has no interest in the past (that there was some checkpoint VM and how it was configured etc).

[dmitripivkine]

I think common behaviour would be GC verbose log has not been requested for snapshot creation but might be set up at restore. It means general expectation is GC verbose log after restore is brand new (initial reset), even it was requested for snapshot creation. Also it means GC verbose log options should be taken at restore. I think we should treat restore as a "new" JVM run from GC verbose log management point of view.
There is possibility when customer might specify options for snapshot as request to apply them for any restore run. If we want to support this case we need to verify compatibility and blend together options provided for snapshot and requested at restore. I am not sure we want this complexity for first cut.
@tajila What do you think?

[tajila]

I think common behaviour would be GC verbose log has not been requested for snapshot creation but might be set up at restore. It means general expectation is GC verbose log after restore is brand new (initial reset), even it was requested for snapshot creation. Also it means GC verbose log options should be taken at restore. I think we should treat restore as a "new" JVM run from GC verbose log management point of view.

From a user perspective I think the most useful data would be a verbose log that begins at restore. So agree with the comment above.

That being said we should also be compatible with modes where verbose is requested from start-up. In this case I think it should capture both snapshot and restore data. If there are issues with elapsed time related data point we have ways to correct that.

[RSalman]

Discussed this with @amicic, we decided that both (checkpoint and restore) set of verbose logs should be kept only if the user doesn't specify file name, in which case the file name will default to verbosegc.%Y%m%d.%H%M%S.%pid.txt, this file name should be regenerated for restore, hence 2 separate files. On the other hand, if the file name is set and the file is already present at restore time, we simply truncate and overwrite it, similar behaviour as starting JVM with old log around .

[RSalman]

When we have the capability to set a separate set of options for restore, the user should be able to specify a new verbose file name, different from the one inited at checkpoint run. This would be another way to keep the both set of logs.

[RSalman]

set of verbose logs should be kept only if the user doesn't specify file name, in which case the file name will default to verbosegc.%Y%m%d.%H%M%S.%pid.txt, this file name should be regenerated for restore

This PR doesn't implement this, I'm deferring this work, will revisit it when

we have the capability to set a separate set of options for restore, the user should be able to specify a new verbose file name, different from the one inited at checkpoint run

[amicic]

looks good. approving, although a couple of minor comments should be addressed

[RSalman]

Sorry, I missed the latest review comments, they've been addressed now.

@babsingh could you please proceed with review/merge

[RSalman]

Please hold off on merging. Internal Axxon builds have a compile issue with these changes, looking into it.

These changes are good, it seems to be OpenJ9 side of things.

[babsingh]

jenkins build all

[babsingh]

https://dev.azure.com/eclipse-omr/omr/_build/results?buildId=7014&view=logs&j=aa2fd561-a338-5537-45ee-49ae22aea958&t=20ff6471-47a7-5631-6842-540dac3e3fb4

Known failure: #6516

[babsingh]

re #6850 (comment): @RSalman can you confirm that there are no other failures in the failed OSX PR build?

[RSalman]

re #6850 (comment): @RSalman can you confirm that there are no other failures in the failed OSX PR build?

Yup, not seeing anything other than the known socket test:

2023-01-21T00:21:13.1470330Z 98% tests passed, 1 tests failed out of 47
2023-01-21T00:21:13.1471310Z 
2023-01-21T00:21:13.1472370Z Total Test time (real) = 220.19 sec
2023-01-21T00:21:13.1473060Z 
2023-01-21T00:21:13.1474650Z The following tests FAILED:
2023-01-21T00:21:13.1477050Z 	 32 - porttest (Failed)

2023-01-21T00:19:19.7220410Z 32: [----------] 19 tests from PortSockTest
2023-01-21T00:19:20.8134940Z 32: /Users/runner/work/1/s/fvtest/porttest/omrsockTest.cpp:1209: Failure
2023-01-21T00:19:20.8139130Z 32:       Expected: rc
2023-01-21T00:19:20.8140340Z 32:       Which is: 1
2023-01-21T00:19:20.8141390Z 32: To be equal to: 2
2023-01-21T00:19:20.8142620Z 32: [  FAILED  ] PortSockTest.poll_functionality_basic (1087 ms)
2023-01-21T00:19:20.8143830Z 32: /Users/runner/work/1/s/fvtest/porttest/omrsockTest.cpp:51: Failure
2023-01-21T00:19:20.8146260Z 32:       Expected: privateOmrPortLibrary->sock_bind(privateOmrPortLibrary, *serverSocket, serverSockAddr)
2023-01-21T00:19:20.8148020Z 32:       Which is: -506
2023-01-21T00:19:20.8156350Z 32: To be equal to: 0
2023-01-21T00:19:20.8157840Z 32: /Users/runner/work/1/s/fvtest/porttest/omrsockTest.cpp:1259: Failure
2023-01-21T00:19:20.8160160Z 32:       Expected: privateOmrPortLibrary->sock_accept(privateOmrPortLibrary, serverSocket, &connectedServerSockAddr, &connectedServerSocket)
2023-01-21T00:19:20.8161920Z 32:       Which is: -20
2023-01-21T00:19:20.8162990Z 32: To be equal to: 0
2023-01-21T00:19:20.8164100Z 32: [  FAILED  ] PortSockTest.poll_functionality_many_sockets (1 ms)
2023-01-21T00:19:20.8170180Z 32: [----------] 19 tests from PortSockTest (1093 ms total)
2023-01-21T00:19:20.8171680Z 32: 
2023-01-21T00:19:20.8173760Z 32: [==========] 246 tests from 21 test cases ran. (103632 ms total)
2023-01-21T00:19:20.8174980Z 32: [  PASSED  ] 244 tests.
2023-01-21T00:19:20.8176040Z 32: [  FAILED  ] 2 tests, listed below:
2023-01-21T00:19:20.8177140Z 32: [  FAILED  ] PortSockTest.poll_functionality_basic
2023-01-21T00:19:20.8178310Z 32: [  FAILED  ] PortSockTest.poll_functionality_many_sockets
2023-01-21T00:19:20.8179370Z 32: 
2023-01-21T00:19:20.8180340Z 32:  2 FAILED TESTS
2023-01-21T00:19:20.8181390Z 32:   YOU HAVE 3 DISABLED TESTS
2023-01-21T00:19:20.8184090Z 32: 
2023-01-21T00:19:20.8274110Z 32: Some textSome text
2023-01-21T00:19:20.8275660Z 46/47 Test #32: porttest ............................***Failed  103.80 sec