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

Async Profiler and Java Flight Recorder are missing some methods at the bottom of the stack. #845

Closed
qsLI opened this issue Nov 24, 2023 · 16 comments
Labels

Comments

@qsLI
Copy link

qsLI commented Nov 24, 2023

From a code perspective, the correct call order should be: Thread.run -> FastThreadLocalRunnable.run -> ThreadPoolExecutor$Worker.run -> ThreadPoolExecutor.runWorker

✅using jstack:
image

❌using async profiler:

image

❌using jfr ExecutionSample event:
image

This doesn't seem to be a bug with async profiler, any thoughts?

@franz1981
Copy link

Did you added DebugNonSafepoints as suggested in the readme?

@qsLI
Copy link
Author

qsLI commented Nov 27, 2023

Did you added DebugNonSafepoints as suggested in the readme?

I'll give it a try.

@heifrank
Copy link

Did you added DebugNonSafepoints as suggested in the readme?

@franz1981 If it's really DebugNonSafepoints problem, then jstack will also show missing stack frame, however jstack shows correctly.

@franz1981
Copy link

Depends. If there is a safepoint poll within an inlined method, jstack can still observe (and blame it), while, without the option I've specified, both jfr and async profiler won't be able to do the same (loop striping can still add polls to counted loops).
Regarding your method: are you using CPU profiling? If yes, jstack has captured a WAITING thread which is not something a CPU profiler would show up, because...it doesn't consume CPU (unless in the precess of contending on some process futex to do it).

@apangin
Copy link
Collaborator

apangin commented Dec 1, 2023

If it's not an async-profiler bug, will it be better to submit an OpenJDK issue instead?
If you could provide a reproducible example, I'd be happy to analyze that.
Btw, does the issue happen with other JDK versions or with a different CPU architecture?

@qsLI
Copy link
Author

qsLI commented Dec 4, 2023

If it's not an async-profiler bug, will it be better to submit an OpenJDK issue instead? If you could provide a reproducible example, I'd be happy to analyze that. Btw, does the issue happen with other JDK versions or with a different CPU architecture?

The issue cannot be stably reproduced at present, it only occurs occasionally. This case was found on an internal version ported based on OpenJDK 11.

@apangin
Copy link
Collaborator

apangin commented Dec 4, 2023

How does --cstack vm work? Does it show missing frame?

@qsLI
Copy link
Author

qsLI commented Dec 5, 2023

How does --cstack vm work? Does it show missing frame?

jdk.ActiveSetting cstack value is fp when using --cstack vm,seems a bug?

https://github.com/async-profiler/async-profiler/blob/29b78f4670b58272ce5968774baed06381f8d0aa/src/flightRecorder.cpp#L71C33-L71C33

using command:
./asprof -e cpu --cstack vm -d 60 -f p.jfr

jfr info:
jdk.ActiveSetting { startTime = 08:40:06.344 id = 107 name = "cstack" value = "fp" eventThread = "Attach Listener" (javaThreadId = 2700) }

@apangin
Copy link
Collaborator

apangin commented Dec 5, 2023

jdk.ActiveSetting cstack value is fp when using --cstack vm,seems a bug?

Yes, thank you for pointing out. I pushed the fix.

@qsLI
Copy link
Author

qsLI commented Dec 8, 2023

How does --cstack vm work? Does it show missing frame?

still not working with async-profiler-2.10-linux-x64

cmd ./asprof -e cpu --cstack vm -d 60 -f p.html

image

@apangin
Copy link
Collaborator

apangin commented Dec 8, 2023

This does not look like a vm stack trace.
cstack=vm option appeared in async-profiler 3.0-ea.

@qsLI
Copy link
Author

qsLI commented Dec 17, 2023

This does not look like a vm stack trace. cstack=vm option appeared in async-profiler 3.0-ea.

  • cstack=vm mode is correct
image
  • the same host with cstack=fp
image

@apangin
Copy link
Collaborator

apangin commented Dec 20, 2023

Thank you for the update. Good to know async-profiler's own stack walker works correctly. It will eventually replace JVM's AsyncGetCallTrace and become the default.

@qsLI
Copy link
Author

qsLI commented Dec 20, 2023

Thank you for the update. Good to know async-profiler's own stack walker works correctly. It will eventually replace JVM's AsyncGetCallTrace and become the default.

cstack=vm reads the symbol information (gHotSpotVMStructs) exported by the JVM, then finds the offset related to PCDesc, reads the corresponding data, and obtains the call stack information. Since the vm mode is correct, it can be inferred that the information of PCDesc is correct or enough, which has nothing to do with DebugNonSafePoint?

@apangin
Copy link
Collaborator

apangin commented Dec 20, 2023

Yes, DebugNonSafepoints option may affect accuracy of the topmost virtual frames, but not a frame at the bottom of the stack.

@apangin
Copy link
Collaborator

apangin commented Jan 3, 2024

Let me close the issue, since there is nothing to do on async-profiler side.

@apangin apangin closed this as completed Jan 3, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants