From 5aefc9d155cfddedd009a9303bdc1ab99d7ef49b Mon Sep 17 00:00:00 2001 From: Fabio Niephaus Date: Tue, 30 Nov 2021 11:35:52 +0100 Subject: [PATCH 1/3] Enable BuildOutputPrefix in GraalVmSVMNativeImageBuildTask. --- sdk/mx.sdk/mx_sdk_vm_impl.py | 1 + .../com/oracle/svm/hosted/reporting/ProgressReporter.java | 7 +------ 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/sdk/mx.sdk/mx_sdk_vm_impl.py b/sdk/mx.sdk/mx_sdk_vm_impl.py index 4daaf9ef29ba..141c55217b9b 100644 --- a/sdk/mx.sdk/mx_sdk_vm_impl.py +++ b/sdk/mx.sdk/mx_sdk_vm_impl.py @@ -2180,6 +2180,7 @@ def get_build_args(self): build_args = [ '--macro:' + GraalVmNativeProperties.macro_name(self.subject.native_image_config), '-H:NumberOfThreads=' + str(self.parallelism), + '-H:+BuildOutputPrefix', ] if self.subject.native_image_config.is_polyglot: build_args += ["--macro:truffle", "--language:all"] diff --git a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java index aeceab34ad23..e0398791fadb 100644 --- a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java +++ b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java @@ -134,12 +134,7 @@ public ProgressReporter(OptionValues options) { if (isEnabled) { Timer.disablePrinting(); } - if (SubstrateOptions.BuildOutputPrefix.hasBeenSet(options)) { - usePrefix = SubstrateOptions.BuildOutputPrefix.getValue(options); - } else { - // Drop mx detection after enabling prefix in gates (GR-35238). - usePrefix = IS_CI && System.getenv("MX_HOME") != null; - } + usePrefix = SubstrateOptions.BuildOutputPrefix.getValue(options); boolean enableColors = !IS_CI; if (SubstrateOptions.BuildOutputColorful.hasBeenSet(options)) { enableColors = SubstrateOptions.BuildOutputColorful.getValue(options); From fcf7b31bfbb7f78ae3d80ac38abbc0b8ed3234de Mon Sep 17 00:00:00 2001 From: Fabio Niephaus Date: Tue, 30 Nov 2021 11:37:00 +0100 Subject: [PATCH 2/3] Fix a typo. --- .../oracle/svm/hosted/image/NativeImageDebugInfoProvider.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImageDebugInfoProvider.java b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImageDebugInfoProvider.java index ccd75a00f104..c0a998b4b308 100644 --- a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImageDebugInfoProvider.java +++ b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImageDebugInfoProvider.java @@ -1278,7 +1278,7 @@ public long getSize() { } private boolean acceptObjectInfo(ObjectInfo objectInfo) { - /* This condiiton rejects filler partition objects. */ + /* This condition rejects filler partition objects. */ return (objectInfo.getPartition().getStartOffset() > 0); } From acd9085bf7dfcf73e2474b003f190edcf30e5171 Mon Sep 17 00:00:00 2001 From: Fabio Niephaus Date: Wed, 1 Dec 2021 08:52:27 +0100 Subject: [PATCH 3/3] Improve and fix ProgressReporter. - Add documentation - List packages (not classes) in code breakdown - List size of "other data" - List number of reachable fields - Print reflection and JNI access registration stats after analysis - Print runtime compiled methods after analysis - Disable progress printing if logging is enabled - Print progress periodically at an increasing interval - Add and fix some links - Minor other improvements --- .../native-image/BuildOutput.md | 166 +++++++++++++-- .../impl/RuntimeReflectionSupport.java | 4 + substratevm/CHANGELOG.md | 2 +- .../oracle/svm/graal/hosted/GraalFeature.java | 7 +- .../hosted/NativeImageGeneratorRunner.java | 5 +- .../hosted/reporting/ProgressReporter.java | 201 +++++++++++------- .../svm/jni/access/JNIAccessFeature.java | 16 ++ .../reflect/hosted/ReflectionDataBuilder.java | 10 + 8 files changed, 318 insertions(+), 93 deletions(-) diff --git a/docs/reference-manual/native-image/BuildOutput.md b/docs/reference-manual/native-image/BuildOutput.md index e2713ebde012..e5650ba947f3 100644 --- a/docs/reference-manual/native-image/BuildOutput.md +++ b/docs/reference-manual/native-image/BuildOutput.md @@ -6,37 +6,169 @@ permalink: /reference-manual/native-image/BuildOutput/ --- # Native Image Build Output -## Glossary +This page provides documentation for the build output of GraalVM Native Image. + +## HelloWorld Example Output +``` +================================================================================ +GraalVM Native Image: Generating 'helloworld'... +================================================================================ +[1/7] Initializing... (4.8s @ 0.21GB) + Version info: 'GraalVM dev Java 11 CE' + 1 user-provided feature(s) + - HelloWorld$MyFeature +[2/7] Performing analysis... [*******] (11.1s @ 0.48GB) + 2,546 (83.20%) of 3,060 classes reachable + 3,187 (60.39%) of 5,277 fields reachable + 11,554 (72.39%) of 15,960 methods reachable + 27 classes, 0 fields, and 135 methods registered for reflection + 57 classes, 60 fields, and 51 methods registered for JNI access +[3/7] Building universe... (0.7s @ 0.64GB) +[4/7] Parsing methods... [*] (0.7s @ 0.86GB) +[5/7] Inlining methods... [****] (1.5s @ 0.75GB) +[6/7] Compiling methods... [***] (8.1s @ 2.37GB) +[7/7] Creating image... (1.7s @ 2.68GB) + 10.27MB in total (35.5% code area, 57.0% image heap, and 7.5% other data) + 3.65MB for code area: 6,913 compilation units + 5.85MB for image heap: 1,530 classes and 80,316 objects + 790.29KB for other data +-------------------------------------------------------------------------------- +Top 10 packages in code area: Top 10 object types in image heap: + 606.18KB java.util 1.64MB byte[] for general heap data + 282.69KB java.lang 713.25KB java.lang.String + 222.47KB java.util.regex 544.73KB java.lang.Class + 219.55KB java.text 449.33KB byte[] for java.lang.String + 193.17KB com.oracle.svm.jni 363.56KB java.util.HashMap$Node + 149.84KB java.util.concurrent 192.14KB java.util.HashMap$Node[] + 113.51KB java.math 139.14KB java.lang.String[] + 103.51KB com.oracle.svm.core.reflect 139.04KB char[] + 97.83KB sun.text.normalizer 130.59KB j.u.c.ConcurrentHashMap$Node + 88.63KB c.oracle.svm.core.genscavenge 103.92KB s.u.l.LocaleObjec~e$CacheEntry + ... 108 additional packages ... 719 additional object types + (use GraalVM Dashboard to see all) +-------------------------------------------------------------------------------- + 1.0s spent in 15 GCs | Peak RSS: 3.00GB | CPU load: ~606.03% +-------------------------------------------------------------------------------- +Produced artifacts: + /Users/janedoe/helloworld/helloworld (executable) + /Users/janedoe/helloworld/helloworld.build_artifacts.txt +================================================================================ +Finished generating 'helloworld' in 30.1s. +``` -### User-provided features +## Build Stages -### Classes registered for reflection +### Initializing +In this stage, the Native Image build process is set up and [`Features`][jdoc_feature] are initialized. -### Reachable classes and methods +#### Version Info +The version info of the Native Image process. +This string is also used for the `java.vm.version` property within the generated image. +Please report this version info when you [file issues][new_issue]. -### Runtime compiled methods +#### User-provided Features +All [`Features`][jdoc_feature] that are provided by the user or implicitly registered for the user, for example, by a framework. +GraalVM Native Image deploys a number of internal features, which are excluded from this list. -### Code Area +### Performing Analysis +In this stage, a [points-to analysis][oopsla19_initialize_once_start_fast] is performed. +The progress indicator visualizes the number of analysis iterations. +A large number of iterations can indicate problems in the analysis likely caused by misconfiguration or a misbehaving feature. -### Image Heap +#### Reachable Classes, Fields, and Methods +The number of classes, fields, and methods that are reachable versus the total number of classes and methods loaded as part of the build process. +A significantly larger number of loaded classes that are not reachable can indicate a configuration problem. +To reduce overhead, please ensure that the classpath only contains entries that are needed for building the application. -### Peak RSS +#### Reflection Registrations +The number of classes, fields, and methods that are registered for reflection. +Large numbers can cause significant reflection overheads, slow down the build process, and increase the size of the native image (see [method metadata](#glossary-method-metadata)). -### CPU load +#### JNI Access Registrations +The number of classes, fields, and methods that are registered for [JNI][doc_jni] access. +#### Runtime Compiled Methods +The number of methods marked for runtime compilation. +This number is only shown if runtime compilation is built into the image, for example, when building a [Truffle][truffle] language. +Runtime compiled methods account for [graph encodings](#glossary-graph-encodings) in the image heap. -## Build Stages +### Building Universe +In this stage, a universe with all classes, fields, and methods is built, which is then used to create the native image. + +### Parsing Methods +In this stage, the Graal compiler parses all reachable methods. +The progress indicator is printed periodically at an increasing interval. + +### Inlining Methods +In this stage, trivial method inlining is performed. +The progress indicator visualizes the number of inlining iterations. + +### Compiling Methods +In this stage, the Graal compiler compiles all reachable methods to machine code. +The progress indicator is printed periodically at an increasing interval. + +### Creating Image +In this stage, the native image is created and written to disk. +Debug info is also generated as part of this stage (if requested). + +#### Code Area +The code area contains machine code produced by the Graal compiler for all reachable methods. +Therefore, reducing the number of reachable methods also reduces the size of the code area. + +#### Image Heap +The image heap contains reachable objects such as static data, classes initialized at run-time, and `byte[]` for different purposes. + +##### General Heap Data Stored in `byte[]` +The total size of all `byte[]` objects that are neither used for `java.lang.String`, nor [graph encodings](#glossary-graph-encodings), nor [method metadata](#glossary-method-metadata). +This typically dominates + +##### Graph Encodings Stored in `byte[]` +The total size of all `byte[]` objects used for graph encodings. +These encodings are a result of [runtime compiled methods](#glossary-runtime-methods). +Therefore, reducing the number of such methods also reduces the size of corresponding graph encodings. + +##### Method Metadata Stored in `byte[]` +The total size of all `byte[]` objects used for method metadata, a type of reflection metadata. +To reduce the amount of method metadata, reduce the number of [classes registered for reflection](#glossary-reflection-classes). + +#### Other Data +The amount of data in the image that is neither in the [code area](#glossary-code-area) nor in the [image heap](#glossary-image-heap). +This data typically contains internal information for Native Image but it can also contain other information such as debug info. + +### Resource Usage Statistics -### Initializing +#### Garbage Collections +The total number of garbage collections and total time spent in all garbage collectors. +A large number of collections or time spent in collectors usually indicates that the system is under memory pressure. +Increase the amount of available memory to reduce the time to build the image. -### Performing analysis +#### Peak RSS +Peak [resident set size][rss_wiki] as reported by the operating system. +This value indicates the maximum amount of memory consumed by the build process. +If the [GC statistics](#glossary-garbage-collection) do not show any problems, the amount of available memory of the system can be reduced to a value closer to the peak RSS. -### Building universe +#### CPU load +The CPU time used by the process divided by the total time to build the image in percent. +Increase the number of CPU threads to reduce the time to build the image. -### Parsing methods +## Build Output Options -### Inlining methods +Run `native-image --expert-options-all | grep "BuildOutput"` to see all build output options: + +``` +-H:±BuildOutputBreakdowns Show code and heap breakdowns as part of the build output. Default: + (enabled). +-H:±BuildOutputColorful Colorize build output. Default: + (enabled). +-H:±BuildOutputGCWarnings Print GC warnings as part of build output. Default: + (enabled). +-H:±BuildOutputLinks Show links in build output. Default: + (enabled). +-H:±BuildOutputPrefix Prefix build output with ':'. Default: - (disabled). +-H:±BuildOutputProgress Report progress in build output. Default: + (enabled). +-H:±BuildOutputUseNewStyle Use new build output style. Default: + (enabled). +``` -### Compiling methods -### Creating image +[jdoc_feature]: https://www.graalvm.org/sdk/javadoc/org/graalvm/nativeimage/hosted/Feature.html +[doc_jni]: https://github.com/oracle/graal/blob/master/docs/reference-manual/native-image/JNI.md +[new_issue]: https://github.com/oracle/graal/issues/new +[oopsla19_initialize_once_start_fast]: https://dl.acm.org/doi/10.1145/3360610 +[rss_wiki]: https://en.wikipedia.org/wiki/Resident_set_size +[truffle]: https://github.com/oracle/graal/tree/master/truffle diff --git a/sdk/src/org.graalvm.nativeimage/src/org/graalvm/nativeimage/impl/RuntimeReflectionSupport.java b/sdk/src/org.graalvm.nativeimage/src/org/graalvm/nativeimage/impl/RuntimeReflectionSupport.java index a6a3ffa773ce..912e0e1779ba 100644 --- a/sdk/src/org.graalvm.nativeimage/src/org/graalvm/nativeimage/impl/RuntimeReflectionSupport.java +++ b/sdk/src/org.graalvm.nativeimage/src/org/graalvm/nativeimage/impl/RuntimeReflectionSupport.java @@ -54,4 +54,8 @@ public interface RuntimeReflectionSupport extends ReflectionRegistry { Set getHidingMethods(); int getReflectionClassesCount(); + + int getReflectionMethodsCount(); + + int getReflectionFieldsCount(); } diff --git a/substratevm/CHANGELOG.md b/substratevm/CHANGELOG.md index 8a948785a054..52a8bfd8bebc 100644 --- a/substratevm/CHANGELOG.md +++ b/substratevm/CHANGELOG.md @@ -12,4 +12,4 @@ This changelog summarizes major changes to GraalVM Native Image. * (GR-35152) Add -H:DisableURLProtocols to allow specifying URL protocols that must never be included in the image. * (GR-35085) Custom prologue/epilogue/handleException customizations of @CEntryPoint must be annotated with @Uninterruptible. The synthetic methods created for entry points are now implicitly annotated with @Uninterruptible too. * (GR-34935) More compiler optimization phases are run before static analysis: Conditional Elimination (to remove redundant conditions) and Escape Analysis. -* (GR-33602) Enable new user-friendly build output mode. The old output can be restored with `-H:-BuildOutputUseNewStyle`. Run `native-image --expert-options-all | grep "BuildOutput` to see all options for the new output. +* (GR-33602) Enable [new user-friendly build output mode](https://github.com/oracle/graal/blob/master/docs/reference-manual/native-image/BuildOutput.md). The old output can be restored with `-H:-BuildOutputUseNewStyle`. diff --git a/substratevm/src/com.oracle.svm.graal/src/com/oracle/svm/graal/hosted/GraalFeature.java b/substratevm/src/com.oracle.svm.graal/src/com/oracle/svm/graal/hosted/GraalFeature.java index 1978e12dde90..5126b03b9734 100644 --- a/substratevm/src/com.oracle.svm.graal/src/com/oracle/svm/graal/hosted/GraalFeature.java +++ b/substratevm/src/com.oracle.svm.graal/src/com/oracle/svm/graal/hosted/GraalFeature.java @@ -640,6 +640,11 @@ public static String buildSourceReference(FrameState startState) { return sourceReferenceBuilder.toString(); } + @Override + public void afterAnalysis(AfterAnalysisAccess access) { + ProgressReporter.singleton().setNumRuntimeCompiledMethods(methods.size()); + } + @Override @SuppressWarnings("try") public void beforeCompilation(BeforeCompilationAccess c) { @@ -649,8 +654,6 @@ public void beforeCompilation(BeforeCompilationAccess c) { printCallTree(); } - ProgressReporter.singleton().printRuntimeCompileMethods(methods.size(), config.getMethods().size()); - if (Options.PrintStaticTruffleBoundaries.getValue()) { printStaticTruffleBoundaries(); } diff --git a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageGeneratorRunner.java b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageGeneratorRunner.java index 50ecd696c98f..a962208e9f2d 100644 --- a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageGeneratorRunner.java +++ b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageGeneratorRunner.java @@ -300,7 +300,7 @@ private int buildImage(ImageClassLoader classLoader) { ForkJoinPool compilationExecutor = null; ProgressReporter reporter = new ProgressReporter(parsedHostedOptions); - + boolean wasSuccessfulBuild = false; try (StopTimer ignored = totalTimer.start()) { Timer classlistTimer = new Timer("classlist", false); try (StopTimer ignored1 = classlistTimer.start()) { @@ -423,6 +423,7 @@ private int buildImage(ImageClassLoader classLoader) { generator = new NativeImageGenerator(classLoader, optionParser, mainEntryPointData, reporter); generator.run(entryPoints, javaMainSupport, imageName, classlistTimer, imageKind, SubstitutionProcessor.IDENTITY, compilationExecutor, analysisExecutor, optionParser.getRuntimeOptionNames()); + wasSuccessfulBuild = true; } catch (InterruptImageBuilding e) { if (analysisExecutor != null) { analysisExecutor.shutdownNow(); @@ -472,7 +473,7 @@ private int buildImage(ImageClassLoader classLoader) { } finally { totalTimer.print(); if (imageName != null && generator != null) { - reporter.printEpilog(generator, imageName, totalTimer, parsedHostedOptions); + reporter.printEpilog(imageName, generator, wasSuccessfulBuild, totalTimer, parsedHostedOptions); } NativeImageGenerator.clearSystemPropertiesForImage(); ImageSingletonsSupportImpl.HostedManagement.clear(); diff --git a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java index e0398791fadb..03752dd0fc3e 100644 --- a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java +++ b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/reporting/ProgressReporter.java @@ -44,6 +44,7 @@ import java.util.concurrent.TimeUnit; import java.util.function.Consumer; +import org.graalvm.compiler.debug.DebugOptions; import org.graalvm.compiler.options.OptionValues; import org.graalvm.compiler.serviceprovider.GraalServices; import org.graalvm.nativeimage.ImageSingletons; @@ -51,6 +52,7 @@ import org.graalvm.nativeimage.impl.RuntimeReflectionSupport; import com.oracle.graal.pointsto.BigBang; +import com.oracle.graal.pointsto.meta.AnalysisField; import com.oracle.graal.pointsto.meta.AnalysisMethod; import com.oracle.graal.pointsto.meta.AnalysisUniverse; import com.oracle.graal.pointsto.reports.ReportUtils; @@ -95,22 +97,25 @@ public class ProgressReporter { private final ScheduledExecutorService executor = Executors.newSingleThreadScheduledExecutor(); private ScheduledFuture periodicPrintingTask; - private int periodicPrintingTaskPeriodSeconds = 1; private int numStageChars = 0; private long lastGCCheckTimeMillis = System.currentTimeMillis(); private GCStats lastGCStats = getCurrentGCStats(); + private long numRuntimeCompiledMethods = -1; private long graphEncodingByteLength = 0; + private int numJNIClasses = -1; + private int numJNIFields = -1; + private int numJNIMethods = -1; private Timer debugInfoTimer; private enum BuildStage { - INITIALIZE("Initializing"), + INITIALIZING("Initializing"), ANALYSIS("Performing analysis"), UNIVERSE("Building universe"), PARSING("Parsing methods"), INLINING("Inlining methods"), COMPILING("Compiling methods"), - CREATION("Creating image"); + CREATING("Creating image"); private static final int NUM_STAGES = values().length; @@ -139,7 +144,8 @@ public ProgressReporter(OptionValues options) { if (SubstrateOptions.BuildOutputColorful.hasBeenSet(options)) { enableColors = SubstrateOptions.BuildOutputColorful.getValue(options); } - boolean enableProgress = !IS_CI; + boolean loggingDisabled = DebugOptions.Log.getValue(options) == null; + boolean enableProgress = !IS_CI && loggingDisabled; if (SubstrateOptions.BuildOutputProgress.hasBeenSet(options)) { enableProgress = SubstrateOptions.BuildOutputProgress.getValue(options); } @@ -162,10 +168,20 @@ private LinePrinter l() { return linePrinter; } + public void setNumRuntimeCompiledMethods(int value) { + numRuntimeCompiledMethods = value; + } + public void setGraphEncodingByteLength(int value) { graphEncodingByteLength = value; } + public void setJNIInfo(int numClasses, int numFields, int numMethods) { + numJNIClasses = numClasses; + numJNIFields = numFields; + numJNIMethods = numMethods; + } + public void printStart(String imageName) { if (usePrefix) { // Add the PID to further disambiguate concurrent builds of images with the same name @@ -175,12 +191,12 @@ public void printStart(String imageName) { l().blueBold().link("GraalVM Native Image", "https://www.graalvm.org/native-image/").reset() .a(": Generating '").bold().a(imageName).reset().a("'...").flushln(); l().printHeadlineSeparator(); - printStageStart(BuildStage.INITIALIZE); + printStageStart(BuildStage.INITIALIZING); } public void printInitializeEnd(Timer classlistTimer, Timer setupTimer, Collection libraries) { printStageEnd(classlistTimer.getTotalTime() + setupTimer.getTotalTime()); - l().a(" Version info: '").a(ImageSingletons.lookup(VM.class).version).a("'").flushln(); + l().a(" ").doclink("Version info", "#glossary-version-info").a(": '").a(ImageSingletons.lookup(VM.class).version).a("'").flushln(); printNativeLibraries(libraries); } @@ -213,8 +229,6 @@ public void printFeatures(List list) { } public ReporterClosable printAnalysis(BigBang bb) { - int numReflectionClasses = ImageSingletons.lookup(RuntimeReflectionSupport.class).getReflectionClassesCount(); - l().a(" ").a(numReflectionClasses).a(" ").doclink("classes registered for reflection", "#glossary-reflection-classes").flushln(); Timer timer = bb.getAnalysisTimer(); timer.start(); printStageStart(BuildStage.ANALYSIS); @@ -226,19 +240,33 @@ public void closeAction() { printProgressEnd(); int analysisMillis = (int) bb.getAnalysisTimer().getTotalTime(); printStageEnd(analysisMillis); - if (analysisMillis > 30_000) { - // Adjust period for printing task according to duration of analysis. - periodicPrintingTaskPeriodSeconds = analysisMillis / 30_000; - } - Collection methods = bb.getUniverse().getMethods(); - long reachableMethod = methods.stream().filter(m -> m.isReachable()).count(); - int totalMethods = methods.size(); - l().a(" %,6d (%2.2f%%) of %,6d methods ", reachableMethod, reachableMethod / (double) totalMethods * 100, totalMethods) - .doclink("reachable", "#glossary-reachability").flushln(); + String actualVsTotalFormat = "%,8d (%5.2f%%) of %,6d"; long reachableClasses = bb.getUniverse().getTypes().stream().filter(t -> t.isReachable()).count(); long totalClasses = bb.getUniverse().getTypes().size(); - l().a(" %,6d (%2.2f%%) of %,6d classes ", reachableClasses, reachableClasses / (double) totalClasses * 100, totalClasses) - .doclink("reachable", "#glossary-reachability").flushln(); + l().a(actualVsTotalFormat, reachableClasses, reachableClasses / (double) totalClasses * 100, totalClasses) + .a(" classes ").doclink("reachable", "#glossary-reachability").flushln(); + Collection fields = bb.getUniverse().getFields(); + long reachableFields = fields.stream().filter(f -> f.isAccessed()).count(); + int totalFields = fields.size(); + l().a(actualVsTotalFormat, reachableFields, reachableFields / (double) totalFields * 100, totalFields) + .a(" fields ").doclink("reachable", "#glossary-reachability").flushln(); + Collection methods = bb.getUniverse().getMethods(); + long reachableMethods = methods.stream().filter(m -> m.isReachable()).count(); + int totalMethods = methods.size(); + l().a(actualVsTotalFormat, reachableMethods, reachableMethods / (double) totalMethods * 100, totalMethods) + .a(" methods ").doclink("reachable", "#glossary-reachability").flushln(); + if (numRuntimeCompiledMethods >= 0) { + l().a(actualVsTotalFormat, numRuntimeCompiledMethods, numRuntimeCompiledMethods / (double) totalMethods * 100, totalMethods) + .a(" methods included for ").doclink("runtime compilation", "#glossary-runtime-methods").flushln(); + } + String classesFieldsMethodFormat = "%,8d classes, %,5d fields, and %,5d methods "; + RuntimeReflectionSupport rs = ImageSingletons.lookup(RuntimeReflectionSupport.class); + l().a(classesFieldsMethodFormat, rs.getReflectionClassesCount(), rs.getReflectionFieldsCount(), rs.getReflectionMethodsCount()) + .doclink("registered for reflection", "#glossary-reflection-registrations").flushln(); + if (numJNIClasses > 0) { + l().a(classesFieldsMethodFormat, numJNIClasses, numJNIFields, numJNIMethods) + .doclink("registered for JNI access", "#glossary-jni-access-registrations").flushln(); + } } }; @@ -256,11 +284,6 @@ public void closeAction() { }; } - public void printRuntimeCompileMethods(int numRuntimeCompileMethods, int numTotalMethods) { - l().a(" %,6d (%2.2f%%) of %,6d methods included for ", numRuntimeCompileMethods, numRuntimeCompileMethods / (double) numTotalMethods * 100, numTotalMethods) - .doclink("runtime compilation", "#glossary-runtime-methods").flushln(); - } - public ReporterClosable printParsing(Timer timer) { timer.start(); printStageStart(BuildStage.PARSING); @@ -293,7 +316,7 @@ public void closeAction() { public void printInliningSkipped() { printStageStart(BuildStage.INLINING); - linePrinter.dim().a(" (skipped)").reset().flushln(false); + linePrinter.a(progressBarStartPadding()).dim().a("(skipped)").reset().flushln(false); numStageChars = 0; } @@ -315,7 +338,7 @@ public void closeAction() { // TODO: merge printCreationStart and printCreationEnd at some point (GR-35238). public void printCreationStart() { - printStageStart(BuildStage.CREATION); + printStageStart(BuildStage.CREATING); } public void setDebugInfoTimer(Timer timer) { @@ -326,11 +349,14 @@ public void printCreationEnd(Timer creationTimer, Timer writeTimer, int imageSiz int numCompilations) { printStageEnd(creationTimer.getTotalTime() + writeTimer.getTotalTime()); String total = bytesToHuman("%4.2f", imageSize); - l().a("%9s in total (%2.2f%% for ", total, codeCacheSize / (double) imageSize * 100).doclink("code area", "#glossary-code-area") - .a(" and %2.2f%% for ", imageHeapSize / (double) imageSize * 100).doclink("image heap", "#glossary-image-heap").a(")").flushln(); - l().a("%9s in code size: %,8d compilation units", bytesToHuman("%4.2f", codeCacheSize), numCompilations).flushln(); + long otherBytes = imageSize - codeCacheSize - imageHeapSize; + l().a("%9s in total (%.1f%% ", total, codeCacheSize / (double) imageSize * 100).doclink("code area", "#glossary-code-area") + .a(", %.1f%% ", imageHeapSize / (double) imageSize * 100).doclink("image heap", "#glossary-image-heap") + .a(", and %.1f%% ", otherBytes / (double) imageSize * 100).doclink("other data", "#glossary-other-data").a(")").flushln(); + l().a("%9s for code area:%,9d compilation units", bytesToHuman("%4.2f", codeCacheSize), numCompilations).flushln(); long numInstantiatedClasses = universe.getTypes().stream().filter(t -> t.isInstantiated()).count(); - l().a("%9s in heap size: %,8d classes and %,d objects", bytesToHuman("%4.2f", imageHeapSize), numInstantiatedClasses, numHeapObjects).flushln(); + l().a("%9s for image heap:%,8d classes and %,d objects", bytesToHuman("%4.2f", imageHeapSize), numInstantiatedClasses, numHeapObjects).flushln(); + l().a("%9s for other data", bytesToHuman("%4.2f", otherBytes)).a(debugInfoTimer != null ? " including debug info" : "").flushln(); if (debugInfoTimer != null) { String debugInfoTime = String.format("%.1fs", millisToSeconds(debugInfoTimer.getTotalTime())); l().dim().a("%9s for generating debug info", debugInfoTime).reset().flushln(); @@ -356,7 +382,7 @@ public void printBreakdowns(Collection compilationTasks, Collection String codeSizePart = ""; if (packagesBySize.hasNext()) { Entry e = packagesBySize.next(); - String className = truncateClassName(e.getKey()); + String className = truncateClassOrPackageName(e.getKey()); codeSizePart = String.format("%9s %s", bytesToHuman("%4.2f", e.getValue()), className); printedCodeSizeEntries.add(e); } @@ -367,7 +393,7 @@ public void printBreakdowns(Collection compilationTasks, Collection String className = e.getKey(); // Do not truncate special breakdown items, they can contain links. if (!className.startsWith(BREAKDOWN_BYTE_ARRAY_PREFIX)) { - className = truncateClassName(className); + className = truncateClassOrPackageName(className); } heapSizePart = String.format("%9s %s", bytesToHuman(e.getValue()), className); printedHeapSizeEntries.add(e); @@ -388,8 +414,12 @@ public void printBreakdowns(Collection compilationTasks, Collection private static Map calculateCodeBreakdown(Collection compilationTasks) { Map classNameToCodeSize = new HashMap<>(); for (CompileTask task : compilationTasks) { - String className = task.method.format("%H"); - classNameToCodeSize.merge(className, (long) task.result.getTargetCodeSize(), (a, b) -> a + b); + String classOrPackageName = task.method.format("%H"); + int lastDotIndex = classOrPackageName.lastIndexOf('.'); + if (lastDotIndex > 0) { + classOrPackageName = classOrPackageName.substring(0, lastDotIndex); + } + classNameToCodeSize.merge(classOrPackageName, (long) task.result.getTargetCodeSize(), Long::sum); } return classNameToCodeSize; } @@ -398,7 +428,7 @@ private Map calculateHeapBreakdown(Collection heapObje Map classNameToSize = new HashMap<>(); long stringByteLength = 0; for (ObjectInfo o : heapObjects) { - classNameToSize.merge(o.getClazz().toJavaName(true), o.getSize(), (a, b) -> a + b); + classNameToSize.merge(o.getClazz().toJavaName(true), o.getSize(), Long::sum); Object javaObject = o.getObject(); if (javaObject instanceof String) { stringByteLength += StringAccess.getInternalByteArrayLength((String) javaObject); @@ -407,47 +437,51 @@ private Map calculateHeapBreakdown(Collection heapObje Long byteArraySize = classNameToSize.remove("byte[]"); if (byteArraySize != null) { - classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + "java.lang.String[]", stringByteLength); + long remainingBytes = byteArraySize; + classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + "java.lang.String", stringByteLength); + remainingBytes -= stringByteLength; long metadataByteLength = ImageSingletons.lookup(MethodMetadataDecoder.class).getMetadataByteLength(); if (metadataByteLength > 0) { - classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + linePrinter.asDocLink("method metadata", "#heapbreakdown-method-metadata"), metadataByteLength); + classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + linePrinter.asDocLink("method metadata", "#glossary-method-metadata"), metadataByteLength); + remainingBytes -= metadataByteLength; } if (graphEncodingByteLength > 0) { - classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + linePrinter.asDocLink("graph encodings", "#heapbreakdown-graph-encodings"), graphEncodingByteLength); + classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + linePrinter.asDocLink("graph encodings", "#glossary-graph-encodings"), graphEncodingByteLength); + remainingBytes -= graphEncodingByteLength; } - long remaining = byteArraySize - stringByteLength - metadataByteLength - graphEncodingByteLength; - assert remaining >= 0; - classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + linePrinter.asDocLink("assorted data", "#heapbreakdown-assorted-data"), remaining); + assert remainingBytes >= 0; + classNameToSize.put(BREAKDOWN_BYTE_ARRAY_PREFIX + linePrinter.asDocLink("general heap data", "#glossary-general-heap-data"), remainingBytes); } return classNameToSize; } - public void printEpilog(NativeImageGenerator generator, String imageName, Timer totalTimer, OptionValues parsedHostedOptions) { + public void printEpilog(String imageName, NativeImageGenerator generator, boolean wasSuccessfulBuild, Timer totalTimer, OptionValues parsedHostedOptions) { l().printLineSeparator(); - printStats(millisToSeconds(totalTimer.getTotalTime())); + printResourceStats(millisToSeconds(totalTimer.getTotalTime())); l().printLineSeparator(); l().yellowBold().a("Produced artifacts:").reset().flushln(); generator.getBuildArtifacts().forEach((artifactType, paths) -> { for (Path p : paths) { - l().a(" ").a(p.toString()).dim().a(" (").a(artifactType.name()).a(")").reset().flushln(); + l().a(" ").link(p).dim().a(" (").a(artifactType.name().toLowerCase()).a(")").reset().flushln(); } }); if (ImageBuildStatistics.Options.CollectImageBuildStatistics.getValue(parsedHostedOptions)) { - l().a(" ").a(reportImageBuildStatistics(imageName, generator.getBigbang()).toString()).flushln(); + l().a(" ").link(reportImageBuildStatistics(imageName, generator.getBigbang())).flushln(); } - l().a(" ").a(reportBuildArtifacts(imageName, generator.getBuildArtifacts()).toString()).flushln(); + l().a(" ").link(reportBuildArtifacts(imageName, generator.getBuildArtifacts())).flushln(); l().printHeadlineSeparator(); double totalSeconds = millisToSeconds(totalTimer.getTotalTime()); String timeStats; - if (totalSeconds <= 60) { + if (totalSeconds < 60) { timeStats = String.format("%.1fs", totalSeconds); } else { timeStats = String.format("%.0fm %.0fs", totalSeconds / 60, totalSeconds % 60); } - l().a("Finished generating '").bold().a(imageName).reset().a("' in ").a(timeStats).a(".").flushln(); + l().a(wasSuccessfulBuild ? "Finished" : "Failed").a(" generating '").bold().a(imageName).reset().a("' ") + .a(wasSuccessfulBuild ? "in" : "after").a(" ").a(timeStats).a(".").flushln(); executor.shutdown(); } @@ -480,16 +514,19 @@ private Path reportBuildArtifacts(String imageName, Map return ReportUtils.report("build artifacts", buildDir.resolve(imageName + ".build_artifacts.txt"), writerConsumer, !isEnabled); } - private void printStats(double totalSeconds) { + private void printResourceStats(double totalSeconds) { GCStats gcStats = getCurrentGCStats(); - LinePrinter l = l().a("%.1fs", millisToSeconds(gcStats.totalTimeMillis)).a(" spent in ").a(gcStats.totalCount).a(" GCs | "); + LinePrinter l = l().a("%.1fs", millisToSeconds(gcStats.totalTimeMillis)).a(" spent in ").a(gcStats.totalCount).a(" ").doclink("GCs", "#glossary-garbage-collections"); long peakRSS = ProgressReporterCHelper.getPeakRSS(); if (peakRSS >= 0) { - l.doclink("Peak RSS", "#glossary-peak-rss").a(": ").a("%.2fGB", bytesToGiB(peakRSS)).a(" | "); + l.a(" | ").doclink("Peak RSS", "#glossary-peak-rss").a(": ").a("%.2fGB", bytesToGiB(peakRSS)); } OperatingSystemMXBean osMXBean = ManagementFactory.getOperatingSystemMXBean(); - double processCPUTime = nanosToSeconds(((com.sun.management.OperatingSystemMXBean) osMXBean).getProcessCpuTime()); - l.doclink("CPU load", "#glossary-cpu-load").a(": ").a("~%.2f%%", processCPUTime / totalSeconds * 100).flushCenteredln(); + long processCPUTime = ((com.sun.management.OperatingSystemMXBean) osMXBean).getProcessCpuTime(); + if (processCPUTime > 0) { + l.a(" | ").doclink("CPU load", "#glossary-cpu-load").a(": ").a("~%.2f%%", nanosToSeconds(processCPUTime) / totalSeconds * 100); + } + l.flushCenteredln(); } private void printStageStart(BuildStage stage) { @@ -497,17 +534,21 @@ private void printStageStart(BuildStage stage) { l().appendPrefix().flush(); linePrinter.blue() .a("[").a(1 + stage.ordinal()).a("/").a(BuildStage.NUM_STAGES).a("] ").reset().blueBold() - .doclink(stage.message, "#step-" + stage.name().toLowerCase()).a("...").reset(); + .doclink(stage.message, "#stage-" + stage.name().toLowerCase()).a("...").reset(); numStageChars = linePrinter.getCurrentTextLength(); linePrinter.flush(); } private void printProgressStart() { - linePrinter.a(stringFilledWith(PROGRESS_BAR_START - numStageChars, " ")).dim().a("["); + linePrinter.a(progressBarStartPadding()).dim().a("["); numStageChars = PROGRESS_BAR_START + 1; /* +1 for [ */ linePrinter.flush(); } + private String progressBarStartPadding() { + return stringFilledWith(PROGRESS_BAR_START - numStageChars, " "); + } + private void printProgressEnd() { linePrinter.a("]").reset().flush(); numStageChars++; // for ] @@ -518,14 +559,19 @@ public void printStageProgress() { numStageChars++; // for * } - private ScheduledFuture startPeriodicPrinting() { + private void startPeriodicPrinting() { periodicPrintingTask = executor.scheduleAtFixedRate(new Runnable() { + int countdown; + int numPrints; + @Override public void run() { - printStageProgress(); + if (--countdown < 0) { + printStageProgress(); + countdown = ++numPrints > 2 ? numPrints * 2 : numPrints; + } } - }, 0, periodicPrintingTaskPeriodSeconds, TimeUnit.SECONDS); - return periodicPrintingTask; + }, 0, 1, TimeUnit.SECONDS); } private void stopPeriodicPrinting() { @@ -556,7 +602,7 @@ private void checkForExcessiveGarbageCollection() { double ratio = gcTimeDeltaMillis / (double) timeDeltaMillis; if (gcTimeDeltaMillis > EXCESSIVE_GC_MIN_THRESHOLD_MILLIS && ratio > EXCESSIVE_GC_RATIO) { l().redBold().a("GC warning").reset() - .a(": %.1fs spent in %d GCs during the last stage, taking up %2.2f%% of the time.", + .a(": %.1fs spent in %d GCs during the last stage, taking up %.2f%% of the time.", millisToSeconds(gcTimeDeltaMillis), currentGCStats.totalCount - lastGCStats.totalCount, ratio * 100) .flushln(); l().a(" Please ensure more than %.2fGB of memory is available for Native Image", bytesToGiB(ProgressReporterCHelper.getPeakRSS())).flushln(); @@ -565,30 +611,30 @@ private void checkForExcessiveGarbageCollection() { lastGCStats = currentGCStats; } - private static void resetANSIMode() { - System.out.print(ANSIColors.RESET); - } - /* * HELPERS */ + private static void resetANSIMode() { + System.out.print(ANSIColors.RESET); + } + private static String stringFilledWith(int size, String fill) { return new String(new char[size]).replace("\0", fill); } - protected static String truncateClassName(String className) { - int classNameLength = className.length(); + protected static String truncateClassOrPackageName(String classOrPackageName) { + int classNameLength = classOrPackageName.length(); int maxLength = CHARACTERS_PER_LINE / 2 - 10; if (classNameLength <= maxLength) { - return className; + return classOrPackageName; } StringBuilder sb = new StringBuilder(); int currentDot = -1; while (true) { - int nextDot = className.indexOf('.', currentDot + 1); + int nextDot = classOrPackageName.indexOf('.', currentDot + 1); if (nextDot < 0) { // Not more dots, handle the rest and return. - String rest = className.substring(currentDot + 1); + String rest = classOrPackageName.substring(currentDot + 1); int sbLength = sb.length(); int restLength = rest.length(); if (sbLength + restLength <= maxLength) { @@ -599,10 +645,10 @@ protected static String truncateClassName(String className) { } break; } - sb.append(className.charAt(currentDot + 1)).append('.'); + sb.append(classOrPackageName.charAt(currentDot + 1)).append('.'); if (sb.length() + (classNameLength - nextDot) <= maxLength) { // Rest fits maxLength, append and return. - sb.append(className.substring(nextDot + 1)); + sb.append(classOrPackageName.substring(nextDot + 1)); break; } currentDot = nextDot; @@ -757,6 +803,8 @@ protected LinePrinter jumpToMiddle() { protected abstract LinePrinter link(String text, String url); + protected abstract LinePrinter link(Path path); + protected abstract LinePrinter doclink(String text, String htmlAnchor); protected abstract String asDocLink(String text, String htmlAnchor); @@ -884,6 +932,12 @@ protected LinePrinter link(String text, String url) { return this; } + @Override + protected LinePrinter link(Path path) { + Path normalized = path.normalize(); + return link(normalized.toString(), normalized.toUri().toString()); + } + @Override protected LinePrinter doclink(String text, String htmlAnchor) { return link(text, STAGE_DOCS_URL + htmlAnchor); @@ -945,6 +999,11 @@ protected LinePrinter link(String text, String url) { return a(text); } + @Override + protected LinePrinter link(Path path) { + return a(path.normalize().toString()); + } + @Override protected LinePrinter doclink(String text, String htmlAnchor) { return a(text); diff --git a/substratevm/src/com.oracle.svm.jni/src/com/oracle/svm/jni/access/JNIAccessFeature.java b/substratevm/src/com.oracle.svm.jni/src/com/oracle/svm/jni/access/JNIAccessFeature.java index 73dfea39fa72..13576d1f4d07 100644 --- a/substratevm/src/com.oracle.svm.jni/src/com/oracle/svm/jni/access/JNIAccessFeature.java +++ b/substratevm/src/com.oracle.svm.jni/src/com/oracle/svm/jni/access/JNIAccessFeature.java @@ -64,6 +64,7 @@ import com.oracle.svm.hosted.code.CEntryPointData; import com.oracle.svm.hosted.config.ConfigurationParserUtils; import com.oracle.svm.hosted.meta.MaterializedConstantFields; +import com.oracle.svm.hosted.reporting.ProgressReporter; import com.oracle.svm.hosted.substitute.SubstitutionReflectivityFilter; import com.oracle.svm.jni.JNIJavaCallWrappers; import com.oracle.svm.jni.JNISupport; @@ -338,11 +339,26 @@ private static void addField(Field reflField, boolean writable, DuringAnalysisAc } @Override + @SuppressWarnings("unused") public void afterAnalysis(AfterAnalysisAccess access) { sealed = true; if (wereElementsAdded()) { abortIfSealed(); } + + int numClasses = 0; + int numFields = 0; + int numMethods = 0; + for (JNIAccessibleClass clazz : JNIReflectionDictionary.singleton().getClasses()) { + numClasses++; + for (JNIAccessibleField f : clazz.getFields()) { + numFields++; + } + for (JNIAccessibleMethod m : clazz.getMethods()) { + numMethods++; + } + } + ProgressReporter.singleton().setJNIInfo(numClasses, numFields, numMethods); } @Override diff --git a/substratevm/src/com.oracle.svm.reflect/src/com/oracle/svm/reflect/hosted/ReflectionDataBuilder.java b/substratevm/src/com.oracle.svm.reflect/src/com/oracle/svm/reflect/hosted/ReflectionDataBuilder.java index f520060b24c1..36455d524d25 100644 --- a/substratevm/src/com.oracle.svm.reflect/src/com/oracle/svm/reflect/hosted/ReflectionDataBuilder.java +++ b/substratevm/src/com.oracle.svm.reflect/src/com/oracle/svm/reflect/hosted/ReflectionDataBuilder.java @@ -764,6 +764,16 @@ public int getReflectionClassesCount() { return reflectionClasses.size(); } + @Override + public int getReflectionMethodsCount() { + return reflectionMethods.size(); + } + + @Override + public int getReflectionFieldsCount() { + return reflectionFields.size(); + } + static final class ReflectionDataAccessors { private final Method reflectionDataMethod; private final Field declaredFieldsField;