graal
graal copied to clipboard
oracle
[GR-41269] Build output: "other data" is miscalculated
It seems that https://github.com/oracle/graal/pull/4707 has introduced a reporting issue. when debug info is enabled, "other data" is usually negative. An example:
[7/7] Creating image... (24.5s @ 2.14GB)
6.08MB ( 9.26%) for code area: 10,189 compilation units
9.59MB (14.62%) for image heap: 138,041 objects and 85 resources
80.62MB (122.88%) for debug info generated in 15.0s
-32170672.00B (-46.76%) for other data
65.61MB in total
Build: https://github.com/oracle/graal/runs/7838086740?check_suite_focus=true#step:10:844
If you could prepare a fix, @jerboaa, that'd be great. Thanks!
https://github.com/oracle/graal/pull/4707 only indirectly introduced this issue. The determined debuginfo size seems to exceed the actual on-disk size (as determined by objcopy --only-keep-debug <binary> <binary>.debuginfo -> ls -l the size of the <binary>.debuginfo) by about the same size the calculation of debuginfo + heap size + code area exceeds the actual on-disk image size. For example, for an hello world with -H:+SourceLevelDebug I'm seeing these numbers:
(d) debuginfo-bytes: 11577272
(h) heap-bytes: 7266304
(c) code-area-bytes: 4573232
------------------------------------
total size: 22135952
sum (d+h+c): 23416808
delta: -1280856
vs. debuginfo size when using on-disk size of the file generated with objcopy --only-keep-debug <binary> <binary>.debuginfo:
(d) debuginfo-bytes: 10189568
(h) heap-bytes: 7266304
(c) code-area-bytes: 4573232
------------------------------------
total size: 22135952
sum (d+h+c): 22029104
delta: 106848
The former debuginfo size is 11577272 and the latter debuginfo size is 10189568 with a delta of ~1.2 MB. That yields me to believe that the debuginfo size reporting is similarly incorrect as the total image size was prior to #4707.
Thanks for investigating... yeah, sounds like we need a similar fix for the debuginfo.
That yields me to believe that the debuginfo size reporting is similarly incorrect as the total image size was prior to https://github.com/oracle/graal/pull/4707.
Hmm, how is that reported debuginfo size actually calculated?
There is not much room for doubt as to exactly how much generated debuginfo data is written into the file. The generator hands over a byte[] as the contents to be written into each section. So, the amount produced can easily be computed as a sum of the individual byte array sizes (possibly rounded-up to conform with any equirement for section alignment).
That said, comparison of the generated byte count with final image byte count is not so straightforward. The image can include debuginfo merged in from compiled C code during final linking. I don't know if there is any easy way to compute how much this will increase the final size (other than linking and seeing what turns up, obviously).
So, the on-disk debuginfo size could be significantly increased relative to the generated content size. I'd like to understand how we have got to the point where the on-disk size is reported as smaller?
That yields me to believe that the debuginfo size reporting is similarly incorrect as the total image size was prior to #4707.
Hmm, how is that reported debuginfo size actually calculated?
There is not much room for doubt as to exactly how much generated debuginfo data is written into the file. The generator hands over a
byte[]as the contents to be written into each section. So, the amount produced can easily be computed as a sum of the individual byte array sizes (possibly rounded-up to conform with any equirement for section alignment).That said, comparison of the generated byte count with final image byte count is not so straightforward. The image can include debuginfo merged in from compiled C code during final linking. I don't know if there is any easy way to compute how much this will increase the final size (other than linking and seeing what turns up, obviously).
So, the on-disk debuginfo size could be significantly increased relative to the generated content size. I'd like to understand how we have got to the point where the on-disk size is reported as smaller?
The comparison I've done is:
- Generate a native-image with debuginfo:
native-image -H:BuildOutputJSONFile=build_stats.json -H:+SourceLevelDebug -g HelloWorld hello-debug - Get the number what the native image generator thinks the debuginfo size is:
cat build_stats.json | jq .image_details.debug_info.bytes=>11582272 - Strip the debuginfo from the
hello-debugbinary usingobjcopy:
$ objcopy --only-keep-debug hello-debug hello-debug.debuginfo
$ ls -l hello-debug.debuginfo
-rwxr-xr-x. 1 sgehwolf sgehwolf 10194576 Aug 16 15:38 hello-debug.debuginfo
- Compare that number to the one the native image generator reports. See that it's larger. The native image reported number is
11582272vs.10194576on-disk.
Hmm, how is that reported debuginfo size actually calculated?
AFAIK it's this:
debugInfoSize = 0;
String debugIdentifier = OS.getCurrent() == OS.DARWIN ? "__debug" : ".debug";
for (Element e : objectFile.getElements()) {
if (e.getName().contains(debugIdentifier)) {
debugInfoSize += e.getMemSize(objectFile.getDecisionsByElement());
}
}
Looking at e.getName().contains(debugIdentifier), I wonder if that's correct. I see this on readelf --sections on hello-debug:
[29] .debug_aranges PROGBITS 0000000000000000 00b65480
0000000000029290 0000000000000000 0 0 8
[30] .debug_info PROGBITS 0000000000000000 00b8e710
000000000014d304 0000000000000000 0 0 8
[31] .debug_abbrev PROGBITS 0000000000000000 00cdba18
0000000000000f3b 0000000000000000 0 0 8
[32] .debug_line PROGBITS 0000000000000000 00cdc958
00000000000d0e49 0000000000000000 0 0 8
[33] .debug_frame PROGBITS 0000000000000000 00dad7a8
000000000004a6a8 0000000000000000 0 0 8
[34] .debug_str PROGBITS 0000000000000000 00df7e50
00000000000ef07e 0000000000000000 0 0 8
[35] .debug_loc PROGBITS 0000000000000000 00ee6ed0
00000000006308d1 0000000000000000 0 0 8
[36] .debug_ranges PROGBITS 0000000000000000 015177a1
0000000000001600 0000000000000000 0 0 1
Should it really count all .debug* sections?
Ah, ok. I think I may have the answer to this then.
Several of the standard .debug_<xxx> sections include fields that are relocatable addresses. For example, a method location record includes a low and high pc. Each of these is specified using a relocation, computed by adding a constant offset to the virtual memory base address (VMA) of the .text section.
Any section with name .debug_xxx that requires relocs has a corresponding section with name .rela.debug_xxx wher edetails of the reloc operation and parameters are written. So, the above code is counting the bytes in the reloc sections as well as the bytes in the debug sections. That's a problem because the reloc section data is squeezed out of the picture during final linking. It is only the bytes for the non-reloc sections that make it into the final image.
A solution which would work for the current ELF/Linux generator is this
debugInfoSize = 0;
String debugIdentifier = OS.getCurrent() == OS.DARWIN ? "__debug" : ".debug";
for (Element e : objectFile.getElements()) {
String name = e.getName()
if (name.contains(debugIdentifier) &&
!name.startsWith(".rela")) {
debugInfoSize += e.getMemSize(objectFile.getDecisionsByElement());
}
}
That will not count the bytes in the reloc sections.
Someone with better knowledge of the object file code needs to deal with DARWIN.
There is also a remaining issue on Linux. The prefix ".rela" will work with the current debug code but that is only modulo the current definition of ObjectFile.useExplicitAddend(int). The prefix might need to be specified as ".rel". A proper solution means the code above really ought to check what that method returns and construct the prefix accordingly. When creating the debug info reloc sections the int argument is set to 0 but only because 1) I had no idea what value to pass and 2) it currently makes no difference. A proper solution fro this bit of code should at the very least call useExplicitAddend with argument 0 or alternatively fix the reloc section create to use a sensible value and adjust the call here accordingly.
Should it really count all .debug* sections?
Yes, the ones you list all go into the final image.
@fniephaus I'm not sure I'm the right assignee for this. Unassigning myself.
I've tested this patch on Linux and it seems promising (for that platform):
commit 67c631e234be7db506eb3ab7995d929e6164c29a (HEAD -> debuginfo-neg-size)
Author: Severin Gehwolf <[email protected]>
Date: Tue Aug 16 16:21:27 2022 +0200
Test debuginfo size fix
diff --git a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImage.java b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImage.java
index 4d9d577d8b2a..2ec21434a97d 100644
--- a/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImage.java
+++ b/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/image/NativeImage.java
@@ -184,7 +184,8 @@ public abstract class NativeImage extends AbstractImage {
debugInfoSize = 0;
String debugIdentifier = OS.getCurrent() == OS.DARWIN ? "__debug" : ".debug";
for (Element e : objectFile.getElements()) {
- if (e.getName().contains(debugIdentifier)) {
+ String name = e.getName();
+ if (name.contains(debugIdentifier) && !name.startsWith(".rela")) {
debugInfoSize += e.getMemSize(objectFile.getDecisionsByElement());
}
}
Build output now seems better:
native-image -H:BuildOutputJSONFile=build_stats.json -H:+SourceLevelDebug -g -cp mandrel-build HelloWorld hello-debug
========================================================================================================================
GraalVM Native Image: Generating 'hello-debug' (executable)...
========================================================================================================================
[1/7] Initializing... (3.2s @ 0.21GB)
Version info: 'GraalVM 21.3.3-dev Java 17 Mandrel Distribution'
Java version info: '17.0.4-beta+7-202206282316'
C compiler: gcc (redhat, x86_64, 12.1.1)
Garbage collector: Serial GC
[2/7] Performing analysis... [*****] (10.5s @ 0.82GB)
2,848 (73.42%) of 3,879 classes reachable
3,441 (51.22%) of 6,718 fields reachable
12,575 (43.27%) of 29,064 methods reachable
28 classes, 0 fields, and 317 methods registered for reflection
58 classes, 58 fields, and 52 methods registered for JNI access
4 native libraries: dl, pthread, rt, z
[3/7] Building universe... (1.7s @ 0.48GB)
[4/7] Parsing methods... [*] (1.4s @ 0.46GB)
[5/7] Inlining methods... [***] (1.3s @ 1.25GB)
[6/7] Compiling methods... [***] (10.8s @ 0.96GB)
[7/7] Creating image... (6.9s @ 4.06GB)
4.36MB (20.66%) for code area: 7,239 compilation units
6.93MB (32.82%) for image heap: 97,196 objects and 5 resources
9.57MB (45.32%) for debug info generated in 3.4s
258.26KB ( 1.19%) for other data
21.11MB in total
------------------------------------------------------------------------------------------------------------------------
Top 10 packages in code area: Top 10 object types in image heap:
700.53KB java.util 908.44KB java.lang.String
352.26KB java.lang 904.57KB byte[] for code metadata
279.51KB java.text 843.52KB byte[] for general heap data
229.59KB java.util.regex 625.16KB java.lang.Class
204.38KB java.util.concurrent 526.50KB byte[] for java.lang.String
157.08KB java.math 430.88KB java.util.HashMap$Node
126.58KB com.oracle.svm.core.genscavenge 222.50KB com.oracle.svm.core.hub.DynamicHubCompanion
123.00KB java.lang.invoke 206.36KB java.util.HashMap$Node[]
100.75KB com.oracle.svm.core.code 158.89KB java.lang.String[]
100.71KB java.util.stream 155.81KB java.util.concurrent.ConcurrentHashMap$Node
1.99MB for 120 more packages 1.55MB for 776 more object types
------------------------------------------------------------------------------------------------------------------------
0.9s (2.3% of total time) in 20 GCs | Peak RSS: 4.39GB | CPU load: 5.99
------------------------------------------------------------------------------------------------------------------------
Produced artifacts:
/disk/graal/upstream-sources/graal/build_stats.json (json)
/disk/graal/upstream-sources/graal/hello-debug (executable, debug_info)
/disk/graal/upstream-sources/graal/hello-debug.build_artifacts.txt (txt)
/disk/graal/upstream-sources/graal/sources (debug_info)
========================================================================================================================
Finished generating 'hello-debug' in 37.3s.
Compare to a non-debuginfo build:
native-image -H:BuildOutputJSONFile=build_stats.json -cp mandrel-build HelloWorld hello-debug
========================================================================================================================
GraalVM Native Image: Generating 'hello-debug' (executable)...
========================================================================================================================
[1/7] Initializing... (3.1s @ 0.21GB)
Version info: 'GraalVM 21.3.3-dev Java 17 Mandrel Distribution'
Java version info: '17.0.4-beta+7-202206282316'
C compiler: gcc (redhat, x86_64, 12.1.1)
Garbage collector: Serial GC
[2/7] Performing analysis... [*****] (10.9s @ 0.88GB)
2,848 (73.44%) of 3,878 classes reachable
3,437 (51.18%) of 6,716 fields reachable
12,572 (43.26%) of 29,061 methods reachable
28 classes, 0 fields, and 317 methods registered for reflection
58 classes, 58 fields, and 52 methods registered for JNI access
4 native libraries: dl, pthread, rt, z
[3/7] Building universe... (1.6s @ 0.44GB)
[4/7] Parsing methods... [*] (1.2s @ 1.15GB)
[5/7] Inlining methods... [***] (0.7s @ 0.59GB)
[6/7] Compiling methods... [***] (11.3s @ 0.62GB)
[7/7] Creating image... (2.0s @ 1.07GB)
4.06MB (36.12%) for code area: 7,225 compilation units
6.93MB (61.64%) for image heap: 97,186 objects and 5 resources
258.41KB ( 2.24%) for other data
11.24MB in total
------------------------------------------------------------------------------------------------------------------------
Top 10 packages in code area: Top 10 object types in image heap:
656.25KB java.util 908.25KB java.lang.String
329.20KB java.lang 897.75KB byte[] for code metadata
264.91KB java.text 843.42KB byte[] for general heap data
216.35KB java.util.regex 625.03KB java.lang.Class
192.82KB java.util.concurrent 526.44KB byte[] for java.lang.String
146.93KB java.math 430.88KB java.util.HashMap$Node
116.98KB java.lang.invoke 222.50KB com.oracle.svm.core.hub.DynamicHubCompanion
105.05KB com.oracle.svm.core.genscavenge 206.36KB java.util.HashMap$Node[]
94.10KB java.util.logging 158.86KB java.lang.String[]
93.86KB java.util.stream 155.81KB java.util.concurrent.ConcurrentHashMap$Node
1.84MB for 119 more packages 1.55MB for 775 more object types
------------------------------------------------------------------------------------------------------------------------
0.8s (2.3% of total time) in 19 GCs | Peak RSS: 3.12GB | CPU load: 6.24
------------------------------------------------------------------------------------------------------------------------
Produced artifacts:
/disk/graal/upstream-sources/graal/build_stats.json (json)
/disk/graal/upstream-sources/graal/hello-debug (executable)
/disk/graal/upstream-sources/graal/hello-debug.build_artifacts.txt (txt)
========================================================================================================================
Finished generating 'hello-debug' in 32.5s.
Also the debuginfo size comparing on-disk vs. what the build output produces:
on-disk: 10195464
build-output: 10037856
I pushed your fix, see https://github.com/oracle/graal/commit/0e7ba4b15c0026009033a6ce5f9cf84cddcc4598.