Write out newline character after the message in verbose output

[fjeremic]

The TR_VerboseLog::writeLine* APIs currently write the newline
character before the message being printed which is non-conventional.
Typically the expectation of a user is that any API that outputs
newline characters outputs them at the end, examples from various
languages in [1] [2] [3], and there are numerous other examples.

The reason we are making this change is because other components in OMR
will expect to be writing at the start of a newline, whether that be
stdout, stderr, or a file. The verbose log not adhering to this
expectation yields in messages getting printed one after another which
is not desirable.

[1] https://docs.python.org/3/library/functions.html#print
[2] https://docs.oracle.com/javase/8/docs/api/java/io/PrintStream.html#println-java.lang.String-
[3] https://docs.microsoft.com/en-us/dotnet/api/system.console.writeline?view=netframework-4.8#System_Console_WriteLine_System_String_

Signed-off-by: Filip Jeremic [email protected]

[fjeremic]

Suggesting @dsouzai for review.

[fjeremic]

@genie-omr build all

[dsouzai]

The change looks reasonable to me. However, it is worth pointing out its impact.

I think I know the reason why the newline was put in the beginning of the line. It's not a good one lol, but essentially, in OpenJ9, there's times when the vlog data is written out as

TR_VerboseLog::vlogAcquire();
...
TR_VerboseLog::write();
...
TR_VerboseLog::vlogRelease();

and so to reduce the "overhead" of writing out the newline explicitly, the writeLine and writeLineLocked would "guarantee" that you'd always get a new line.

Searching through the code, I also found this [1]

TR_VerboseLog::vlogAcquire();
TR_VerboseLog::writeLine(..);
...
TR_VerboseLog::write(..);
...
TR_VerboseLog::vlogRelease();

Notice how we do writeLine first and then do a bunch of writes. With your change, we'll have to update all those locations in OpenJ9 and possibly OMR that assume that the newline is printed out at the start.

[1] https://github.com/eclipse/openj9/blob/2054d856333aab1b46166f989e1ee904622b7930/runtime/compiler/control/CompilationThread.cpp#L5486-L5514

[fjeremic]

Searching through the code, I also found this [1]

TR_VerboseLog::vlogAcquire();
TR_VerboseLog::writeLine(..);
...
TR_VerboseLog::write(..);
...
TR_VerboseLog::vlogRelease();

Thanks for pointing this out. To fix such a location we would just do:

TR_VerboseLog::vlogAcquire();
TR_VerboseLog::write(..);
...
TR_VerboseLog::write(..);
...
TR_VerboseLog::writeLine(..);
TR_VerboseLog::vlogRelease();

Is this correct? I have no problem going through all the locations and fixing this up so we have conventional printing and not catch users off guard. Do you think this is feasible?

[dsouzai]

Is this correct?

Yeah looks correct.

Do you think this is feasible?

Yeah i don't think there's too many locations where we do this. Probably could just grep for TR_VerboseLog::vlogAcquire or TR_VerboseLog::writeLine for these few outliers; the majority of data is written to the vlog via TR_VerboseLog::writeLineLocked.

[fjeremic]

Uuuups. Accidentally clicked close button. Meant to say thanks for the feedback and I'll turn this into WIP: until we address this.

[fjeremic]

@dsouzai issues have been addressed. Ready for another review.

[andrewcraik]

@mpirvu perhaps you would take a look since you are probably one of the biggest verbose log users?

[dsouzai]

lgtm

[mpirvu]

LGTM. Not directly related to this PR, I have an inline question about some write statements without a preceding lock.

[fjeremic]

@genie-omr build all

[andrewcraik]

@fjeremic this looks like it should be close to being ready - do we need to warn/help migrate any downstream consumers like OpenJ9 to avoid breaking the logging?

[fjeremic]

do we need to warn/help migrate any downstream consumers like OpenJ9 to avoid breaking the logging?

Yes, this is done in eclipse-openj9/openj9#9391.

[fjeremic]

Rebased on the latest branches and I went ahead and generated builds using this PR and compared how the verbose log looks before and after. I carefully analyzed all output of verbose={*} and could not find a difference in any of the output following this change.

[fjeremic]

@genie-omr build all

[fjeremic]

Any committer want to sign up to shepherd this one?

[fjeremic]

@0xdaryl @Leonardo2718 any takers for this one perhaps (and the OpenJ9 change)?