DebugSymbolsTest.debugSymbolsQuarkus fails with latest graal/mandrel main #160
Comments
|
First failure from ~1.5 weeks ago (May 23): |
|
The test seems just to time out. So it looks like a perf problem? When debugging locally, gdb just seems to hang when trying to set a breakpoint, but if you wait long enough it'll eventually give you your prompt back: So it takes on the order of 3 minutes to set the breakpoint. |
|
The test times out after 10 seconds, which is reasonable. |
WoW! That's a lot... And it didn't use to take that long in the past... |
|
The issue was introduced by quarkusio/quarkus#33203, i.e. the addition of Building quarkus-microprofile-full with: instead of the current: Results in the breakpoint being set in seconds. |
|
Now the question is whether this still makes sense to keep as the default. Not sure what's a better default, waiting a few minutes for gdb to load the symbols and get highly accurate mappings or getting slightly worse accuracy but only waiting a few seconds? Probably worth discussing with the Quarkus devs. |
|
I don't recall experiencing this 😱 |
Hmm, with |
|
It always used to take some time but I don't have exact numbers... I noticed (while looking for the cause of this) that oracle/graal#6419 seems to result in an increase in gdb start-up times |
|
This is down to two factors: a lot of extra debug info records for local var data and the recent change to merge all debug info into one big compile unit. So gdb start up requires a big slurp of all the debug info at once. We need to think about maybe switching off source mappnigs but that's not so good for the eventual debug experience. |
|
As to the numbers here are some (seems an order of magnitude difference). Time it takes to set
Details Details |
|
Do you have the size of the debuginfo files for those two cases? Also, if you dump the info section as text what are the relative line counts? (objdump --dwarf=info |
According to the native-image build output:
Seems also an order of magnitude difference. |
|
For reference when using a |
|
Yeah, the on-disk size disparity is bad but the difference in the DIE (info record) count is the real measure of how much more work needs to be done. There may also be some supra-linearity in the growth even when measured in DIEs because local var info needs to be organized into a tree structure and cross-referenced to the type info for the var type. Still that is an order of magnitude (actually more) extra information about what data the program is handling which makes all the difference when you are trying to debug optimized code. I'd hate to not have that info when a real production bug turns up. |
Just to be sure: are you certain that is built to include all local var info? I'm not implying otherwise not saying that this result is particularly surprising. This result could well just be down to collapsing all that info into one CU. The extra var info may multiply a CU size by 10 but with 22.3 there will be at least 1000 per-class CUs in even a small program. So, even if you had to load 10 CUs in order to resolve the main class that would reduce the loaded record count by 100. One other thing I might be able do speed up the reading is add sibling links to some of the top level DIEs that have a lot of children, in particular the method definition DIEs that includes a tree of var info DIES as children. That would allow gdb to do a quick traversal of the top level DIES when looking for a give method without having to slurp the whole tree. I'll experiment with that to see if it helps. |
No, I'm not sure at all. How can I make sure? Is that in 22.3? I don't know the state of debuginfo between 22.3.2.0 and revision |
|
@jerboaa I just checked: 22.3 is like 23.0 i.e. it relies on you setting SourceLevelDebug to enable generation of full infopoints (local var info is derived from Infopoint and SourceMapping instances). So, if you set that for the 22.3 build then this is an apples to apples comparison. |
|
@adinn Hmm, we don't seem to set that option anywhere. |
|
@jerboaa Well, a comparison without Option The I think However, that is not to suggest this is the full story. Other flags include: The first one must be supplied for debug info to work at all. The second one is needed in order for perf and valgrind to be able to connect mangled method names to code addresses (they need linker symbols as well as debug info to do so). The third one ensures that file and line number info is attached to nodes during compiler graph building and retained as far as possible during transformation. Omitting it can result in less, or less accurate, local var info. |
OK. FWIW, the above runs were "omitted in both" comparisons as the default is
It's the other way around. 22.3 doesn't have |
|
Another run with
|
|
Worst case seems to be
|
|
We've increased the GDB timeout for the quarkus debuginfo test to 5 minutes (#163) as an interim measure so as to not overlook other issues in CI meanwhile. |
|
It looks like 5 minutes are not enough for github actions, we will need to further increase it: |
|
I'd really like to look at an example program that manifests this behaviour then see what the debug info looks like and what gdb is doing with it. Most important of all I'd like to be able to build the native image myself using whatever modified version of the debug info generator, native image command line args and gdb command line args I need to test out what is going on (in particular I will likely need to run gdb itself under gdb). I cannot do that as things currently stand because the test setup does not allow me to drive the build or the gdb run. Is there a simpler setup I can use? |
|
I don't know about "simpler" but you can try the following: If you still want to manually run HTH |
|
Thanks Foivos. There is one point that is still unclear in your explanation. You say: What needs to be at the end of that path? (I need it to be something I have built from my dev tree). |
|
You can either use the output of |
|
For the manual |
|
Thanks. I am now generating full debug info and full log output for the generator (after I worked out how to escape the commas in the comma separated list of options to the |
|
I am not seeing any significant delay in the debug image I just built Here is the build step: Note the debug info-specific arguments I provided and the reported debug info generation stats The generated image and debug info files are as follows i.e. roughly 80Mb of image and likewise of debug info. The output log shows full local var info being added e.g. It also shows a very large number of types, methods and fields being registered as present in the debug info. n.b. the last count omits fields that are declared but not defined I ran this up in gdb as per Serverin's example above and got these timings: Allowing for the time I took to type the commands the actual startup was a matter of a few (2-3?) seconds. n.b. This is fedora 37 on bare metal: So, I am confused. Anyone have any idea what is going on? n.b. When I step through the program in gdb under emacs source files are being located. However, the sources directory appears to be missing a fair number of source files that correspond to jars downloaded by Maven. I am wondering if that might be an issue. Is there a simple way to ensure all source jars for the project (including dependency sources) are downloaded alongside the class jars? |
@adinn I think you are missing |
|
Yes, but that's not the real problem (a slowdown was observed even without that flag being set). The real problem was that I was using a substrate build (of native-image) that was built from an older branch to generate the quarkus app (doh!). I rebuilt substrate from head and the resulting quarkus app image reproduced the problem. I'm debugging gdb now to see where all the time is going. |
|
Ok, so the generated image and debug info with all flag set (including When I ran up gdb the VMEM went up to 6.9GB and RSS to 5.8GB. The cpu was at about 12% so it looks like it is spending an enormous amount of time and space reading and modelling the 300Mb of DWARF info. |
|
I have identified that the delay that has been introduced by the move to one CU occurs both when reading file+line info and when reading type/code info. So, that means it is not all to do with the inclusion of local vars. I also believe I have pinned down the major cause of the cost difference as far line info is concerned. I'm not sure it accounts for all the extra time taken but it is certainly a large part of it. My current native image for the quarkus app includes 18626 classes 1131 source file dir paths and and 10122 source file names. That's a lot more than the 4382 in a simple hello world app. In the old model there was a dir and line number table for each CU i.e. for each class. So the file index for an owning class C included an entry for C itself plus an entry for every classes C' which has a method C'.m' that gets inlined into a top level compiled method C.m. For many classes the file count was zero or 1 (a lot of classes have no top level compiled methods). For a lot of classes it was small (1 - 10). For a few classes it might rise up to maybe 100. So, gdb creates a name table array for each class with up to maybe 100 entries and populates a list of of file info records which grows up to at most around 100 entries. In the new model all dir paths and files are listed in the one dir path and file index belonging to the the line number table for the one shared CU. So, gdb populates its name table with an array with 10122 strings and then builds a list of file info records which grows up to 10122 entries. The problem happens when gdb begins processing the line number table data. This encodes line info for all code addresses in compiled code in a state machine representation. The important thing to bear in mind is that the amount of state machine data is unchanged between old and new model. The encoding works through code addresses from the start of the first top-level compiled method to the end of the last top-level compiled method. Previously it was split into multiple sections by class/CU each with its own small dir path and file index and gdb could read each section one at a time. It now occurs in one big lump with one of each type of index and gdb has to read it all in one go. The slow down is not simply (or even primarily) having to read the data in one big slurp. The biggest problem is the algorithm that reads an individual line table. Every time the address info progresses into or out of a new top level compiled method or inlined method the current file index is updated and gdb has to locate the line info for record the associated file. It translates the index to the correspoding string name and then linearly searches its current list of line info records for one whose name string compares equal. So, this algorithm is o(N^2) in the new model where N = the total file count. In the old model it is essentially o(N). i.e. even if you have to read all the line info in the old model you execute instructions roughly proportional to 10000 * K for K probably somewhere well below 10, whereas with the new model you get something proportional to 10000 * 10000. I'll have a think about what to do about this but it is not obvious to me that there is a solution that does not involve re-introducing multiple CUs because there is a 1-1 map between CUs and line number tables. Meantime I will also see if I can work out why the reading the code/type info is also taking longer. |
|
@adinn Thanks for the analysis. Please use this gdb snippet for the timing stats though (over manual It should print the time in seconds (including fractionals) it takes to set the breakpoint. |
|
Resulting output is: |
|
Thanks. That roughly matches my measurements in #160 (comment) |
|
I looked into this further to get some feel for how costly the whole process is, not just processing the line data but also processing info section entries, and wher ethe balance lies between these and other operations. After parsing the Java CU for the info section and then processing the line number table for that CU located in the line section, gdb goes on to process the full tree of records (DIEs) that the CU contains. This includes recursively indexing, for every compiled method DIE, the tree of inlined subroutine sub-records. That latter operation appears to be by far the largest part of the remaining processing work. That's because this tree lists for every code address in the method at which call info is present the inlined or top-level method the code originates from plus an associated file and line number. Because of the depth of Java inlining these inline subrecord trees are often very large. The initial parsing seems to be very quick. The subsequent two steps, line info processing then DIE processing, are where almost all the time is spent processing debug info (something like 99%). I measured the times when running with my (debug) build of gdb and it was roughly 240 secs processing line info and 100 secs processing DIEs. The absolute times and the ratio might well turn out to be different when debugging with a non-debug build of gdb but the ratio does at least give a rough indication of the proportion of time spent on each task. Also, during processing, the scratch data used by gdb to track the info it was building up from these line and info sections increased the VMEM to 6GB and the resident memory (RSS) to about 2.5GB. Most of this memory was freed at the end of DIE processing dropping back to about 2.0 GB and 0.9 GB. The difficulty here is that the extra line processing time grows in part because of having to check each file against the list of all files, which is determined by the number of fires actually referenced in the line section. However, it also grows because there are more file checks when there are more inlined method traces. The DIE processing ought to grow linearly with the number of inlined method traces, although the depth of tree/node count for the tree will imply more work. In an attempt to isolate these two effects I tweaked the full debug options to always include the following settings
The idea was to successively reduce the inline trace count. However, it turns out that configs 2, 3 and 4 performed identically (modulo a tiny amount of noise). The following tables show some key stats for the first 2 configs:
If both UseSourceMappings and TrackNodeSourcePosition are enabled the debug info size is nearly tripled.
Although there are 18,000 classes with 10,000 associated source files only 1/3rd of the files are actually referenced from the Java CU's line number table. However, enabling both options means that the number of file switch operations during line info processing increases 4-fold.
The number of inlined subroutine trees in the info section grows by just over 3 when both options are enabled while the number of nodes in those trees grows by roughly 9. So, the average tree depth goes up by a factor of 3.
Overall the line processing time increases by just over 4 and the die processing by around 11.
The most alarming issue is the amount of excess scratch memory needed to process the line info when both options are enabled. This memory is released after DIE processing taking the image VMem and RSS back to around 1.8 and 0.9. With either option omitted the difference between peak VMem/RSS and the values after processing is almost non-existent. I think this is probably because the full config involves many repeated visits to files each of which creates scratch data that later needs to be freed freed while the lower configs involve few repeat visits. In particular the code I identified that traverses the file lists appears to be creating a lot of copies of strings formed by concatenating a dir path and a file name. It also looks like it is reallocating a lot of temporary array structures that are used to track visited locations in each file and only freeing these arrays at the end of processing. So, it seems the growth here is distinctly non-linear. I think the only way to bring these numbers down is to find some way to return to using multiple CUs that also allows out of (class) order generation of compiled method code. That may well allow the inline tree info to be loaded incrementally rather than all at once during startup. It should also allow processing of each line table to be much quicker as per table file ref counts will be substantially lower, ensuring that each individual file switch only involves traversal of a comparably reduced file record list. I will investigate this after reporting the problem to the upstream GraalVM team. |
It doesn't look like the 10 minute timeout solves it reliably either: https://github.com/graalvm/mandrel/actions/runs/5295670650/jobs/9586454998#step:11:8896 |
|
I prepared a fix for this that factors out compiled method details for each class into a single compiled method CU (separate from the types CU) when its methods occupy a single range, or a group of compiled method CUs when they are factored into subsets with discontiguous subranges thanks to interleaving of code form other class's methods. That gives each compiled method CU its own line table which means that for full debug info the time to set a breakpoint comes down from > 200 seconds to 3 seconds. Unfortunately, it also means that setting a method breakpoint That is clearly an unacceptable problem when it comes to usability (as an example, it breaks the debug info test when it tries to break a method used to test foreign types). I have not been able to come up with a way of making sure gdb automatically cross-indexes the declaration in the types CU with the definition in the separate compiled method CU. I believe I am going to have to revert to using a CU per class in order to ensure that the declarations and definitions stay together while still keeping CU file counts down to a manageable size. I checked the DWARF spec and found out that there is a way to deal with the CUs having discontinuous subranges (the problem that led to merging all the info). Instead of a lo and hi watermark an info CU can point to a table or address ranges listed in a separate |
|
I have patched the generator to split the info into a compile unit per class. This brings down the line processing overhead enormously -- to around a second. Most CUs have only a small number of files. There are occasionally CUs with a few hundred files but even that is not enough to create a large processing load. Unfortunately, the patch does not remove all the overhead in processing inline method hierarchies. The overall time to set the breakpoint is now down to 60 seconds. So, this patch has reduced the inline method processing cost (was ~100 seconds) but it is still large. I ran gdb under perf to identify where the time is spent and I don't think I can improve on this result. Processing an inline tree involves a recursive traversal of the relevant inline nodes. perf shows most of the time spent in a hierarchy of recursive calls from The first call to read_func_scope is for the compiled method info (i.e. inline depth 0). The recursive entries represent processing of an inline call at the equivalent depth in the inline tree. So, the figure of 0.73% for the 11th call represents time spent processing nodes at depth 10 in an inline tree (there may be trees with greater depths but perf has not spotted them). There is no way to make processing this info run faster other dropping inline nodes from the generated info, for example by limiting the inline tree depth. Even then you need a very low limit for this to cut the time significantly e.g. to halve the time you would need to stop at inline depth 3. |
|
Fix is in the upstream merge queue: oracle/graal#6984 We shall see... |
|
Upstream fix is now merged. Hopefully the CI will succeed tomorrow :) |
Fingers crossed. |
oracle/graal#6984 reduced the time spent reading debyg symbols but it's still noticeable. This PR re-adjusts the timeouts to a timeout of 60 seconds. Relates to Karm#160
oracle/graal#6984 reduced the time spent reading debyg symbols but it's still noticeable. This PR re-adjusts the timeouts to a timeout of 60 seconds. Relates to #160
|
Closed by oracle/graal#6984 and #170 |
Fails locally with:
The text was updated successfully, but these errors were encountered: