UL: logging before initialization?

[David Holmes]

On 11/03/2016 9:22 PM, Thomas Stüfe wrote:
> Hi David, Marcus,
>
> thanks for thinking about this! Please find my comments inline.
>
> On Fri, Mar 11, 2016 at 9:14 AM, Marcus Larsson
> <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>
>     Hi,
>
>     On 2016-03-11 03:12, David Holmes wrote:
>
>         Hi Thomas,
>
>         Expanding to hotspot-dev as UL was not designed/built by the
>         runtime team.
>
>         My comments below based on my limited understanding of UL.
>
>         On 11/03/2016 2:25 AM, Thomas Stüfe wrote:
>
>             Hi all,
>
>             I wanted to use UL to log some information from early OS
>             initialization but
>             found that we initialize logging quite late. It is
>             initialized way after
>             os::init() runs.
>
>
>         There are various dependencies in the unified logging framework
>         that prevent it (or at least parts of it) from being used early eg:
>         - argument parsing and log configuration
>         - existence of current thread (for logStreams)
>
>
>     Currently, the framework can be used as soon as static
>     initialization is done. This doesn't include the logStreams of
>     course since they require resource allocations. The problem is as
>     you say that there is no way to configure the logging before parsing
>     the -Xlog command. This means up until that point the default
>     configuration will apply, which means warnings and errors to stdout.
>
>
>             I also see that warnings and errors are printed
>             unconditionally even
>             before, only log calls for levels <= info are quietly swallowed.
>
>
>         Are those warnings/errors using UL? I suspect not.
>
>
>     They could be, since errors and warnings are enabled by default.
>
>
> They are from UL. I see errors and warnings. Decorators seem to be off
> though, e.g. the timestamp, because they rely on initialization in
> os::init(). But nothing serious which breaks logging as long as one is
> fine with default settings.
>
>
>
>
>         Silent swallowing is not good though.
>
>             Would there be a way to move UL initialization and parsing
>             of -Xlog
>             Arguments to an earlier point to be able to use logging in
>             os::init()?
>
>
>         I don't see how you could utilize tags and levels until after
>         full initialization of the logging system, so that would
>         preclude using it as early as os::init.
>
>
>     It is a possible solution I guess. I don't know how dependent
>     argument parsing is on other initialization. There would always be
>     some part of the initialization where you only have warning and
>     error logging unless we do the parsing first thing during startup,
>     which I assume will be impossible.
>
>
> Sure, the logging system must be fully initialized to use it. However, I
> argue that the logging system should be as independent as possible from
> the rest of the VM, so not rely on VM initialization. If that is the
> case - and I think it is now - then logging initialization and -Xlog
> parsing can be moved up in Thread::create_vm() to before os::init().

You would need to examine the complete transitive closure of logging 
code to see if such a move is feasible.

> I would even argue that if this does not work, it is an error. For
> example, if we were to require Thread::current() to work for
> logging,e.g. for log decorators, this would mean logging breaks if
> Thread::current() is not available. So, if we make the logging system
> work for pre-initialization time, and add regression tests for this,
> this is a pretty good way to keep the logging system healthy and robust
> and avoid too much dependencies into the VM.
>
> I would think that the logging system as it is now is already robust -
> the fact that it works, with default settings, right after static
> initialization is a good sign. So, we could probably move initialization
> and -Xlog parsing to an earlier point with not much work.

While the logging system has taken a number of steps to make itself 
immune to some initialization issues (for example "locking" uses a 
semaphore and doesn't rely on Thread::current()), different parts of the 
system have different dependencies - which seems unavoidable to me. I 
don't know if it would be possible to enable a subset of the API earlier 
in the initialization sequence by refactoring some of the configuration 
logic and argument parsing.

David
-----

>
>             Or, if that is not possible, would there be a way to delay
>             printing of
>             early logging calls to after logging initialization and then
>             print them out
>             in one go? I think this would be not trivial though: one
>             would have to
>             collect all logging output in memory somewhere - because we
>             do not yet know
>             which tags are switched on - and then, once -Xlog is parsed,
>             filter it by
>             tag before printing it out.
>
>
>         Yeah that seems difficult/complex given the problem that the VM
>         is in the early stages of initialization
>
>
> I really do not like this solution either, I only added this for
> completeness and to make my first proposal look better in comparison :)
>
>             What do you think, would that be a worthwhile change? I am a
>             bit unhappy
>             about how logging calls are quietly swallowed, so for any
>             code which runs
>             at VM initialization, one always has to keep in mind that UL
>             may not yet be
>             initialized.
>
>
>         Not a new problem (adding more code during VM initialization)
>         but one that is getting more complicated :)
>
>
>     I think it would perhaps be worthwhile if there's demand for a bunch
>     of info to trace level logging from startup code (before argument
>     parsing).
>
>
> At least in the AIX port we have a lot of tracing going on very early.
> For platform porters, OS initialization is a very interesting time. We
> have now a very primitive trace there which I would love to switch to
> UL, but right now the trace output would just be swallowed by
> not-yet-initialized UL.
>
> Thank you,
>
> Thomas
>
>     Thanks,
>     Marcus
>
>
>
>         Cheers,
>         David
>
>             Kind Regards, Thomas
>
>
>