stringStream in UL and nested ResourceMarks

Erik Helin erik.helin at
Wed Jun 14 09:39:55 UTC 2017

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:

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.

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

    if (string.not_null()) {
-    log->print(": ");
-    java_lang_String::print(string(), log);
+    ls.print(": ");
+    java_lang_String::print(string(), &ls);
-  log->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?

--- 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()) {
-        if (log_is_enabled(Info, class, loader, constraints)) {
+        if (lt.is_enabled()) {
            ResourceMark rm;
-          outputStream* out = Log(class, loader, 
-          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:",
            for (int i = 0; i < probe->num_loaders(); i++) {
-            out->print_cr("    [%d]: %s", i,
+            ls.print_cr("    [%d]: %s", i,

Could the pattern
   LogStream ls(lt);
   ls.print_cr("hello, brave new logging world");

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

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

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 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()) {

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;

(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).

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


> Kind regards, Thomas

More information about the hotspot-dev mailing list