RFR: 8146793: logStream::write re-formats string

[Kim Barrett]

On Jan 19, 2016, at 6:55 PM, John Rose <john.r.rose at oracle.com> wrote:
> 
> On Jan 12, 2016, at 7:25 AM, Kim Barrett <kim.barrett at oracle.com> wrote:
>> 
>> Please review this fix to some problems in logStream::write and the
>> facilities used to implement it.
>> 
>> 1. logStream::write no longer attempt to reformat the already
>> formatted accumulated output.  [Fixing this led to the discovery of
>> the issues below.]
>> 
>> 2. Fixed Log<>::vwrite test for overflow of the initial buffer, which
>> didn't allow for the trailing NUL.
>> 
>> 3. Fixed Log<>::vwrite to copy the va_list arguments before first
>> format attempt and use that copy if a second format attempt is
>> needed, rather than incorrectly reusing the original (now possibly
>> modified) va_list.
>> 
>> CR:
>> https://bugs.openjdk.java.net/browse/JDK-8146793
>> 
>> Webrev:
>> http://cr.openjdk.java.net/~kbarrett/8146793/webrev.00/
>> 
>> Testing:
>> JPRT
>> Locally verified printing a "%" to a log stream works, by running
>> TestPrintGCDetailsVerbose (after fixing it for JDK-8146728).
> 
> The previous logging facility includes, at the corresponding cut point,
> optimizations for no-% and %s-only format strings, to avoid trips
> through the sprintf engine and needless copying.  Please see:
> 
> http://hg.openjdk.java.net/jdk9/jdk9/hotspot/file/tip/src/share/vm/utilities/ostream.cpp#l90
> 
> In other words, let's not do the buffer-buffer rhumba if we don't need to.
> 
> This is an excellent moment to incorporate those optimizations
> in the new logging system.

It doesn't look like the logging code has anything like that. I think
it would need to be an addition to Log<>::vwrite. [I'd thought about
trying to improve this path from logStream some way, but decided I was
mostly interested in fixing the crashing bug, and could leave
optimizing this path to others if needed.] I'll file an RFE for this.

> Nice catches on the va_copy and buffer overrun.  How did you find
> the log_func(foo) instead of log_func("%s", foo)?  Please tell me it
> was a gcc warning; if not then we have some software rot going on.

Sorry, but I found it the hard way, via a crash (I think it was the
assert in Log<>::vwrite). logStream::_log_func is a function pointer.
Maybe we can attach an ATTRIBUTE_PRINTF to the data member and/or to
the logStream constructor argument? And maybe that would produce the
desired warnings? I think attaching that attribute would have
generated a warning for the non-literal format string being passed to
_log_func.

> Reviewed.

Thanks.