RFR(S) 8233826 Change CDS dumping tty->print_cr() to unified logging
Jiangli Zhou
jianglizhou at google.com
Thu Dec 19 23:08:23 UTC 2019
Thanks for cleaning up the -Xlog:cds and -Xlog:cds=debug output.
Although I still respectfully disagree about omitting the default
output for -Xshare:dump, I don't like to block any progress. So your
current version seems acceptable to me. If there is any stronger
demand for enabling the dump output, it can be easily enabled.
Regards,
Jiangli
On Thu, Dec 19, 2019 at 11:09 AM Ioi Lam <ioi.lam at oracle.com> wrote:
>
> Hi Jiangli & Coleen,
>
> Thanks for the comments. I agree with both of you that the -Xlog:cds "info"
> output is too verbose, so I moved the ones you suggested into the
> "debug" log.
>
> Coleen, I used -Xlog:cds=debug instead of -Xlog:cds+regions=info,
> because there's
> no current log of the cds+regions combination. My experience with have a
> minor
> combination like that is people (including me) will forget about it, and
> will end up using -Xlog:cds*=info, which produces too much output.
>
> Here's the update from the last webrev:
>
> http://cr.openjdk.java.net/~iklam/jdk15/8233826-cds-change-tty-to-ul.v02.delta/
>
> Sample output:
>
> java -Xshare:dump -Xlog:cds
> http://cr.openjdk.java.net/~iklam/jdk15/8233826-cds-change-tty-to-ul.v02.delta/log_cds.txt
>
> java -Xshare:dump -Xlog:cds=debug
> http://cr.openjdk.java.net/~iklam/jdk15/8233826-cds-change-tty-to-ul.v02.delta/log_cds_debug.txt
>
> Thanks
> - Ioi
>
>
> On 12/19/2019 9:01 AM, coleen.phillimore at oracle.com wrote:
> >
> > Hi Jiangli,
> >
> > On 12/18/19 7:34 PM, Jiangli Zhou wrote:
> >> Hi Coleen,
> >>
> >> On Wed, Dec 18, 2019 at 1:45 PM <coleen.phillimore at oracle.com> wrote:
> >>>
> >>>
> >>> 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.
> >>>
> >> Average Java developers may not have the detailed/ and right knowledge
> >> about the logging system(?).
> >
> > I don't believe that. Logging's been in the system since JDK 9, and
> > it's pretty intuitive.
> >>
> >>> 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.
> >>>
> >> With Ioi's current change in place, -Xshare:dump now produce no
> >> output. To be able to see any dumping output even for confirmation
> >> purpose, users now need to add -Xlog:cds option explicitly. The
> >> -Xlog:cds gives the original default dumping output and some
> >> additional information. If we can cleanup the -Xlog:cds logging info
> >> by removing the 'Shared file region 4: 0x0002dc18 bytes...' related
> >> output, we can still give user useful and not overwhelming
> >> information, by enabling it by default for -Xshare:dump. It would also
> >> help users to avoid having to type -Xlog:cds when they
> >> experimenting/using with the feature manually. Any particular reason
> >> or concern for not going with that?
> >>
> >> $ bin/java -Xshare:dump
> >>
> >> $ bin/java -Xshare:dump -Xlog:cds
> >> [0.028s][info][cds] narrow_klass_base = 0x0000000800000000,
> >> narrow_klass_shift = 3
> >> [0.028s][info][cds] Allocated temporary class space: 1073741824 bytes
> >> at 0x00000008c0000000
> >> [0.028s][info][cds] Allocated shared space: 3221225472 bytes at
> >> 0x0000000800000000
> >> [0.417s][info][cds] Loading classes to share ...
> >> [1.020s][info][cds] Loading classes to share: done.
> >> [1.020s][info][cds] Shared spaces: preloaded 1187 classes
> >> [1.020s][info][cds] Reading extra data: done.
> >> [1.026s][info][cds] Rewriting and linking classes ...
> >> [1.126s][info][cds] Rewriting and linking classes: done
> >> [2.077s][info][cds] Number of classes 1261
> >> [2.077s][info][cds] instance classes = 1195
> >> [2.077s][info][cds] obj array classes = 58
> >> [2.077s][info][cds] type array classes = 8
> >> [2.077s][info][cds] Updating ConstMethods ...
> >> [2.141s][info][cds] done.
> >> [2.141s][info][cds] Removing unshareable information ...
> >> [2.203s][info][cds] done.
> >> [2.226s][info][cds] Scanning all metaspace objects ...
> >> [2.226s][info][cds] Allocating RW objects ...
> >> [2.552s][info][cds] Allocating RO objects ...
> >> [2.916s][info][cds] Relocating embedded pointers ...
> >> [3.518s][info][cds] Relocating external roots ...
> >> [3.580s][info][cds] Verifying external roots ...
> >> [3.627s][info][cds] Dumping symbol table ...
> >> [3.693s][info][cds] Dumping objects to closed archive heap region ...
> >> [3.775s][info][cds] Dumping objects to open archive heap region ...
> >> [3.863s][info][cds] Relocating
> >> SystemDictionary::_well_known_klasses[] ...
> >> [3.863s][info][cds] Removing java_mirror ...
> >> [3.863s][info][cds] done.
> >> [3.868s][info][cds] Oopmap = 0x0000000800b705c0 ( 16256 bytes) for
> >> heap region 0x00000007ffc00000 ( 520192 bytes)
> >> [3.870s][info][cds] Oopmap = 0x0000000800b74540 ( 10624 bytes) for
> >> heap region 0x00000007ff800000 ( 339968 bytes)
> >> [3.880s][info][cds] Dumping shared data to file:
> >> [3.880s][info][cds]
> >> /usr/local/google/home/jianglizhou/openjdk/jdk/build/linux-x86_64-server-slowdebug/images/jdk/lib/server/classes.jsa
> >>
> >
> > Here.
> >> [3.880s][info][cds] Shared file region 0: 0x000058d8 bytes, addr
> >> 0x0000000800000000 file offset 0x00001000
> >> [3.880s][info][cds] Shared file region 1: 0x00436528 bytes, addr
> >> 0x0000000800006000 file offset 0x00007000
> >> [3.885s][info][cds] Shared file region 2: 0x00739ec0 bytes, addr
> >> 0x000000080043d000 file offset 0x0043e000
> >> [3.895s][info][cds] Shared file region 3: 0x000009a0 bytes, addr
> >> 0x0000000800b77000 file offset 0x00b78000
> >> [3.895s][info][cds] ptrmap = 0x00007fe961b5a230 (187416 bytes)
> >> [3.895s][info][cds] Shared file region 4: 0x0002dc18 bytes, addr
> >> 0x0000000000000000 file offset 0x00b79000
> >> [3.895s][info][cds] Archive heap region 5: 0x00000007ffc00000 -
> >> 0x00000007ffc7f000 = 520192 bytes
> >> [3.895s][info][cds] Shared file region 5: 0x0007f000 bytes, addr
> >> 0x00000007ffc00000 file offset 0x00ba7000
> >> [3.896s][info][cds] Archive heap region 6: 0x0000000000000000 -
> >> 0x0000000000000000 = 0 bytes
> >> [3.896s][info][cds] Shared file region 6: 0x00000000 bytes, addr
> >> 0x0000000000000000 file offset 0x00c26000
> >> [3.896s][info][cds] Archive heap region 7: 0x00000007ff800000 -
> >> 0x00000007ff853000 = 339968 bytes
> >> [3.896s][info][cds] Shared file region 7: 0x00053000 bytes, addr
> >> 0x00000007ff800000 file offset 0x00c26000
> >> [3.896s][info][cds] Archive heap region 8: 0x0000000000000000 -
> >> 0x0000000000000000 = 0 bytes
> >> [3.896s][info][cds] Shared file region 8: 0x00000000 bytes, addr
> >> 0x0000000000000000 file offset 0x00c79000
> >> [3.896s][info][cds] mc space: 22744 [ 0.2% of total] out of
> >> 24576 bytes [ 92.5% used] at 0x0000000800000000
> >> [3.896s][info][cds] rw space: 4416808 [ 33.8% of total] out of
> >> 4419584 bytes [ 99.9% used] at 0x0000000800006000
> >> [3.896s][info][cds] ro space: 7577280 [ 58.0% of total] out of
> >> 7577600 bytes [100.0% used] at 0x000000080043d000
> >> [3.896s][info][cds] md space: 2464 [ 0.0% of total] out of
> >> 4096 bytes [ 60.2% used] at 0x0000000800b77000
> >> [3.896s][info][cds] bm space: 188416 [ 1.4% of total] out of
> >> 188416 bytes [100.0% used] at 0x0000000000000000
> >> [3.896s][info][cds] ca0 space: 520192 [ 4.0% of total] out of
> >> 520192 bytes [100.0% used] at 0x00000007ffc00000
> >> [3.896s][info][cds] oa0 space: 339968 [ 2.6% of total] out of
> >> 339968 bytes [100.0% used] at 0x00000007ff800000
> >> [3.896s][info][cds] total : 13066872 [100.0% of total] out of
> >> 13074432 bytes [ 99.9% used]
> >> [3.896s][info][cds] Detailed metadata info (excluding st regions; rw
> >> stats include md/mc regions):
> >> [3.896s][info][cds] ro_cnt ro_bytes % |
> >> rw_cnt rw_bytes % | all_cnt all_bytes %
> >> [3.896s][info][cds]
> >> --------------------+---------------------------+---------------------------+--------------------------
> >>
> >> [3.896s][info][cds] Class : 0 0 0.0 |
> >> 1261 843432 19.0 | 1261 843432 7.0
> >> [3.896s][info][cds] Symbol : 37883 1491992 19.7 |
> >> 0 0 0.0 | 37883 1491992 12.4
> >> [3.896s][info][cds] TypeArrayU1 : 9274 275872 3.6 |
> >> 1195 244616 5.5 | 10469 520488 4.3
> >> [3.896s][info][cds] TypeArrayU2 : 3093 161104 2.1 |
> >> 0 0 0.0 | 3093 161104 1.3
> >> [3.896s][info][cds] TypeArrayU4 : 1370 87216 1.2 |
> >> 0 0 0.0 | 1370 87216 0.7
> >> [3.896s][info][cds] TypeArrayU8 : 2045 188936 2.5 |
> >> 1195 142840 3.2 | 3240 331776 2.8
> >> [3.896s][info][cds] TypeArrayOther : 0 0 0.0 |
> >> 0 0 0.0 | 0 0 0.0
> >> [3.896s][info][cds] Method : 0 0 0.0 |
> >> 19089 1992200 44.8 | 19089 1992200 16.6
> >> [3.896s][info][cds] ConstMethod : 19089 2956768 39.0 |
> >> 0 0 0.0 | 19089 2956768 24.6
> >> [3.896s][info][cds] MethodData : 0 0 0.0 |
> >> 0 0 0.0 | 0 0 0.0
> >> [3.896s][info][cds] ConstantPool : 1195 1942912 25.6 |
> >> 0 0 0.0 | 1195 1942912 16.2
> >> [3.896s][info][cds] ConstantPoolCache : 0 0 0.0 |
> >> 1195 1193720 26.9 | 1195 1193720 9.9
> >> [3.896s][info][cds] Annotations : 59 1888 0.0 |
> >> 0 0 0.0 | 59 1888 0.0
> >> [3.896s][info][cds] MethodCounters : 0 0 0.0 |
> >> 0 0 0.0 | 0 0 0.0
> >> [3.896s][info][cds] RecordComponent : 0 0 0.0 |
> >> 0 0 0.0 | 0 0 0.0
> >> [3.896s][info][cds] SymbolHashentry : 37883 300216 4.0 |
> >> 0 0 0.0 | 37883 300216 2.5
> >> [3.896s][info][cds] SymbolBucket : 9470 37888 0.5 |
> >> 0 0 0.0 | 9470 37888 0.3
> >> [3.896s][info][cds] StringHashentry : 7227 57320 0.8 |
> >> 0 0 0.0 | 7227 57320 0.5
> >> [3.896s][info][cds] StringBucket : 1806 7232 0.1 |
> >> 0 0 0.0 | 1806 7232 0.1
> >> [3.896s][info][cds] Other : 0 67936 0.9 |
> >> 0 25208 0.6 | 0 93144 0.8
> >> [3.896s][info][cds]
> >> --------------------+---------------------------+---------------------------+--------------------------
> >>
> >> [3.896s][info][cds] Total : 130394 7577280 100.0 |
> >> 23935 4442016 100.0 | 154329 12019296 100.0
> >>
> >
> > Actually, I partially agree with this. I think the table at the end,
> > and maybe even the shared region %ages part could be -Xlog:cds=debug,
> > but all of the output should be under -Xlog:cds={info,debug}.
> >
> > Someone experimenting with CDS should absolutely already know about
> > -Xlog:cds. That's not a stretch. We're trying to get to the jvm not
> > having any tty->print() anymore, and all output is controlled so that
> > users can choose what they see. UL is nice that you have this
> > flexibility to see what you want.
> >
> > So I agree that making the last part of the output -Xlog:cds=debug or
> > even -Xlog:cds+regions=info.
> >
> > thanks,
> > Coleen
> >
> >
> >> Best,
> >> Jiangli
> >>
> >>> 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
> >>>>>>>
> >
>
More information about the hotspot-runtime-dev
mailing list