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

[Thomas Stüfe]

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?



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