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

[Thomas Stüfe]

On Mon, Jun 19, 2017 at 3:49 PM, Marcus Larsson <marcus.larsson at oracle.com>
wrote:

>
>
> 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
> > 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> 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/
>>>
>>>
>>> (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();
>
> is really equivalent to
>
> Log(,,) log;
> log.info("<");
> log.info("br");
> 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() (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.
>
>
>
Ah, ok!

Maybe this is something to ponder. I think your original idea was that
LogStream's only purpose was just to be plugged into outputStream*
compatible pre-existing print functions, right? But it is so darn useful,
e.g. for assembling lines piece-wise. So I think people use it way more
than expected.

Maybe somewhere in the future, LogStream could be the only interface for
printing to UL... ? This would certainly simplify the UL API and make our
(SAPs) developers very happy, who constantly complain about the problem
that it is difficult to grep for UL log sites, because they can come in so
many forms.


>
>
>
>>
>> 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.
>>>
>>>
>> 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/
>>>
>>> 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/
>>>
>>>
>>>   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
>>
>>
>>
>
>