RFR: JDK-8266503: [UL] Make Decorations safely copy-able and reduce their size

[Volker Simonis]

On Wed, 5 May 2021 08:09:35 GMT, Thomas Stuefe <stuefe at openjdk.org> wrote:

> This patch reduces the size of UL `LogDecorations` by about 85% (from 368 -> 56 bytes on Linux x64). This matters in the context of asynchronous logging in UL where we plan to keep a buffer containing log messages, including decorations, for asynchronous printing.
> 
> As a side effect, it makes the LogDecorations object safe to copy with trivial assignment constructors and operators (which it had not been before).
> 
> As another side effect, the 256-char-for-all-decorators limit has been removed with this patch.
> 
> What the patch does:
> 
> In LogDecorations, we resolve the values of the given decorators ("uptime", "tid" etc) and print them in human-readable format. Before this patch, the class LogDecorations stored the printed decorators in an internal (limited, fixed-sized) buffer. This is inefficient since this takes much more memory than storing the binary data before printing them.
> 
> So this patch separates the decorator value resolving from the printing. It stores the resolved values in binary form and only prints them when needed. Since a decorations object is only printed once this is fine. No need to cache the formatted text.
> 
> *Please Note that this patch includes the fix for JDK-8266536: "Provide a variant of os::iso8601_time which works with arbitrary timestamps" which is in a separate PR (https://github.com/openjdk/jdk/pull/3869) - so please ignore all the iso6801 stuff. It also contains a fix for the broken harfbuzz build.*
> 
> Testing:
> - gtests, manually
> - jtreg runtime/logging, manually
> - SAP nightlies ran fine, but since then the tests changed, will run them again tonight

Hi Thomas,

your change looks good and I like it :)

Am I right that you've changed the 256-char-for-all-decorators limit to a 255-char limit for a single decorator (which is obviously much better)?

Find my other comments inline.

Thank you and best regards,
Volker

src/hotspot/share/logging/logDecorations.cpp line 92:

> 90: void LogDecorations::print_time_decoration(outputStream* st) const {
> 91:   char buf[29];
> 92:   st->print_raw(os::iso8601_time(_millis, buf, sizeof(buf), false));

You have no error handling here. `os::iso8601_time()` can return `NULL` and `print_raw()` will call `strlen(NULL)` which will crash. Do something like:

char *result = os::iso8601_time(_millis, buf, sizeof(buf), false);
st->print_raw(result == NULL ? "-1" : result);


Notice that the previous implementation was buggy as well. If `os::iso8601_time()` returned `NULL` it would have called `ASSERT_AND_RETURN(-1, pos)` which would have overwritten the last character in `pos` for non-product builds. It could also lead in a buffer-underflow if `pos` pointed to the very first character of an array.

src/hotspot/share/logging/logDecorations.cpp line 97:

> 95: void LogDecorations::print_utctime_decoration(outputStream* st) const {
> 96:   char buf[29];
> 97:   st->print_raw(os::iso8601_time(_millis, buf, sizeof(buf), true));

Same as for `LogDecorations::print_time_decoration()`.

src/hotspot/share/logging/logDecorations.cpp line 134:

> 132: void LogDecorations::print_tags_decoration(outputStream* st) const {
> 133:   char tmp[255];
> 134:   _tagset.label(tmp, sizeof(tmp)); // Todo: add a LogTagSet::label(outputStream*) to avoid this copy step

Yes, that would be desirable and probably not too hard :)

Otherwise you'll might have an uninitialized `tmp` array if the first tag doesn't fir into the array and  `LogTagSet::label()` returns `-1`. I understand that that's more a theoretical problem because at least one tag should always fir within 255 characters :)

src/hotspot/share/logging/logDecorations.hpp line 42:

> 40:   const jlong _nanos;             // for "timenanos"
> 41:   const double _elapsed_seconds;  // for "uptime", "uptimemillis", "uptimenanos"
> 42:   const int _pid;                 // for "pid"

You can use the same trick for `_pid` (i.e. make it static and resolve it a single time) like for `_host_name`. That will save you another 4 bytes for the size of `LogDecorations`.

test/hotspot/gtest/logging/test_logDecorations.cpp line 35:

> 33: 
> 34: TEST_VM(LogDecorations, level) {
> 35:   char buf[1024];

Minor nit: in `LogFileStreamOutput::write_decorations()` you are using a temporary buffer of 255 charaters so you should use the same buffer size for testing. Ideally you can make that a constant or macro which can be reused here in the tests.

-------------

Changes requested by simonis (Reviewer).

PR: https://git.openjdk.java.net/jdk/pull/3874