RFR(XL): 8181917: Refactor UL LogStreams to avoid using resource area
Thomas Stüfe
thomas.stuefe at gmail.com
Fri Jul 21 12:23:46 UTC 2017
Great, thanks a lot Eric and Marcus for your review work!
Note I still have not yet time to run current iteration of the patch fully
thru jtreg. I did full jtreg tests on one of the earlier versions, so I do
not expect any surprises. Thank you for sponsoring!
Kind Regards, Thomas
On Fri, Jul 21, 2017 at 10:24 AM, Erik Helin <erik.helin at oracle.com> wrote:
> On 07/20/2017 09:11 AM, Thomas Stüfe wrote:
>
>> Hi all,
>>
>> after the last irc discussion with Erik here the new webrev with the
>> changes he requested:
>>
>> Full: http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-
>> ul-logstream/all.webrev.05/webrev/
>> Delta: http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-
>> ul-logstream/delta-04-to-05/webrev/
>>
>
> This looks good to me, Reviewed. Thank you Thomas for "hanging in there"
> with this big patch, really solid work!
>
> I built the change on windows (32bit too :P), Linux and AIX. I am
>> currently re-running jtreg tests on Linux, no issues so far.
>>
>
> I took the patch for a spin in our build system and it worked fine. I will
> sponsor this patch.
>
> Thanks,
> Erik
>
> The changes:
>>
>> - I removed all stray "Unconditional write?" comments I had used before
>> to mark sites which did logging unconditionally. Marcus had opened a follow
>> up bug report for that issue (https://bugs.openjdk.java.net
>> /browse/JDK-8182466), and I added the affected sites I found to the
>> comment section of that bug.
>>
>> - In g1GCPhaseTimes.cpp, I changed the logging code in
>> G1GCPhaseTimes::debug_phase() to use LogTarget instead of Log to be
>> consistent with G1GCPhaseTimes::trace_phase()
>>
>> - In the new LogStream implementation (logStream.cpp), I added temporary
>> variables in LogStream::LineBuffer::append() and
>> LogStream::LineBuffer::try_ensure_cap().
>>
>> - I also enlarge the line buffer a bit more aggressive. We now, once the
>> initial 64byte buffer is exhausted - enlarge by 256 bytes steps.
>>
>> - Finally, I renamed LineBuffer::ptr() to LineBuffer::buffer()
>> A note about memory consumption of the LogStream line buffer: I do not
>> think we need to overly worry about memory consumption, at least not if we
>> think the old solution was fine. Old solution was using stringStream, which
>> uses NEW_RESOURCE_ARRAY to enlarge the line buffer when exhausted. This is
>> resource area, so it *always* leaks the previous allocation, which is not
>> deallocated until the resource area stack is reset. Even worse, for larger
>> line lengths the growth strategy in stringStream() seems to be to just
>> enlarge by the requested amount, which means that every single write would
>> cause a reallocation and hence a new allocation of the underlying buffer
>> (see stringStream::write()). I am not 100% sure, this is just from
>> dry-reading the code.
>>
>> Kind Regards, Thomas
>>
>>
>>
>> On Mon, Jul 17, 2017 at 3:44 PM, Thomas Stüfe <thomas.stuefe at gmail.com
>> <mailto:thomas.stuefe at gmail.com>> wrote:
>>
>> Hi Eric,
>>
>> thank you for your review!
>>
>> new Webrev:
>> http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-
>> ul-logstream/all.webrev.04/webrev/
>> <http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor
>> -ul-logstream/all.webrev.04/webrev/>
>> delta to last:
>> http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-
>> ul-logstream/delta-03-to-04/webrev/
>> <http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor
>> -ul-logstream/delta-03-to-04/webrev/>
>>
>> Changes:
>>
>> - I changed the allocation function to handle the case where we
>> already reached the reasonable_max cap. You are right, in that case
>> reallocating is unnecessary.
>> - Also, added log_info() for that case as you suggested.
>> - Finally, added a fix to the LogStream gtest which somehow slipped
>> thru the last webrev.
>>
>> Changes are now rebased to the current tip.
>>
>> Thanks!
>>
>> ..Thomas
>>
>> On Fri, Jul 14, 2017 at 12:36 PM, Erik Helin <erik.helin at oracle.com
>> <mailto:erik.helin at oracle.com>> wrote:
>>
>> On 07/13/2017 08:46 AM, Thomas Stüfe wrote:
>>
>> Hi Erik!
>>
>>
>> On Mon, Jul 10, 2017 at 11:40 AM, Erik Helin
>> <erik.helin at oracle.com <mailto:erik.helin at oracle.com>
>> <mailto:erik.helin at oracle.com
>>
>> <mailto:erik.helin at oracle.com>>> wrote:
>>
>> Hi Thomas,
>>
>> On 06/30/2017 08:32 PM, Thomas Stüfe wrote:
>>
>> Hi Eric,
>>
>> thank you for the review!
>>
>> New
>> Version:
>> http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-
>> ul-logstream/all.webrev.03/webrev/
>> <http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor
>> -ul-logstream/all.webrev.03/webrev/>
>> <http://cr.openjdk.java.net/~s
>> tuefe/webrevs/8181917-refactor-ul-logstream/all.webrev.03/webrev/
>> <http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor
>> -ul-logstream/all.webrev.03/webrev/>>
>>
>>
>> I think you still have a problem with "runaway" loggers
>> in this version:
>>
>> +// try_ensure_cap tries to enlarge the capacity of the
>> internal buffer
>> +// to the given atleast value. May fail if either OOM
>> happens or
>> atleast
>> +// is larger than a reasonable max of 1 M. Caller must
>> not assume
>> +// capacity without checking.
>> +void LogStream::LineBuffer::try_ensure_cap(size_t
>> atleast) {
>> + assert(_cap >= sizeof(_smallbuf), "sanity");
>> + if (_cap < atleast) {
>> + const size_t reasonable_max = 1 * M;
>> + size_t newcap = align_size_up(atleast + 64, 64);
>> + assert(_cap <= reasonable_max, "sanity");
>> + // Cap out at a reasonable max to prevent runaway
>> leaks.
>> + if (newcap > reasonable_max) {
>> + newcap = reasonable_max;
>> + }
>> +
>> + char* const newbuf = (char*) os::malloc(newcap,
>> mtLogging);
>> + if (newbuf == NULL) { // OOM. Leave object
>> unchanged.
>> + return;
>> + }
>> + if (_pos > 0) { // preserve old content
>> + memcpy(newbuf, _buf, _pos + 1); // ..including
>> trailing zero
>> + }
>> + if (_buf != _smallbuf) {
>> + os::free(_buf);
>> + }
>> + _buf = newbuf;
>> + _cap = newcap;
>> + }
>> + assert(_cap >= atleast, "sanity");
>> +}
>>
>> with the above code, even though _cap > reasonable_max,
>> you will
>> always allocate newbuf with os::malloc. For debug
>> builds, we are
>> fine, since the JVM will assert on _cap <=
>> reasonable_max, but for
>> product builds we are not. Would it be better to first
>> check if _cap
>> == reasonable_max? As in the following snippet:
>>
>> void LogStream::LineBuffer::try_ensure_cap(size_t
>> atleast) {
>> if (_cap < atleast) {
>> const size_t reasonable_max = 1 * M;
>> if (_cap == reasonable_max) {
>> // max memory used, "die" in debug builds, log
>> in product builds
>> log_warning(logging)("Max memory used for
>> message: %s\n", _buf);
>> ShouldNotReachHere();
>> return;
>> }
>>
>> size_t newcap = align_size_up(atleast + 64, 64);
>> if (newcap > reasonable_max) {
>> newcap = reasonable_max;
>> }
>> char* const newbuf = (char*) os::malloc(newcap,
>> mtLogging);
>> // rest of logic
>> }
>> }
>>
>> Thanks,
>> Erik
>>
>>
>> I'm not sure I understand. Are you concerned that _cap would
>> grow beyond reasonable_max - because I do not see a way this
>> could happen. Or do you want to also treat the *attempt* to
>> grow the _cap beyond reasonable_max as a loggable offence?
>>
>>
>> What I am trying to say is that with your current patch, even if
>> _cap == reasonable_max, you will still allocate a new 1M buffer,
>> copy all the chars over, and the free the old one. My proposal
>> simply skips the allocation, copying and freeing if _cap ==
>> reasonable_max. The result will be the same, just less stress on
>> malloc.
>>
>> If the latter, I am not sure about logging. If this is an
>> error which may happen at a customer site without popping up
>> first in inhouse-tests (which it conceivably is, because
>> logging is very content dependent), I would rather hide the
>> error in production code instead of flooding stderr with
>> tons of log warnings or crashing with a guarantee, no?
>>
>>
>> I see what you mean, but perhaps log_info(logging) at least? I
>> want to be able to discover if this happens in production, for
>> example if a customer complains about truncated logs. A
>> log_info(logging) will only be printed if -Xlog:logging=info is
>> specified on the command-line.
>>
>> Thanks,
>> Erik
>>
>> ..Thomas
>>
>>
>>
>>
>>
More information about the hotspot-dev
mailing list