[GR-47507] [GR-48180] Reduce logging overhead in debug info generator.

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

@@ -39,7 +39,7 @@ GraalVM Native Image: Generating 'helloworld' (executable)...
 [4/8] Parsing methods...      [*]                                (0.6s @ 0.75GB)
 [5/8] Inlining methods...     [***]                              (0.3s @ 0.32GB)
 [6/8] Compiling methods...    [**]                               (3.7s @ 0.60GB)
-[7/8] Layouting methods...    [*]                                (0.8s @ 0.83GB)
+[7/8] Laying out methods...   [*]                                (0.8s @ 0.83GB)
 [8/8] Creating image...       [**]                               (3.1s @ 0.58GB)
    5.32MB (24.22%) for code area:     8,702 compilation units
    7.03MB (32.02%) for image heap:   93,301 objects and 5 resources

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/ArrayTypeEntry.java

@@ -56,7 +56,9 @@ public void addDebugInfo(DebugInfoBase debugInfoBase, DebugTypeInfo debugTypeInf
         this.lengthOffset = debugArrayTypeInfo.lengthOffset();
         /* Add details of fields and field types */
         debugArrayTypeInfo.fieldInfoProvider().forEach(debugFieldInfo -> this.processField(debugFieldInfo, debugInfoBase, debugContext));
-        debugContext.log("typename %s element type %s base size %d length offset %d%n", typeName, this.elementType.getTypeName(), baseSize, lengthOffset);
+        if (debugContext.isLogEnabled()) {
+            debugContext.log("typename %s element type %s base size %d length offset %d%n", typeName, this.elementType.getTypeName(), baseSize, lengthOffset);
+        }
     }
 
     public TypeEntry getElementType() {

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/ClassEntry.java

@@ -132,13 +132,9 @@ public void addDebugInfo(DebugInfoBase debugInfoBase, DebugTypeInfo debugTypeInf
         DebugInstanceTypeInfo debugInstanceTypeInfo = (DebugInstanceTypeInfo) debugTypeInfo;
         /* Add details of super and interface classes */
         ResolvedJavaType superType = debugInstanceTypeInfo.superClass();
-        String superName;
-        if (superType != null) {
-            superName = superType.toJavaName();
-        } else {
-            superName = "";
+        if (debugContext.isLogEnabled()) {
+            debugContext.log("typename %s adding super %s%n", typeName, superType != null ? superType.toJavaName() : "");
         }
-        debugContext.log("typename %s adding super %s%n", typeName, superName);
         if (superType != null) {
             this.superClass = debugInfoBase.lookupClassEntry(superType);
         }
@@ -250,8 +246,9 @@ public Stream<CompiledMethodEntry> compiledEntries() {
     }
 
     protected void processInterface(ResolvedJavaType interfaceType, DebugInfoBase debugInfoBase, DebugContext debugContext) {
-        String interfaceName = interfaceType.toJavaName();
-        debugContext.log("typename %s adding interface %s%n", typeName, interfaceName);
+        if (debugContext.isLogEnabled()) {
+            debugContext.log("typename %s adding interface %s%n", typeName, interfaceType.toJavaName());
+        }
         ClassEntry entry = debugInfoBase.lookupClassEntry(interfaceType);
         assert entry instanceof InterfaceClassEntry || (entry instanceof ForeignTypeEntry && this instanceof ForeignTypeEntry);
         InterfaceClassEntry interfaceClassEntry = (InterfaceClassEntry) entry;
@@ -263,13 +260,15 @@ protected MethodEntry processMethod(DebugMethodInfo debugMethodInfo, DebugInfoBa
         String methodName = debugMethodInfo.name();
         int line = debugMethodInfo.line();
         ResolvedJavaType resultType = debugMethodInfo.valueType();
-        String resultTypeName = resultType.toJavaName();
         int modifiers = debugMethodInfo.modifiers();
         DebugLocalInfo[] paramInfos = debugMethodInfo.getParamInfo();
         DebugLocalInfo thisParam = debugMethodInfo.getThisParamInfo();
         int paramCount = paramInfos.length;
-        debugContext.log("typename %s adding %s method %s %s(%s)%n",
-                        typeName, memberModifiers(modifiers), resultTypeName, methodName, formatParams(paramInfos));
+        if (debugContext.isLogEnabled()) {
+            String resultTypeName = resultType.toJavaName();
+            debugContext.log("typename %s adding %s method %s %s(%s)%n",
+                            typeName, memberModifiers(modifiers), resultTypeName, methodName, formatParams(paramInfos));
+        }
         TypeEntry resultTypeEntry = debugInfoBase.lookupTypeEntry(resultType);
         TypeEntry[] typeEntries = new TypeEntry[paramCount];
         for (int i = 0; i < paramCount; i++) {

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/DebugInfoBase.java

@@ -294,7 +294,9 @@ public void installDebugInfo(DebugInfoProvider debugInfoProvider) {
             DebugTypeKind typeKind = debugTypeInfo.typeKind();
             int byteSize = debugTypeInfo.size();
 
-            debugContext.log(DebugContext.INFO_LEVEL, "Register %s type %s ", typeKind.toString(), typeName);
+            if (debugContext.isLogEnabled(DebugContext.INFO_LEVEL)) {
+                debugContext.log(DebugContext.INFO_LEVEL, "Register %s type %s ", typeKind.toString(), typeName);
+            }
             String fileName = debugTypeInfo.fileName();
             Path filePath = debugTypeInfo.filePath();
             addTypeEntry(idType, typeName, fileName, filePath, byteSize, typeKind);
@@ -307,7 +309,9 @@ public void installDebugInfo(DebugInfoProvider debugInfoProvider) {
             String typeName = debugTypeInfo.typeName();
             DebugTypeKind typeKind = debugTypeInfo.typeKind();
 
-            debugContext.log(DebugContext.INFO_LEVEL, "Process %s type %s ", typeKind.toString(), typeName);
+            if (debugContext.isLogEnabled(DebugContext.INFO_LEVEL)) {
+                debugContext.log(DebugContext.INFO_LEVEL, "Process %s type %s ", typeKind.toString(), typeName);
+            }
             TypeEntry typeEntry = (idType != null ? lookupTypeEntry(idType) : lookupHeaderType());
             typeEntry.addDebugInfo(this, debugTypeInfo, debugContext);
         }));
@@ -329,7 +333,9 @@ public void installDebugInfo(DebugInfoProvider debugInfoProvider) {
             ClassEntry classEntry = lookupClassEntry(ownerType);
             MethodEntry methodEntry = classEntry.ensureMethodEntryForDebugRangeInfo(debugCodeInfo, this, debugContext);
             PrimaryRange primaryRange = Range.createPrimary(methodEntry, lo, hi, primaryLine);
-            debugContext.log(DebugContext.INFO_LEVEL, "PrimaryRange %s.%s %s %s:%d [0x%x, 0x%x]", ownerType.toJavaName(), methodName, filePath, fileName, primaryLine, lo, hi);
+            if (debugContext.isLogEnabled(DebugContext.INFO_LEVEL)) {
+                debugContext.log(DebugContext.INFO_LEVEL, "PrimaryRange %s.%s %s %s:%d [0x%x, 0x%x]", ownerType.toJavaName(), methodName, filePath, fileName, primaryLine, lo, hi);
+            }
             addPrimaryRange(primaryRange, debugCodeInfo, classEntry);
             /*
              * Record all subranges even if they have no line or file so we at least get a symbol
@@ -517,13 +523,17 @@ private Range addSubrange(DebugLocationInfo locationInfo, PrimaryRange primaryRa
         SubRange subRange = Range.createSubrange(subRangeMethodEntry, lo, hi, line, primaryRange, caller, locationInfo.isLeaf());
         classEntry.indexSubRange(subRange);
         subRangeIndex.put(locationInfo, subRange);
-        debugContext.log(DebugContext.DETAILED_LEVEL, "SubRange %s.%s %d %s:%d [0x%x, 0x%x] (%d, %d)",
-                        ownerType.toJavaName(), methodName, subRange.getDepth(), fullPath, line, lo, hi, loOff, hiOff);
+        if (debugContext.isLogEnabled(DebugContext.DETAILED_LEVEL)) {
+            debugContext.log(DebugContext.DETAILED_LEVEL, "SubRange %s.%s %d %s:%d [0x%x, 0x%x] (%d, %d)",
+                            ownerType.toJavaName(), methodName, subRange.getDepth(), fullPath, line, lo, hi, loOff, hiOff);
+        }
         assert (callerLocationInfo == null || (callerLocationInfo.addressLo() <= loOff && callerLocationInfo.addressHi() >= hiOff)) : "parent range should enclose subrange!";
         DebugLocalValueInfo[] localValueInfos = locationInfo.getLocalValueInfo();
         for (int i = 0; i < localValueInfos.length; i++) {
             DebugLocalValueInfo localValueInfo = localValueInfos[i];
-            debugContext.log(DebugContext.DETAILED_LEVEL, "  locals[%d] %s:%s = %s", localValueInfo.slot(), localValueInfo.name(), localValueInfo.typeName(), localValueInfo);
+            if (debugContext.isLogEnabled(DebugContext.DETAILED_LEVEL)) {
+                debugContext.log(DebugContext.DETAILED_LEVEL, "  locals[%d] %s:%s = %s", localValueInfo.slot(), localValueInfo.name(), localValueInfo.typeName(), localValueInfo);
+            }
         }
         subRange.setLocalValueInfo(localValueInfos);
         return subRange;

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/ForeignTypeEntry.java

@@ -87,10 +87,12 @@ public void addDebugInfo(DebugInfoBase debugInfoBase, DebugTypeInfo debugTypeInf
         if (debugForeignTypeInfo.isSigned()) {
             flags |= FLAG_SIGNED;
         }
-        if (isPointer() && pointerTo != null) {
-            debugContext.log("foreign type %s flags 0x%x referent %s ", typeName, flags, pointerTo.getTypeName());
-        } else {
-            debugContext.log("foreign type %s flags 0x%x", typeName, flags);
+        if (debugContext.isLogEnabled()) {
+            if (isPointer() && pointerTo != null) {
+                debugContext.log("foreign type %s flags 0x%x referent %s ", typeName, flags, pointerTo.getTypeName());
+            } else {
+                debugContext.log("foreign type %s flags 0x%x", typeName, flags);
+            }
         }
     }
 

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/InterfaceClassEntry.java

@@ -56,7 +56,9 @@ public void addDebugInfo(DebugInfoBase debugInfoBase, DebugTypeInfo debugTypeInf
 
     public void addImplementor(ClassEntry classEntry, DebugContext debugContext) {
         implementors.add(classEntry);
-        debugContext.log("typename %s add implementor %s%n", typeName, classEntry.getTypeName());
+        if (debugContext.isLogEnabled()) {
+            debugContext.log("typename %s add implementor %s%n", typeName, classEntry.getTypeName());
+        }
     }
 
     public Stream<ClassEntry> implementors() {

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/PrimitiveTypeEntry.java

@@ -59,7 +59,9 @@ public void addDebugInfo(DebugInfoBase debugInfoBase, DebugTypeInfo debugTypeInf
         flags = debugPrimitiveTypeInfo.flags();
         typeChar = debugPrimitiveTypeInfo.typeChar();
         bitCount = debugPrimitiveTypeInfo.bitCount();
-        debugContext.log("typename %s %s (%d bits)%n", typeName, decodeFlags(), bitCount);
+        if (debugContext.isLogEnabled()) {
+            debugContext.log("typename %s %s (%d bits)%n", typeName, decodeFlags(), bitCount);
+        }
     }
 
     private String decodeFlags() {

substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/StructureTypeEntry.java

@@ -71,8 +71,10 @@ protected FieldEntry addField(DebugFieldInfo debugFieldInfo, DebugInfoBase debug
         int fieldoffset = debugFieldInfo.offset();
         boolean fieldIsEmbedded = debugFieldInfo.isEmbedded();
         int fieldModifiers = debugFieldInfo.modifiers();
-        debugContext.log("typename %s adding %s field %s type %s%s size %s at offset 0x%x%n",
-                        typeName, memberModifiers(fieldModifiers), fieldName, valueTypeName, (fieldIsEmbedded ? "(embedded)" : ""), fieldSize, fieldoffset);
+        if (debugContext.isLogEnabled()) {
+            debugContext.log("typename %s adding %s field %s type %s%s size %s at offset 0x%x%n",
+                            typeName, memberModifiers(fieldModifiers), fieldName, valueTypeName, (fieldIsEmbedded ? "(embedded)" : ""), fieldSize, fieldoffset);
+        }
         TypeEntry valueTypeEntry = debugInfoBase.lookupTypeEntry(valueType);
         /*
          * n.b. the field file may differ from the owning class file when the field is a

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

@@ -685,7 +685,7 @@ protected void doRun(Map<Method, CEntryPointData> entryPoints,
                                     ImageSingletons.lookup(TemporaryBuildDirectoryProvider.class).getTemporaryBuildDirectory());
                     codeCache.layoutConstants();
                     codeCache.layoutMethods(debug, bb, compilationExecutor);
-                    codeCache.buildRuntimeMetadata(bb.getSnippetReflectionProvider(), compilationExecutor);
+                    codeCache.buildRuntimeMetadata(bb.getSnippetReflectionProvider(), compilationExecutor, loader.watchdog::recordActivity);
                 }
 
                 AfterCompilationAccessImpl config = new AfterCompilationAccessImpl(featureHandler, loader, aUniverse, hUniverse, compileQueue.getCompilations(), codeCache, heap, debug,

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

@@ -140,7 +140,7 @@ private enum BuildStage {
         PARSING("Parsing methods", true, true),
         INLINING("Inlining methods", true, false),
         COMPILING("Compiling methods", true, true),
-        LAYOUTING("Layouting methods", true, true),
+        LAYING_OUT("Laying out methods", true, true),
         CREATING("Creating image", true, true);
 
         private static final int NUM_STAGES = values().length;
@@ -511,7 +511,7 @@ public ReporterClosable printCompiling() {
     }
 
     public ReporterClosable printLayouting() {
-        return print(TimerCollection.Registry.LAYOUT, BuildStage.LAYOUTING);
+        return print(TimerCollection.Registry.LAYOUT, BuildStage.LAYING_OUT);
     }
 
     // TODO: merge printCreationStart and printCreationEnd at some point (GR-35721).

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

@@ -49,7 +49,6 @@
 import java.util.concurrent.ForkJoinPool;
 import java.util.stream.Collectors;
 
-import com.oracle.svm.core.meta.MethodPointer;
 import org.graalvm.collections.Pair;
 import org.graalvm.compiler.api.replacements.SnippetReflectionProvider;
 import org.graalvm.compiler.code.CompilationResult;
@@ -84,6 +83,7 @@
 import com.oracle.svm.core.config.ConfigurationValues;
 import com.oracle.svm.core.deopt.DeoptEntryInfopoint;
 import com.oracle.svm.core.graal.code.SubstrateDataBuilder;
+import com.oracle.svm.core.meta.MethodPointer;
 import com.oracle.svm.core.meta.SubstrateMethodPointerConstant;
 import com.oracle.svm.core.option.HostedOptionKey;
 import com.oracle.svm.core.option.HostedOptionValues;
@@ -262,17 +262,18 @@ public int getAlignedConstantsSize() {
         return ConfigurationValues.getObjectLayout().alignUp(getConstantsSize());
     }
 
-    public void buildRuntimeMetadata(SnippetReflectionProvider snippetReflectionProvider, ForkJoinPool threadPool) {
-        buildRuntimeMetadata(snippetReflectionProvider, threadPool, new MethodPointer(getFirstCompilation().getLeft()), WordFactory.signed(getCodeAreaSize()));
+    public void buildRuntimeMetadata(SnippetReflectionProvider snippetReflectionProvider, ForkJoinPool threadPool, Runnable heartbeatCallback) {
+        buildRuntimeMetadata(snippetReflectionProvider, threadPool, heartbeatCallback, new MethodPointer(getFirstCompilation().getLeft()), WordFactory.signed(getCodeAreaSize()));
     }
 
-    protected void buildRuntimeMetadata(SnippetReflectionProvider snippetReflection, ForkJoinPool threadPool, CFunctionPointer firstMethod, UnsignedWord codeSize) {
+    protected void buildRuntimeMetadata(SnippetReflectionProvider snippetReflection, ForkJoinPool threadPool, Runnable heartbeatCallback, CFunctionPointer firstMethod, UnsignedWord codeSize) {
         // Build run-time metadata.
         HostedFrameInfoCustomization frameInfoCustomization = new HostedFrameInfoCustomization();
         CodeInfoEncoder.Encoders encoders = new CodeInfoEncoder.Encoders();
         CodeInfoEncoder codeInfoEncoder = new CodeInfoEncoder(frameInfoCustomization, encoders);
         for (Pair<HostedMethod, CompilationResult> pair : getOrderedCompilations()) {
             encodeMethod(codeInfoEncoder, pair);
+            heartbeatCallback.run();
         }
 
         HostedUniverse hUniverse = imageHeap.hUniverse;