UL: logging before initialization?

[Thomas Stüfe]

Hi David,

On Fri, Mar 11, 2016 at 1:53 PM, David Holmes <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>> 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?

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