[prev in list] [next in list] [prev in thread] [next in thread]
List: openjdk-hotspot-runtime-dev
Subject: Re: RFR(S) 8233826 Change CDS dumping tty->print_cr() to unified logging
From: Ioi Lam <ioi.lam () oracle ! com>
Date: 2019-12-19 23:42:32
Message-ID: d9f95e6d-1083-5de6-7516-bc040994dab7 () oracle ! com
[Download RAW message or body]
Hi Jiangli,
Thanks for being flexible. I'll do more testing before pushing the
patch.
- Ioi
On 12/19/2019 3:08 PM, Jiangli Zhou wrote:
> 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@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@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@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@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@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
> > > > > > > > >
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic