RFR(XL): 8181917: Refactor UL LogStreams to avoid using resource area
Thomas Stüfe
thomas.stuefe at gmail.com
Thu Jul 20 07:11:07 UTC 2017
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/
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.
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>
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/
> delta to last: 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>
> 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>> 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/>
>>>
>>>
>>> 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