Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[GR-33516] Updated fix for inline debuginfo to fix issue 2701 #3745

Merged
merged 27 commits into from
Sep 8, 2021

Conversation

adinn
Copy link
Collaborator

@adinn adinn commented Sep 1, 2021

This PR supersedes PR #2880 posted by @zakkak with one extra commit. With that extra change the PR should be ready for review and able to close issue #2701.

The PR supplies a small fix to the compiler which ensures that inline call source positions are propagated through to compilation results.

It also updates and corrects the debuginfotest driver script to correctly validate the processing of those inline source positions into debug info embedded in a native image.

zakkak and others added 23 commits August 17, 2021 14:46
If line gets successfully retrieved from subrange instead of
primaryrange get file index from the subrange since the line might be
from a different file for inlined methods.
When using -H:+OmitInlinedMethodDebugLineInfo we know that ranges are
not expected to have inlined subranges so we can avoid looping over
them to see if we need to generate inline debug info.
This way we save space and time by not replicating abstract inline DIEs
in the caller's CU.
* remove line records with zero extent
* remove caller marking substitution entry (bci = -1)
PrimaryEntry provides a top-down subrange iterator that performs a
depth-first traversal of the call-graph and a leaf subrange iterator
that performs a depth-first traversal returning only the leafs.

The sibling nodes in the tree are being merged whenever possible to
reduce the debuginfo size.

Co-authored-by: Foivos Zakkak <fzakkak@redhat.com>
Co-authored-by: Andrew Dinn <adinn@redhat.com>
This way we avoid the expensive calls to "toJavaName".

This patch reduces the time spend in debug info generation from ~12s to
5s.
@olpaw olpaw self-requested a review September 1, 2021 13:35
@olpaw olpaw added this to To do in Native Image via automation Sep 1, 2021
@olpaw olpaw moved this from To do to In progress in Native Image Sep 1, 2021
@olpaw olpaw added this to the 21.3 milestone Sep 1, 2021
@olpaw olpaw linked an issue Sep 1, 2021 that may be closed by this pull request
Copy link
Member

@olpaw olpaw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks fine overall.
I will run this in our CI now and give it a deeper second look.

Please amend b08c6ce to have the commit message start with uppercase (like all other commits).

@olpaw olpaw changed the title Updated fix for inline debuginfo to fix issue 2701 [GR-33516] Updated fix for inline debuginfo to fix issue 2701 Sep 1, 2021
@olpaw olpaw self-assigned this Sep 1, 2021
Copy original source position in InvokeWithExceptionNode.replaceWithInvoke
Update debug info test to resstore check for resulting inline frames
@adinn
Copy link
Collaborator Author

adinn commented Sep 1, 2021

@olpaw wrote:

Please amend b08c6ce to have the commit message start with uppercase (like all other commits).

Done

@olpaw
Copy link
Member

olpaw commented Sep 1, 2021

One of our Windows gates triggers our deadlock-during-image-building detection with the following stacks:

=== Image generator watchdog detected no activity. This can be a sign of a deadlock during image building. Dumping all stack traces. Current time: Wed Sep 01 07:33:12 PDT 2021
"Thread-11" Id=48 in RUNNABLE (running in native)
    at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method)
    at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:144)
"Thread-9" Id=44 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@6d304f9d
"Thread-8" Id=43 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@dcfda20
"Thread-7" Id=42 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@a4b2d8f
"Thread-6" Id=41 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@1fdfafd2
"Thread-5" Id=40 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@5b07730f
"Thread-4" Id=39 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@58ebfd03
"Thread-3" Id=38 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@1080b026
"Thread-2" Id=37 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    Locked synchronizers: count = 1
      - java.util.concurrent.ThreadPoolExecutor$Worker@5b43fbf6
"Thread-1" Id=36 in RUNNABLE (running in native)
    at sun.nio.ch.Iocp.getQueuedCompletionStatus(Native Method)
    at sun.nio.ch.Iocp.access$300(Iocp.java:46)
    at sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:333)
    at java.lang.Thread.run(Thread.java:748)
"Thread-0" Id=26 in RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
    at com.oracle.svm.hosted.DeadlockWatchdog.threadDump(DeadlockWatchdog.java:113)
    at com.oracle.svm.hosted.DeadlockWatchdog.watchdogThread(DeadlockWatchdog.java:80)
    at com.oracle.svm.hosted.DeadlockWatchdog$$Lambda$75/951741667.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)
"Attach Listener" Id=5 in RUNNABLE
"Signal Dispatcher" Id=4 in RUNNABLE
"Finalizer" Id=3 in WAITING on lock=java.lang.ref.ReferenceQueue$Lock@385dd2ad
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
"Reference Handler" Id=2 in WAITING on lock=java.lang.ref.Reference$Lock@369a2bd6
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"main" Id=1 in RUNNABLE
    at com.oracle.objectfile.debugentry.MethodEntry.compareTo(MethodEntry.java:167)
    at com.oracle.objectfile.debugentry.ClassEntry.ensureMethodEntryForDebugRangeInfo(ClassEntry.java:351)
    at com.oracle.objectfile.debugentry.DebugInfoBase.lambda$null$5(DebugInfoBase.java:250)
    at com.oracle.objectfile.debugentry.DebugInfoBase$$Lambda$1260/1003464708.accept(Unknown Source)
    at com.oracle.svm.hosted.image.NativeImageDebugInfoProvider$NativeImageDebugCodeInfo.debugContext(NativeImageDebugInfoProvider.java:840)
    at com.oracle.objectfile.debugentry.DebugInfoBase.lambda$installDebugInfo$6(DebugInfoBase.java:236)
    at com.oracle.objectfile.debugentry.DebugInfoBase$$Lambda$1259/350351113.accept(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
    at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
    at java.util.TreeMap$EntrySpliterator.forEachRemaining(TreeMap.java:2969)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
    at com.oracle.objectfile.debugentry.DebugInfoBase.installDebugInfo(DebugInfoBase.java:236)
    at com.oracle.objectfile.pecoff.PECoffObjectFile.installDebugInfo(PECoffObjectFile.java:726)
    at com.oracle.svm.hosted.image.NativeImage.build(NativeImage.java:456)
    at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:635)
    at com.oracle.svm.hosted.NativeImageGenerator.run(NativeImageGenerator.java:493)
    at com.oracle.svm.hosted.NativeImageGeneratorRunner.buildImage(NativeImageGeneratorRunner.java:400)
    at com.oracle.svm.hosted.NativeImageGeneratorRunner.build(NativeImageGeneratorRunner.java:566)
    at com.oracle.svm.hosted.NativeImageGeneratorRunner.main(NativeImageGeneratorRunner.java:122)

I will see if I can come up with a reproducer.

@adinn
Copy link
Collaborator Author

adinn commented Sep 1, 2021

One of our Windows gates triggers our deadlock-during-image-building detection with the following stacks:

 . . .
   "main" Id=1 in RUNNABLE
   at com.oracle.objectfile.debugentry.MethodEntry.compareTo(MethodEntry.java:167)
   at com.oracle.objectfile.debugentry.ClassEntry.ensureMethodEntryForDebugRangeInfo(ClassEntry.java:351)    
. . .

Interesting that this is wedged in the code that is sorting the class's method list. Foivos employed a sort to make it quicker to lookup existing entries when a method already exists . I think it is a much better idea to employ a separate hash table index to ensure that this check is constant time (that's what I did for all the other parts of the model). I'll prepare a revision to the patch do that.

@adinn
Copy link
Collaborator Author

adinn commented Sep 6, 2021

@olpaw I just pushed a fix to use a hash index rather than sorting the methods list. Let's see if that fixes the gate timeout.

n.b. I also had to fix a regression I introduced into the debuginfo test script when I was updating to allow for proper inline info. This meant some inline backtrace output was not being correctly validated (the backtraces were still correct). The tests are now all passing with the expected output.

@olpaw
Copy link
Member

olpaw commented Sep 6, 2021

Hi @adinn
I updated the internal PR with your latest changes. Rerunning CI now. I will keep you updated.

@olpaw
Copy link
Member

olpaw commented Sep 6, 2021

@adinn it seems you have a leftover from sorting methods list:

 1. ERROR in /home/runner/work/graal/graal/substratevm/src/com.oracle.objectfile/src/com/oracle/objectfile/debugentry/ClassEntry.java (at line 369)
	private static boolean listIsSorted(List<MethodEntry> list) {
	                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
The method listIsSorted(List<MethodEntry>) from the type ClassEntry is never used locally
----------
1 problem (1 error)

@adinn
Copy link
Collaborator Author

adinn commented Sep 6, 2021

@olpaw The latest push has the redundant code removed.

Testing has one failure which seems to be spurious (on jdk11 GraalCheckIntrinsics.test checks for float and double copySign intrinsics are marked as ignored then that is raised as a red flag when intrinsics are found).

@olpaw
Copy link
Member

olpaw commented Sep 6, 2021

I will keep you updated.

commit 21d9ca3929736a93ea86335a92d13d33e9161792 (HEAD -> fix-2701, origin/fix-2701)
Author: Andrew Dinn <adinn@redhat.com>
Date:   Mon Sep 6 12:16:11 2021 +0100

    remove redundant methods and fields
    ^
    |
    +-- Hey ... you did it again ;-)

@adinn please start commit messages with uppercase letters.

Apart from that it looks good now.

All tests passed except for the style gates (I started running gates before you added 21d9ca3)

@adinn
Copy link
Collaborator Author

adinn commented Sep 6, 2021

Aaargh! Sorry for that. I pushed a corrected update.

@olpaw
Copy link
Member

olpaw commented Sep 6, 2021

Rerunning in internal CI ...

@olpaw olpaw self-requested a review September 7, 2021 09:32
Copy link
Member

@olpaw olpaw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All gates passed. The PR is in the merge queue.

@adinn
Copy link
Collaborator Author

adinn commented Sep 7, 2021

@olpaw Excellent! Thanks.

@graalvmbot graalvmbot merged commit 86ed850 into oracle:master Sep 8, 2021
Native Image automation moved this from In progress to Done Sep 8, 2021
@adinn adinn deleted the fix-2701 branch September 9, 2022 07:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Native Image
  
Done
Development

Successfully merging this pull request may close these issues.

Inlined methods not referenceable from gdb when compiling with -g.
5 participants