stringStream in UL and nested ResourceMarks
Thomas Stüfe
thomas.stuefe at gmail.com
Sun Jun 18 07:40:17 UTC 2017
Hi Eric, thanks for the review!
I reposted the next iteration as a first "real" fix under a new subject. As
for your suggestions, please find my answers inline.
On Wed, Jun 14, 2017 at 11:39 AM, Erik Helin <erik.helin at oracle.com> wrote:
> On 06/13/2017 06:23 PM, Thomas Stüfe wrote:
>
>> So, I changed a whole bunch of callsites to stack-only LogStreams and my
>> brain is slowly turning to cheese :) therefore, lets do a sanity check
>> if this is still what we want. Current snapshot of my work here:
>>
>> http://cr.openjdk.java.net/~stuefe/webrevs/8181917-UL-should
>> -not-use-resource-memory-for-LogStream/current-work-2/webrev/
>>
>
> I think this looks really good! A few comments:
>
> --- old/src/cpu/sparc/vm/vm_version_sparc.cpp
> +++ new/src/cpu/sparc/vm/vm_version_sparc.cpp
> @@ -381,7 +382,8 @@
> - outputStream* log = Log(os, cpu)::info_stream();
> + LogStream ls(Log(os, cpu)::info());
> + outputStream* log = &ls;
>
> I think the above pattern, LogStream ls(Log(foo, bar)::info()), turned out
> very good, succinct and readable. Great work.
>
>
thanks!
> --- old/src/share/vm/classfile/classLoaderData.cpp
> +++ new/src/share/vm/classfile/classLoaderData.cpp
> @@ -831,16 +833,17 @@
> - outputStream* log = Log(class, loader, data)::debug_stream();
> - log->print("create class loader data " INTPTR_FORMAT, p2i(cld));
> - log->print(" for instance " INTPTR_FORMAT " of %s", p2i((void
> *)cld->class_loader()),
> + Log(class, loader, data) log;
> + LogStream ls(log.debug());
> + ls.print("create class loader data " INTPTR_FORMAT, p2i(cld));
> + ls.print(" for instance " INTPTR_FORMAT " of %s", p2i((void
> *)cld->class_loader()),
> cld->loader_name());
>
> if (string.not_null()) {
> - log->print(": ");
> - java_lang_String::print(string(), log);
> + ls.print(": ");
> + java_lang_String::print(string(), &ls);
> }
> - log->cr();
> + ls.cr();
>
> Do you really need the `log` variable here? It seems to that only `ls` is
> used? Or did you mean to do the `outputStream* log = &ls` pattern here as
> well? Or maybe I missed something?
>
>
I ended up reformulating the function. Because I did not like that we have
the "is_enabled(level, tags....)" upstairs in the caller frame, and again
unconditional write in this frame. So I redid the function, it now does
know nothing of UL but writes to an outputStream, and the usual LogStream
logic is in the caller frame.
> --- old/src/share/vm/classfile/loaderConstraints.cpp
> +++ new/src/share/vm/classfile/loaderConstraints.cpp
> @@ -98,14 +101,14 @@
> if (klass != NULL &&
> klass->class_loader_data()->is_unloading()) {
> probe->set_klass(NULL);
> - if (log_is_enabled(Info, class, loader, constraints)) {
> + if (lt.is_enabled()) {
> ResourceMark rm;
> - outputStream* out = Log(class, loader,
> constraints)::info_stream();
> - out->print_cr("purging class object from constraint for name
> %s,"
> + LogStream ls(lt);
> + ls.print_cr("purging class object from constraint for name %s,"
> " loader list:",
> probe->name()->as_C_string());
> for (int i = 0; i < probe->num_loaders(); i++) {
> - out->print_cr(" [%d]: %s", i,
> + ls.print_cr(" [%d]: %s", i,
> probe->loader_data(i)->loader_name());
> }
> }
>
> Could the pattern
> LogStream ls(lt);
> ls.print_cr("hello, brave new logging world");
>
> become
> LogStream(lt).print_cr("hello, brave new logging world");
>
> in order to have less line? Not sure if it is better, but it is at least
> shorter :) Seems to be a rather common pattern as well...
>
>
It could, but "ls" is used twice, so I guess I need the variable name.
> --- old/src/share/vm/gc/g1/g1AllocRegion.cpp
> +++ new/src/share/vm/gc/g1/g1AllocRegion.cpp
> @@ -211,12 +213,9 @@
>
> if ((actual_word_size == 0 && result == NULL) || detailed_info) {
> ResourceMark rm;
> - outputStream* out;
> - if (detailed_info) {
> - out = log.trace_stream();
> - } else {
> - out = log.debug_stream();
> - }
> + LogStream ls_trace(log.trace());
> + LogStream ls_debug(log.debug());
> + outputStream* out = detailed_info ? &ls_trace : &ls_debug;
>
> Could this be
> LogStream out = LogStream(detailed_info ? log.trace() : log.debug());
>
> or is this too succinct? Anyways, nice use of the ternary operator here,
> makes the code much more readable.
>
>
Ah, that was annoying. This is the price you pay for too much templates.
In short, I did not find a better way to express this. I played around with
LogStream ls(detailled?
LogTargetHandle(log.trace()):LogTargetHandle(log.debug())); but neither
could get it to work nor was too impressed with the shortness of that
expression.... If you have a better way to do this, please tell me :)
I didn't have to look through the entire patch (got approx 50% of the way),
> but I think the patch is becoming really good.
>
> Some thoughts:
>>
>> After talking this over with Eric off-list,
>>
>
> Well, off-list, but on IRC ;) #openjdk on irc.oftc.net for those that
> want to follow along or join in on the discussion.
>
> I do not think anymore that reducing the:
>>
>> LogTarget(...) log;
>> if (log.is_enabled()) {
>> LogStream ls(log)...
>> }
>>
>> to just
>>
>> LogStream ls(..);
>> if (ls.is_enabled()) {
>> ..
>> }
>>
>> is really a good idea. We want logging to not cause costs if logging is
>> disabled. But this way, we would always to pay the cost for initializing
>> the LogStream, which means initializing outputStream at least once (for
>> the parent class) and maybe twice (if the line buffer is an outputStream
>> class too). outputStream constructor just assigns a bunch of member
>> variables, but this is still more than nothing.
>>
>
> Yep, I still agree with this.
>
> ---
>>
>> Funnily, when translating all these callsites, I almost never used Log,
>> but mostly LogTarget. This is because I wanted to avoid repeating the
>> (level, tag, tag..) declarations, and the only way to do this is via
>> LogTarget. Compare:
>>
>> Log(gc, metaspace, freelist) log;
>> if (log.is_debug()) {
>> LogStream ls(log.debug());
>> }
>>
>> repeats the "debug" info. Even worse are cases where the whole taglist
>> would be repeated:
>>
>> if (log_is_enabled(Info, class, loader, constraints)) {
>> LogStream ls(Log( class, loader, constraints)::info());
>> }
>>
>
> I think using LogTarget makes a lot sense in these situations, I prefer
> that solution.
>
> ---
>>
>> I found cases where the usage of "xx_stream()" was not guarded by any
>> is_enabled() flag but executed unconditionally, e.g. metaspace.cpp
>> (VirtualSpaceNode::take_from_committed()):
>>
>> 1016 if (!is_available(chunk_word_size)) {
>> 1017 Log(gc, metaspace, freelist) log;
>> 1018 log.debug("VirtualSpaceNode::take_from_committed() not
>> available " SIZE_FORMAT " words ", chunk_word_size);
>> 1019 // Dump some information about the virtual space that is nearly
>> full
>> 1020 ResourceMark rm;
>> 1021 print_on(log.debug_stream());
>> 1022 return NULL;
>> 1023 }
>>
>> So I really wondered: print_on(log.debug_stream()) is executed
>> unconditionally, what happens here? What happens is that the whole
>> printing is executed, first inside the LogStream, then down to
>> LogTargetImpl, and somewhere deep down in UL (in LogTagSet::log()) the
>> assembled message is ignored because there is no output connected to it.
>> So we always pay for the whole printing. I consider this an error,
>> right? I wonder how this could be prevented.
>>
>
> Hmm, I'm not an expert on UL internals, so take my ideas with a large
> grain of salt :) Would be possible to have log.debug() do the is_enabled()
> check (and just do nothing if the check is false)? That would unfortunately
> penalize code that want to call log multiple times, such as:
>
> Log(foo, bar) log;
> if (log.is_enabled()) {
> log.debug(...);
> log.debug(...);
> log.debug(...);
> }
>
> In the above snippet, we would with my suggestion do the is_enabled check
> 4 times instead of 1. OTOH, then one could then remove the first check and
> just have:
>
> Log(foo, bar) log;
> log.debug(...);
> log.debug(...);
> log.debug(...);
>
> (but still, this is 3 checks compared to 1).
>
> How expensive is the is_enabled check? I _think_ (others, please correct
> me if I'm wrong) that code is meant to use the "if (is_enabled()" pattern
> if either the logging or getting the data for logging is expensive. Hence,
> if code doesn't do this (and instead rely on log.debug() to discard the
> data), then it should be fine with this costing a bit more (or we have a
> bug).
>
>
I think so too (that the author just forgot to use is_enabled() enclosure).
I re-asked the question in my official RFR, so lets see what people say. I
think that maybe UL should print a warning if the UL frontend attempts to
write something and there is no LogOutput for it available. But I think
this can be done as a separate issue.
> ---
>>
>> After doing all these changes, I am unsure. Is this the right direction?
>> The alternative would still be my original proposal (tying the LogStream
>> instances as members to the LogTarget instance on the stack). What do
>> you think? I also think that if we go this direction, it might make
>> sense to do this in jdk9, because auto-merging jdk9 to jdk10 may be a
>> problem with so many changes. Or am I too pessimistic?
>>
>
> IMHO you are definitely heading in the right direction. Again, IMO, I
> don't think we should do this in JDK 9. Focus on 10 and if backporting
> turns to be problematic due to this change, then we fix it then ;)
>
> Again, others might have a different view (if so, please chime in).
>
> Thanks,
> Erik
>
>
Thanks, Thomas
> Kind regards, Thomas
>>
>>
>>
>>
>>
>>
More information about the hotspot-dev
mailing list