UL: logging before initialization?

[Thomas Stüfe]

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

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.



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