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

Marcus Larsson marcus.larsson at oracle.com
Wed Oct 12 08:41:52 UTC 2016 

Hi,


On 10/11/2016 02:52 PM, Thomas Stüfe wrote:
> Hi Marcus,
>
> On Tue, Oct 11, 2016 at 12:12 PM, Marcus Larsson 
> <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>
>     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.
>
>
> You sometimes do not know, it could be a log call in a small 
> inconspicuous function which gets called a lot more than the original 
> author intended. Plus, you still have the cost of retrieving the 
> information you try to print, which you can completely avoid if you 
> know the log site is not active.
>
>     At least I hope not. Some of it could perhaps be debug-only
>     logging (log_develop... etc)?
>
>
> Our logging usually does not differ between develop and product build. 
> Simply because logging is valuable for our support people at customer 
> sites, and they usually have product builds.
>
>>
>>     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).
>
>
> If argument parsing for -Xlog could be factored out, it could be 
> called for arguments from various sources - including the hypothetical 
> environment variable - from a very early point on. But I know, every 
> patch is easy from a high level :)

Yeah, I guess we'll have to look at the alternatives and details as we 
go. I've filed https://bugs.openjdk.java.net/browse/JDK-8167571 for 
this. I appreciate the input!

Thanks,
Marcus

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

More information about the hotspot-dev mailing list