[GR-33602] Additional bugfixes for ProgressReporter (#3955).

docs/reference-manual/native-image/BuildOutput.md

@@ -9,49 +9,52 @@ permalink: /reference-manual/native-image/BuildOutput/
 This page provides documentation for the build output of GraalVM Native Image.
 
 ## HelloWorld Example Output
-```
+```text
 ================================================================================
 GraalVM Native Image: Generating 'helloworld'...
 ================================================================================
-[1/7] Initializing...                                            (2.1s @ 0.19GB)
+[1/7] Initializing...                                            (2.5s @ 0.21GB)
  Version info: 'GraalVM dev Java 11 CE'
-[2/7] Performing analysis...  [*******]                          (5.7s @ 0.47GB)
+[2/7] Performing analysis...  [*******]                          (5.6s @ 0.46GB)
    2,565 (82.61%) of  3,105 classes reachable
    3,216 (60.42%) of  5,323 fields reachable
-  11,653 (72.44%) of 16,087 methods reachable
+  11,652 (72.44%) of 16,086 methods reachable
       27 classes,     0 fields, and   135 methods registered for reflection
       57 classes,    59 fields, and    51 methods registered for JNI access
-[3/7] Building universe...                                       (0.4s @ 0.63GB)
-[4/7] Parsing methods...      [*]                                (0.4s @ 0.83GB)
-[5/7] Inlining methods...     [****]                             (0.4s @ 0.67GB)
-[6/7] Compiling methods...    [**]                               (3.4s @ 1.38GB)
-[7/7] Creating image...                                          (0.8s @ 1.65GB)
-  10.52MB in total (35.1% code area, 55.7% image heap, and 9.3% other data)
-   3.69MB for code area:    6,955 compilation units
-   5.86MB for image heap:   1,545 classes and 81,111 objects
- 997.09KB for other data
+[3/7] Building universe...                                       (0.5s @ 0.61GB)
+[4/7] Parsing methods...      [*]                                (0.5s @ 0.86GB)
+[5/7] Inlining methods...     [****]                             (0.5s @ 0.73GB)
+[6/7] Compiling methods...    [**]                               (3.7s @ 2.38GB)
+[7/7] Creating image...                                          (2.1s @ 1.04GB)
+   3.69MB (27.19%) for code area:    6,955 compilation units
+   5.86MB (43.18%) for image heap:   1,545 classes and 80,528 objects
+   3.05MB (22.46%) for debug info generated in 1.0s
+ 997.25KB ( 7.18%) for other data
+  13.57MB in total
 --------------------------------------------------------------------------------
 Top 10 packages in code area:           Top 10 object types in image heap:
- 606.11KB java.util                        1.64MB byte[] for general heap data
- 282.34KB java.lang                      718.09KB java.lang.String
+ 606.23KB java.util                        1.64MB byte[] for general heap data
+ 282.34KB java.lang                      715.56KB java.lang.String
  222.47KB java.util.regex                549.46KB java.lang.Class
- 219.55KB java.text                      454.06KB byte[] for java.lang.String
+ 219.55KB java.text                      451.79KB byte[] for java.lang.String
  193.17KB com.oracle.svm.jni             363.23KB java.util.HashMap$Node
- 149.80KB java.util.concurrent           192.11KB java.util.HashMap$Node[]
- 118.09KB java.math                      139.04KB char[]
- 103.60KB com.oracle.svm.core.reflect    136.48KB java.lang.String[]
+ 149.80KB java.util.concurrent           192.00KB java.util.HashMap$Node[]
+ 118.07KB java.math                      139.83KB java.lang.String[]
+ 103.60KB com.oracle.svm.core.reflect    139.04KB char[]
   97.83KB sun.text.normalizer            130.59KB j.u.c.ConcurrentHashMap$Node
   88.78KB c.oracle.svm.core.genscavenge  103.92KB s.u.l.LocaleObjec~e$CacheEntry
       ... 111 additional packages             ... 723 additional object types
                        (use GraalVM Dashboard to see all)
 --------------------------------------------------------------------------------
-  0.8s (5.4% of total time) in 17 GCs | Peak RSS: 2.60GB | CPU load: ~1183.69%
+    0.9s (5.6% of total time) in 17 GCs | Peak RSS: 3.22GB | CPU load: 10.87
 --------------------------------------------------------------------------------
 Produced artifacts:
  /home/janedoe/helloworld/helloworld (executable)
+ /home/janedoe/helloworld/sources (debug_info)
+ /home/janedoe/helloworld/helloworld (debug_info)
  /home/janedoe/helloworld/helloworld.build_artifacts.txt
 ================================================================================
-Finished generating 'helloworld' in 14.0s.
+Finished generating 'helloworld' in 16.2s.
 ```
 
 ## Build Stages
@@ -136,7 +139,7 @@ This data typically contains internal information for Native Image but it can al
 ### Resource Usage Statistics
 
 #### <a name="glossary-garbage-collection"></a>Garbage Collections
-The total time spent in all garbage collectors, total GC time divided by the total time to build the image in percent, and the total number of garbage collections.
+The total time spent in all garbage collectors, total GC time divided by the total process time in percent, and the total number of garbage collections.
 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.
 
@@ -146,7 +149,7 @@ 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.
 
 #### <a name="glossary-cpu-load"></a>CPU load
-The CPU time used by the process divided by the total time to build the image in percent.
+The CPU time used by the process divided by the total process time.
 Increase the number of CPU threads to reduce the time to build the image.
 
 ## Build Output Options

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jdk/SystemInOutErrSupport.java

@@ -37,9 +37,6 @@
 import org.graalvm.nativeimage.ImageSingletons;
 import org.graalvm.nativeimage.hosted.Feature;
 
-import com.oracle.svm.core.annotate.AutomaticFeature;
-import com.oracle.svm.core.annotate.RecomputeFieldValue;
-
 /**
  * This class provides replacement values for the {@link System#in}, {@link System#out}, and
  * {@link System#err} streams at run time. We want a fresh set of objects, so that any buffers
@@ -66,45 +63,27 @@ private static PrintStream newPrintStream(FileOutputStream fos, String enc) {
         return new PrintStream(new BufferedOutputStream(fos, 128), true);
     }
 
+    public static InputStream in() {
+        return ImageSingletons.lookup(SystemInOutErrSupport.class).in;
+    }
+
     public static void setIn(InputStream in) {
         ImageSingletons.lookup(SystemInOutErrSupport.class).in = Objects.requireNonNull(in);
     }
 
-    public static void setOut(PrintStream out) {
-        ImageSingletons.lookup(SystemInOutErrSupport.class).out = Objects.requireNonNull(out);
+    public static PrintStream out() {
+        return ImageSingletons.lookup(SystemInOutErrSupport.class).out;
     }
 
-    public static void setErr(PrintStream err) {
-        ImageSingletons.lookup(SystemInOutErrSupport.class).err = Objects.requireNonNull(err);
+    public static void setOut(PrintStream out) {
+        ImageSingletons.lookup(SystemInOutErrSupport.class).out = Objects.requireNonNull(out);
     }
 
-    // Checkstyle: stop
-    Object replaceStreams(Object object) {
-        if (object == System.in) {
-            return in;
-        } else if (object == System.out) {
-            return out;
-        } else if (object == System.err) {
-            return err;
-        } else {
-            return object;
-        }
+    public static PrintStream err() {
+        return ImageSingletons.lookup(SystemInOutErrSupport.class).err;
     }
-    // Checkstyle: resume
-}
 
-/**
- * We use an {@link Feature.DuringSetupAccess#registerObjectReplacer object replacer} because the
- * streams can be cached in other instance and static fields in addition to the fields in
- * {@link System}. We do not know all these places, so we do now know where to place
- * {@link RecomputeFieldValue} annotations.
- */
-@AutomaticFeature
-class SystemInOutErrFeature implements Feature {
-    @Override
-    public void duringSetup(DuringSetupAccess access) {
-        SystemInOutErrSupport support = new SystemInOutErrSupport();
-        ImageSingletons.add(SystemInOutErrSupport.class, support);
-        access.registerObjectReplacer(support::replaceStreams);
+    public static void setErr(PrintStream err) {
+        ImageSingletons.lookup(SystemInOutErrSupport.class).err = Objects.requireNonNull(err);
     }
 }

substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageGenerator.java

@@ -680,7 +680,7 @@ private void doRun(Map<Method, CEntryPointData> entryPoints,
                 featureHandler.forEachFeature(feature -> feature.afterImageWrite(afterConfig));
             }
             reporter.printCreationEnd(imageTimer, writeTimer, image.getImageSize(), bb.getUniverse(), heap.getObjectCount(), image.getImageHeapSize(), codeCache.getCodeCacheSize(),
-                            codeCache.getCompilations().size());
+                            codeCache.getCompilations().size(), image.getDebugInfoSize());
             if (SubstrateOptions.BuildOutputBreakdowns.getValue()) {
                 ProgressReporter.singleton().printBreakdowns(compileQueue.getCompilationTasks(), image.getHeap().getObjects());
             }

substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageSystemClassLoader.java

@@ -52,13 +52,23 @@
 public final class NativeImageSystemClassLoader extends SecureClassLoader {
 
     public final ClassLoader defaultSystemClassLoader;
+
+    NativeImageSystemIOWrappers systemIOWrappers;
+
     private volatile ClassLoader nativeImageClassLoader = null;
 
     private Set<ClassLoader> disallowedClassLoaders = Collections.newSetFromMap(new WeakHashMap<>());
 
     public NativeImageSystemClassLoader(ClassLoader defaultSystemClassLoader) {
         super(defaultSystemClassLoader);
         this.defaultSystemClassLoader = defaultSystemClassLoader;
+        resetSystemIOWrappers();
+    }
+
+    private void resetSystemIOWrappers() {
+        systemIOWrappers = new NativeImageSystemIOWrappers();
+        /* Image building console output requires custom System.out and System.err */
+        systemIOWrappers.replaceSystemOutErr();
     }
 
     public static NativeImageSystemClassLoader singleton() {
@@ -243,4 +253,5 @@ private void appendToClassPathForInstrumentation(String classPathEntry) {
             VMError.shouldNotReachHere(message, e);
         }
     }
+
 }

substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/NativeImageSystemIOWrappers.java

@@ -0,0 +1,111 @@
+/*
+ * Copyright (c) 2021, 2021, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.  Oracle designates this
+ * particular file as subject to the "Classpath" exception as provided
+ * by Oracle in the LICENSE file that accompanied this code.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+package com.oracle.svm.hosted;
+
+import java.io.ByteArrayOutputStream;
+import java.io.PrintStream;
+
+import com.oracle.svm.core.util.VMError;
+
+public class NativeImageSystemIOWrappers {
+
+    private final CapturingStdioWrapper outWrapper;
+    private final CapturingStdioWrapper errWrapper;
+
+    public boolean useCapturing;
+
+    NativeImageSystemIOWrappers() {
+        outWrapper = new CapturingStdioWrapper(System.out, new ByteArrayOutputStream(128));
+        errWrapper = new CapturingStdioWrapper(System.err, new ByteArrayOutputStream(128));
+        useCapturing = false;
+    }
+
+    public static NativeImageSystemIOWrappers singleton() {
+        return NativeImageSystemClassLoader.singleton().systemIOWrappers;
+    }
+
+    public void verifySystemOutErrReplacement() {
+        String msg = " was changed during image building. This is not allowed.";
+        VMError.guarantee(System.out == outWrapper, "System.out" + msg);
+        VMError.guarantee(System.err == errWrapper, "System.err" + msg);
+    }
+
+    public PrintStream originalOut() {
+        return outWrapper.delegate;
+    }
+
+    public PrintStream originalErr() {
+        return errWrapper.delegate;
+    }
+
+    public void flushCapturedContent() {
+        outWrapper.flushCapturedContent();
+        errWrapper.flushCapturedContent();
+    }
+
+    void replaceSystemOutErr() {
+        System.setOut(outWrapper);
+        System.setErr(errWrapper);
+    }
+
+    /**
+     * Wrapper with the ability to temporarily capture output to stdout and stderr.
+     */
+    private final class CapturingStdioWrapper extends PrintStream {
+        private final ByteArrayOutputStream buffer;
+        private final PrintStream delegate;
+
+        private CapturingStdioWrapper(PrintStream delegate, ByteArrayOutputStream buffer) {
+            super(buffer);
+            this.buffer = buffer;
+            this.delegate = delegate;
+        }
+
+        @Override
+        public void write(int b) {
+            if (useCapturing) {
+                super.write(b);
+            } else {
+                delegate.write(b);
+            }
+        }
+
+        @Override
+        public void write(byte[] buf, int off, int len) {
+            if (useCapturing) {
+                super.write(buf, off, len);
+            } else {
+                delegate.write(buf, off, len);
+            }
+        }
+
+        private void flushCapturedContent() {
+            byte[] byteArray = buffer.toByteArray();
+            delegate.write(byteArray, 0, byteArray.length);
+            buffer.reset();
+        }
+    }
+}

substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/AbstractImage.java

@@ -47,6 +47,7 @@ public abstract class AbstractImage {
     protected final NativeImageCodeCache codeCache;
     protected final List<HostedMethod> entryPoints;
     protected int resultingImageSize; // for statistical output
+    protected int debugInfoSize; // for statistical output
 
     public enum NativeImageKind {
         SHARED_LIBRARY(false) {
@@ -115,6 +116,10 @@ public int getImageSize() {
         return resultingImageSize;
     }
 
+    public int getDebugInfoSize() {
+        return debugInfoSize;
+    }
+
     public NativeLibraries getNativeLibs() {
         return nativeLibs;
     }

substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImage.java

@@ -179,6 +179,12 @@ protected final void write(DebugContext context, Path outputFile) {
             throw shouldNotReachHere(ex);
         }
         resultingImageSize = (int) outputFile.toFile().length();
+        debugInfoSize = 0;
+        for (Element e : objectFile.getElements()) {
+            if (e.getName().contains(".debug")) {
+                debugInfoSize += e.getMemSize(objectFile.getDecisionsByElement());
+            }
+        }
         if (NativeImageOptions.PrintImageElementSizes.getValue()) {
             for (Element e : objectFile.getElements()) {
                 System.out.printf("PrintImageElementSizes:  size: %15d  name: %s\n", e.getMemSize(objectFile.getDecisionsByElement()), e.getElementName());