RFR: 8146009: "pure virtual method called" with using new GC logging mechanism

[Marcus Larsson]

Hi,


On 10/11/2016 11:53 AM, Thomas Stüfe wrote:
> Hi Marcus,
>
> On Tue, Oct 11, 2016 at 11:41 AM, Marcus Larsson 
> <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>
>     Hi Thomas,
>
>
>     On 10/11/2016 11:13 AM, Thomas Stüfe wrote:
>>     Hi Markus,
>>
>>     just a question whether I understand this correctly: Logging
>>     works already from static initialization on, but as no arguments
>>     are parsed yet, the default is to print out all warning and error
>>     level messages to stderr?
>>
>>     If true, this may be potentially confusing, because there will
>>     always be a small window at startup where logging does not behave
>>     as expected from the command line arguments given. Like, if I
>>     redirect log output to a file, the first burst of log output
>>     would still go to stderr. This may also confuse tools which grep
>>     the output of a VM.
>
>     Yes you're right, it's a limitation of UL at the moment. Logging
>     before argument parsing means you can only use warning and error
>     level, and can only expect to see it on stdout.
>
>>
>>     Additionally, during initialization one may actually want precise
>>     control of the logging system before arguments are parsed, e.g.
>>     in os::init(). We have a lot of tracing in the AIX os layer
>>     initialization which currently goes to nil because it runs before
>>     Xlog argument parsing is done.
>>
>>     Both situations could be solved if there were a possibility to
>>     specify logging options right from the start, e.g. via a file or
>>     an environment variable, which could be parsed in a static
>>     initializer without relying on any VM initialization.
>
>     It's either that or we implement some early logging buffering that
>     saves all logging happening before UL initialization and logs it
>     after UL is fully initialized. We haven't had the need for that
>     early logging previously, but given that you seem to require it,
>     it seems like a worthwhile enhancement of UL now.
>
>
> Thank you! This would be helpful.
>
> I think that buffering is not a good solution. For one, it requires 
> you execute each and every log call and buffer the resulting string, 
> because you do not know yet which of the log calls will be active. 
> This may be cpu and memory intensive, which especially at startup may 
> hurt.

That's a fair point. Although I don't think we should have enough such 
logging (before UL init) to make a significant difference. At least I 
hope not. Some of it could perhaps be debug-only logging (log_develop... 
etc)?

>
> Also, there is no guarantee the VM even lives long enough to parse the 
> Xlog arguments to print out the buffered messages. The situations 
> where we use early logging are often situations where the VM crashes 
> early.

Unprocessed log buffers could possibly be printed in the hs_err output 
to avoid logging losses when the VM crashes early. Having an additional 
early parsing step seems more complicated to me (at least at first glance).

Thanks,
Marcus

>
> Kind Regards, Thomas
>
>     Thanks,
>     Marcus
>
>>
>>     Kind Regards, Thomas
>>
>>
>>
>>     On Mon, Oct 10, 2016 at 11:20 AM, Marcus Larsson
>>     <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>>
>>         Updated webrev after feedback:
>>         http://cr.openjdk.java.net/~mlarsson/8146009/webrev.01
>>         <http://cr.openjdk.java.net/%7Emlarsson/8146009/webrev.01>
>>
>>         Incremental:
>>         http://cr.openjdk.java.net/~mlarsson/8146009/webrev.00-01
>>         <http://cr.openjdk.java.net/%7Emlarsson/8146009/webrev.00-01>
>>
>>
>>
>>         On 10/07/2016 04:26 PM, Marcus Larsson wrote:
>>
>>             Hi,
>>
>>             Making another attempt to fix this issue.
>>
>>             Summary:
>>             The following patch resolves a problem where the VM would
>>             crash during shutdown due to static log related memory
>>             being de-initialized before the last use of the logging
>>             framework. The solution involves parts of the Nifty
>>             Counter idiom [0] to control static initialization and
>>             de-initialization of stdout's and stderr's LogOutputs.
>>             Both objects are now allocated using placement new, and
>>             avoids destructor calls during de-initialization. The
>>             LogStreamInitializer makes sure both objects are
>>             initialized before first use.
>>
>>             Because the LogOutput::Stdout/err pointers could no
>>             longer be kept in LogOutput, I've replaced all usages of
>>             them with the new references instead.
>>
>>             The patch includes a regression test for this issue,
>>             contributed by Michail Chernov.
>>
>>             Webrev:
>>             http://cr.openjdk.java.net/~mlarsson/8146009/webrev.00
>>             <http://cr.openjdk.java.net/%7Emlarsson/8146009/webrev.00>
>>
>>             Issue:
>>             https://bugs.openjdk.java.net/browse/JDK-8146009
>>             <https://bugs.openjdk.java.net/browse/JDK-8146009>
>>
>>             Testing:
>>             JPRT testset hotspot, included test on supported platforms.
>>
>>             Thanks,
>>             Marcus
>>
>>             [0]
>>             https://en.wikibooks.org/wiki/More_C%2B%2B_Idioms/Nifty_Counter
>>             <https://en.wikibooks.org/wiki/More_C%2B%2B_Idioms/Nifty_Counter>
>>
>>
>>
>
>