UL: logging before initialization?

[David Holmes]

On 12/03/2016 12:34 AM, Thomas Stüfe wrote:
> Hi David,
>
> On Fri, Mar 11, 2016 at 1:53 PM, David Holmes <david.holmes at oracle.com
> <mailto:david.holmes at oracle.com>> wrote:
>
>     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>
>         <mailto: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.
>
>
> Not sure I understand.
>
> Making sure that the logging system itself does not contain deep VM
> dependencies should be feasible. If with "logging code" you mean logging
> calls by the various components, I would think that anyone introducing
> logging calls should not log anything which is not available at the time
> the logging call is executed. Or do I not understand?

Just the logging system itself, but dependencies are often not obvious 
inside the VM - eg allocation -> NMT

Thanks,
David

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