RFR(XL): 8181917: Refactor UL LogStreams to avoid using resource area

[Marcus Larsson]

On 2017-06-19 15:47, Thomas Stüfe wrote:
>
>
> On Mon, Jun 19, 2017 at 3:37 PM, Marcus Larsson 
> <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>
>
>     On 2017-06-19 15:16, Thomas Stüfe wrote:
>>     Hi Marcus,
>>
>>     On Mon, Jun 19, 2017 at 2:30 PM, Marcus Larsson
>>     <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>>
>>         Hi Thomas,
>>
>>         Thanks for your effort on this, great work!
>>
>>
>>         On 2017-06-18 09:30, Thomas Stüfe wrote:
>>>
>>>         --
>>>
>>>         http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-ul-logstream/callsite-changes.webrev.00/webrev/
>>>         <http://cr.openjdk.java.net/%7Estuefe/webrevs/8181917-refactor-ul-logstream/callsite-changes.webrev.00/webrev/>
>>>
>>
>>         (Although this is a pre-existing issue, it might be a good
>>         opportunity to clean it up now.)
>>         In file loaderConstraints.cpp, class LoaderConstraintTable,
>>         for functions purge_loader_constraints(), add_entry(),
>>         check_or_update(), extend_loader_constraint() and
>>         merge_loader_constraints():
>>         A LogStream is created, but only ever used for print_cr():s,
>>         which sort of defeats its purpose. It would be much simpler
>>         just to use the LogTarget directly. This is actually what's
>>         done for the converted log_ldr_constraint_msg().
>>
>>
>>     I found some of those too, but can a sequence of
>>     LogStream::print() calls really be replaced by a sequence of
>>     LogTarget::print()/LogImpl::print()?
>>
>>     LogStream buffers all input till newline is encountered, whereas
>>     LogTarget::print (LogImpl::vwrite()->LogTagSet::vwrite()...) will
>>     print one log line for each invocation, no?
>
>     Indeed they can. There's nothing special going on in LogStreams to
>     make the lines grouped in any way. Each print_cr on a LogStream is
>     equivalent to a LogImpl::write call.
>
>
> Yes, but what about print() (without cr?) Maybe I am just slow...
>
> A sequence of
>
> Logstream ls;
> ls.print("<");
> ls.print("br");
> ls.print(">");
> ls.cr <http://ls.cr>();
>
> is really equivalent to
>
> Log(,,) log;
> log.info <http://log.info>("<");
> log.info <http://log.info>("br");
> log.info <http://log.info>(">\n");
>
> ?
>
> I would have thought that only LogStream::cr() will cause the stream 
> to be flushed, hence it will write "<br>", whereas all log.info 
> <http://log.info>() (or LogTarget::print()) calls would be logged as 
> separate lines?

No you're right. I was just talking about cases where there's *only* 
print_cr() calls, not when there are print() calls mixed in.

>
>
>>
>>
>>         A similar but worse issue is present in sharedPathsMiscInfo.cpp:
>>         Here, a LogStream is used to print incomplete lines without
>>         any CR at the end. These messages will never be logged. Also,
>>         the use of a stream here is unnecessary as well.
>>
>>
>>     Yes, you are right, and it is also not enclosed in is_enabled().
>>     Also, seems this coding is never tested, otherwise the assert in
>>     ~LogStreamBase() would have fired because of missing stream flush().
>
>     True. The old code would never had a chance to hit the assert due
>     to the resource allocation destructor problem, but now we should
>     be able to hit it with proper testing.
>
>>         In compactibleFreeListSpace.cpp:
>>
>>         2200       ResourceMark rm;
>>
>>         It should be safe to remove this ResourceMark.
>>
>>
>>     Right.
>>
>>>         These are the - mostly mechanical - changes to the many
>>>         callsites. Most of these changes follow the same pattern. A
>>>         code sequence using "xxx_stream()" was split into
>>>         declaration of LogTarget or Log (usually the former), an
>>>         "is_enabled()" query and declaration of LogStream on the
>>>         stack afterwards. This follows the principle that the
>>>         logging itself should be cheap if unused: the declaration of
>>>         LogTarget is a noop, because LogTarget has no members. Only
>>>         if is_enabled() is true, more expensive things are done,
>>>         e.g. initializing the outputStream object and allocating
>>>         ResourceMarks.
>>>
>>>         Note that I encountered some places where logging was done
>>>         without enclosing "is_enabled()" query - for instance, see
>>>         gc/g1/heapRegion.cpp, or cms/compactibleFreeListSpace.cpp.
>>>         As far as I understand, in these cases we actually do print
>>>         (assemble the line to be printed), only to discard all that
>>>         work in the UL backend because logging is not enabled for
>>>         that log target. So, we pay quite a bit for nothing. I
>>>         marked these questionable code sections with an "//
>>>         Unconditional write?" comment and we may want to fix those
>>>         later in a follow up issue?
>>
>>         That sounds good to me. I found more sites where the logging
>>         is unconditional (compactibleFreeListSpace.cpp,
>>         parOopClosures.inline.hpp, g1RemSet.cpp), but we should fix
>>         them all as a separate issue. I filed
>>         https://bugs.openjdk.java.net/browse/JDK-8182466
>>         <https://bugs.openjdk.java.net/browse/JDK-8182466>.
>>
>>
>>     Ok! I'll add whatever I find as comments.
>>
>>>
>>>         --
>>>
>>>         http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-ul-logstream/api-changes.webrev.00/webrev/
>>>         <http://cr.openjdk.java.net/%7Estuefe/webrevs/8181917-refactor-ul-logstream/api-changes.webrev.00/webrev/>
>>>
>>>         The API changes mostly are simplifications. Before, we had a
>>>         whole hierarchy of LogStream... classes whose only
>>>         difference was how the backing memory was allocated. Because
>>>         we now always use C-Heap, all this can be folded together
>>>         into a single simple LogStream class which uses Cheap as
>>>         line memory. Please note that I left
>>>         "LogStreamNoResourceMark" and "LogStreamCHeap" for now and
>>>         typedef'ed them to the one single LogStream class; I will
>>>         fix those later as part of this refactoring.
>>
>>         Looks good to me, as long as we get rid of the typedefs too
>>         eventually. :)
>>
>>
>>     Sure!
>>
>>
>>>
>>>         --
>>>
>>>         http://cr.openjdk.java.net/~stuefe/webrevs/8181917-refactor-ul-logstream/logstream-optimization.webrev.00/webrev/
>>>         <http://cr.openjdk.java.net/%7Estuefe/webrevs/8181917-refactor-ul-logstream/logstream-optimization.webrev.00/webrev/>
>>
>>         56 // Prevent operator new for LogStream.
>>         57 // static void* operator new (size_t);
>>         58 // static void* operator new[] (size_t);
>>         59
>>
>>         Should these be uncommented?
>>
>>
>>     Oh, right. I have to play a bit more, was unsure whether that
>>     coding actually does what I want it to do, prevent
>>     ResourceObj::operator new from running. Will test a bit more.
>
>     Alright, sounds good.
>
>     Marcus
>
>>
>>         Thanks again,
>>         Marcus
>>
>>
>>     Thanks for your review! I'll prepare an updated patch.
>>
>>     ..Thomas
>>
>
>