RFR: 8256256: UL should not use heap allocation for output string [v2]

[Thomas Stuefe]

On Wed, 18 Nov 2020 04:32:18 GMT, Yumin Qi <minqi at openjdk.org> wrote:

>> Hi, Please review
>>   Unified Logging uses 512 bytes buffer on stack for printing out message, above that will allocate heap for extra space needed. This may potentially may cause a circulation when we log the heap allocation and the log message is over 512. The max logging buffer size now is increased to 4096 and above that, output will be truncated.
>> 
>> Tests: tier1,tier4
>
> Yumin Qi has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Use malloc/free for large log message buffer

Hi Yumin,

thanks. Sorry if this seems bikesheddy - I have a proposal about how to print in case of OOM, see below. Feel free to ignore it as you see fit, the patch is already good in its current form.

Cheers, Thomas

src/hotspot/share/logging/logTagSet.cpp line 130:

> 128:     size_t newbuf_len = prefix_len + ret + 1;
> 129:     char* newbuf = (char*)::calloc(newbuf_len, sizeof(char));
> 130:     if (newbuf == nullptr) {

Thinking about this, I see now another advantage of this patch: I don't like UL to go silent because of native OOM.

About that, how about instead of printing to tty, we do this instead:

if (newbuf == nullptr) {
  log(level, buf);
  log(level, "(Truncated, native OOM.");
  return;
}
instead? 

This would first print the truncated line, still in the static buffer, to the UL log - so we miss as little information as possible - followed by a truncation marker to show the reader that we truncated.

(Alternatively we could stamp something like "..(truncated)" to the end of the static buffer and just print once).

This proposal has one little beauty spot: in case the prefix did overflow the static buffer, we end up in line 124, and print the log line without prefix. I think that would be totally fine. The message content is more important than the prefix. Its a very rare case. But should that bother you, you could "dry print" at line 124:

  } else {
    // Buffer too small. Just call printf to find out the length for realloc below.
    // vv "dry-print" to find out length but dont change buffer content
    ret = os::vsnprintf(NULL, 0, fmt, args);
  }

which would leave the buffer with the truncated prefix intact.

(Side note, looking at logPrefix.hpp, I see that the code there asserts in case of buffer overflow. So why do we even handle it here. But since this is all templatized to oblivion I may be missing something).

Thanks Thomas

src/hotspot/share/logging/logTagSet.cpp line 129:

> 127:   if ((size_t)ret >= sizeof(buf)) {
> 128:     size_t newbuf_len = prefix_len + ret + 1;
> 129:     char* newbuf = (char*)::calloc(newbuf_len, sizeof(char));

Can you precede this with a little comment please: 
`// We use raw ::malloc to prevent circularities`

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

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