stringStream in UL and nested ResourceMarks

[Thomas Stüfe]

Hi,

On Tue, Jun 13, 2017 at 11:53 AM, Thomas Stüfe <thomas.stuefe at gmail.com>
wrote:

> Hi Marcus,
>
> On Tue, Jun 13, 2017 at 10:32 AM, Marcus Larsson <
> marcus.larsson at oracle.com> wrote:
>
>>
>> On 2017-06-12 17:47, Thomas Stüfe wrote:
>>
>>
>>
>> Okay, I put a bit of work into it (stack-only LogStream) and encountered
>> nothing difficult, just a lot of boilerplate work.
>>
>> This is how I am changing the callsites:
>>
>> http://cr.openjdk.java.net/~stuefe/webrevs/8181917-UL-should
>> -not-use-resource-memory-for-LogStream/current-work/webrev/
>>
>> Please tell me if you had something different in mind; I want to make
>> sure we have the same idea before changing such a lot of code.
>>
>>
>> Nice work. This is what I expected to see.
>>
>>
> Great.
>
>
>> Just a small suggestion I thought of when looking at it:
>>
>> Instead of
>>
>>  769   Log(itables) logi; 770   LogStream lsi(logi.trace());
>>
>> you could do
>>
>>  769   LogStream lsi(Log(itables)::trace());
>>
>> to save a line.
>> Of course this only works if the log instance isn't used for anything
>> else than initializing the LogStream.
>>
>> Touching on this is a suggestion that was brought up here when discussing
>> this locally, which is to add is_enabled() functions to the LogStream class.
>> By doing that we wouldn't need the log instance at all in places where
>> only the stream API is used, which is good.
>> If we're going for that, it would be great to do it before this change so
>> we could fix up the call sites to use that as well.
>> Let me know what you think.
>>
>>
> Makes sense. But then, how about making the syntax consistent with Log and
> LogTarget:
>
> LogStream(Debug, gc) ls;
> if (ls.is_enabled()) {... }
>
> We actually already have this already, "LogStreamHandle". I'd propose
> instead to make this a default for LogStream:
>
> template <LogLevelType level, LogTagType T0, LogTagType T1 =
> LogTag::__NO_TAG, ......>
> class LogStreamImpl : public outputStream {
>   LogTargetImpl<level, T0, T1, T2, T3, T4, GuardTag> _log_target;
> public:
>   static bool is_enabled() {
>     return LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(level);
>   }
>   void write(const char* s, size_t len) {
>     _log_target.print("%s", s);
>   }
> };
>
> #define LogStream(level, ...) LogStreamImpl<LogLevel::level,
> LOG_TAGS(__VA_ARGS__)>
>
> This is now made easy because with the planned simplification of LogStream
> line buffer handling, the LogStream class hierarchy can be simplified down
> to this one class LogStreamImpl.
>
> Then, syntax for using Log and LogTarget is the same as for LogStream.
> Also, implementation is similar for all three cases, which helps
> maintenance.
>
>
>> Notes:
>> - I only remove ResourceMark objects where I can be sure that they are
>> intended to scope the LogStream itself. If I cannot be sure, I leave them
>> in for now.
>> - using LogStream as a stack object means we need to include
>> logStream.hpp (or decide to move LogStream to log.hpp).
>>
>>
>> I don't think it's a big deal to include logStream.hpp as well, but we
>> can consider moving it into log.hpp if people prefer that. I don't really
>> have a strong opinion on this.
>>
>>
> I prefer keeping logStream.hpp around and to add the second include if you
> need an outputStream.
>
>
>> - If there is only one debug level involved (true in a lot of places), I
>> prefer LogTarget to Log, because it minimizes error possibilities
>> - In some places the coding gets more complicated, usually if the code
>> wants to decide the log level dynamically, but the log level is a template
>> parameter to LogTarget. See e.g. linkresolver.cpp.
>> - I see the macro "log_develop_is_enabled" and wonder why it exists and
>> why the code is not just surrounded by #ifndef PRODUCT?
>>
>>
>> That's only for convenience. It could as well have been ifndef:ed.
>>
>> Thanks,
>> Marcus
>>
>
> Note that I am currently in the process of doing these changes, because I
> like to get this fix done. The number of callsites to fix up is large
> (~100). I do this partly with scripting, but still a bit of work. I would
> appreciate it if we could agree quickly, to prevent having to rewrite
> larger sections later.
>
> ..Thomas
>


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/

Some thoughts:

After talking this over with Eric off-list, 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.

---

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

---

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?

Kind regards, Thomas