RFR(S) 8233826 Change CDS dumping tty->print_cr() to unified logging

[coleen.phillimore at oracle.com]

On 12/18/19 12:35 PM, Jiangli Zhou wrote:
> On Wed, Dec 18, 2019 at 9:09 AM Ioi Lam <ioi.lam at oracle.com> wrote:
>> On 12/18/19 7:49 AM, Jiangli Zhou wrote:
>>> The default dumping output provides useful information, particularly
>>> with static archiving.
>> Hi Jiangli,
>>
>> Thanks for looking this patch.
>>
>> This patch affects only "informational" messages. It doesn't affect the
>> warning/error messages, which I think are the ones that users want to see.
>>
>> I agree that the informational messages are useful for developers of CDS
>> (I look at them all the time). However, I don't know if any of the
>> following messages would be useful to a user of CDS. These messages are
>> not printed during dynamic dumping, and no one has complained.
>>
> The number of archived classes and arrays, the size of the archive and
> etc are all useful information for users of static CDS dumping. If
> there is any failure, the output also provides helpful information for
> isolating when failure occurs.
>
>> $ java -Xshare:dump
>> Allocated shared space: 3221225472 bytes at 0x0000000800000000
>> Loading classes to share ...
>> Loading classes to share: done.
>> Reading extra data: done.
>> Rewriting and linking classes ...
>> Rewriting and linking classes: done
>> Number of classes 1258
>>       instance classes   =  1192
>>       obj array classes  =    58
>>       type array classes =     8
>> Updating ConstMethods ... done.
>> Removing unshareable information ... done.
>> Scanning all metaspace objects ...
>> Allocating RW objects ...
>> Allocating RO objects ...
>> Relocating embedded pointers ...
>> Relocating external roots ...
>> Dumping symbol table ...
>> Dumping objects to closed archive heap region ...
>> Dumping objects to open archive heap region ...
>> Relocating SystemDictionary::_well_known_klasses[] ...
>> Removing java_mirror ... done.
>> mc  space:      8728 [  0.1% of total] out of     12288 bytes [ 71.0%
>> used] at 0x0000000800000000
>> rw  space:   4089896 [ 32.2% of total] out of   4091904 bytes [100.0%
>> used] at 0x0000000800003000
>> ro  space:   7546512 [ 59.4% of total] out of   7548928 bytes [100.0%
>> used] at 0x00000008003ea000
>> md  space:      2272 [  0.0% of total] out of      4096 bytes [ 55.5%
>> used] at 0x0000000800b1d000
>> bm  space:    184320 [  1.5% of total] out of    184320 bytes [100.0%
>> used] at 0x0000000000000000
>> ca0 space:    520192 [  4.1% of total] out of    520192 bytes [100.0%
>> used] at 0x00000007bfc00000
>> oa0 space:    339968 [  2.7% of total] out of    339968 bytes [100.0%
>> used] at 0x00000007bf800000
>> total    :  12689192 [100.0% of total] out of  12701696 bytes [ 99.9% used]
>>
>>
>>
>>> Developers may not know which logging option
>>> needs to be specified to enable the output.
>>>
>>> One possible solution is to enable -Xlog:cds by default for
>>> -Xshare:dump, if the output method is converted to use unified
>>> logging.
>> I suppose if someone is interested, they can find out the tag
>> information by reading the documentation? That's the same if you want to
>> see the logs for other VM features such as gc or class loading.
> The above does not seem to be a safe assumption. The less burden that
> we place on Java developers the better.
>
>  From a usability point of view, I think the output should be enabled
> by default.

The Unified Logging system was added to the VM so that all the JVM 
output used the same mechanism.  Having a knowlegable user specify 
-Xlog:cds doesn't seem burdensome.

To me, the output has always looked like logging, and not simply 
printing that it succeeded.  Also the size percentage output seems less 
meaningful now that the archive is compacted before dumping. Most of 
this information is only useful for developers and should be -Xlog:cds=info.

Thanks,
Coleen

>
> Regards,
> Jiangli
>
>> Thanks
>> - Ioi
>>
>>> Regards,
>>> Jiangli
>>>
>>> On Tue, Dec 17, 2019 at 10:34 PM Ioi Lam <ioi.lam at oracle.com> wrote:
>>>> https://bugs.openjdk.java.net/browse/JDK-8233826
>>>> http://cr.openjdk.java.net/~iklam/jdk15/8233826-cds-change-tty-to-ul.v01/
>>>>
>>>> During CDS dumping, a few messages are printed out unconditionally
>>>> using tty->print_cr(). This patch changes the message to use
>>>> log_info(cds) instead.
>>>>
>>>> Some test cases were expecting the messages in stdout. I modified
>>>> these tests to explicitly pass -Xlog:cds.
>>>>
>>>> Thanks
>>>> - Ioi
>>>>