0

I grabbed the stack frames of all threads using jcmd pid Thread.print on the production server to troubleshoot the problem, but found that one of the methods had a clearly incorrect line number, so I grabbed a heap dump using the internal diagnostic tool, And the line number in the thread stack frame in the heap dump is correct, because it is a commercial application, so I can't provide all the source code, I want to know the reason why jcmd returns the wrong line number. I checked the relevant underlying implementations, and it seems that they all use bci to query the corresponding line number in LineNumberTable.

Stack frame returned by jcmd, sensitive information is replaced by *:

"myScheduler-7" #131 prio=5 os_prio=0 tid=0x00007ffb039df000 nid=0x91 waiting on condition [0x00007ffae9364000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000006d3406010> (a java.util.concurrent.CountDownLatch$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
    at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
    at ***.*****.***.service.impl.ScheduledServiceImpl.analyze*****(ScheduledServiceImpl.java:546)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
    at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    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)

In this stack frame, ScheduledServiceImpl has line number 546, which is clearly incorrect.

Stack frame returned by internal diagnostic tool, heap dump is generated by the following command: ManagementFactory.getPlatformMXBean(HotSpotDiagnosticMXBean.class).dumpHeap(dumpFilePath, true), sensitive information is mosaicked:

enter image description here

In this stack frame, ScheduledServiceImpl has line number 559, which is correct.

Related source code: enter image description here

JDK version: Oracle JDK 1.8.0_291

OS: Linux 4.15.0-139-generic #143-Ubuntu SMP Tue Mar 16 01:30:17 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Reference:

Poison
  • 389
  • 2
  • 14
  • Are you sure the version of the class loaded in the JVM matches your local version of the class? Are there any bytecode instrumentation agents used in the application? Try to [extract](https://github.com/apangin/class-file-extractor) the class from the loaded JVM, disassemble it and see what bytecode corresponds to the line number 546. – apangin Oct 14 '22 at 20:15
  • @apangin The version is matched, there is indeed an Agent, [Arthas](https://github.com/alibaba/arthas) was watching the method at that time, and I only checked the class file in the jar, and confirmed that the disassembled bytecode of the class file in the jar corresponds to line 559, after you reminder, now I suspect that it is related to bytecode instrumentation, how to get the enhanced class file? – Poison Oct 15 '22 at 15:53
  • [`class-file-extractor`](https://github.com/apangin/class-file-extractor) tool mentioned above or [`jvm-explorer`](https://github.com/Naton1/jvm-explorer) – apangin Oct 15 '22 at 16:18
  • @apangin Thanks for your reminder, I have reproduced the problem, confirmed that it is caused by Agent, and the line number in `jcmd` is wrong, but the line number in `jmap` is correct, I use [class-file-extractor](https://github.com/apangin/class-file-extractor) to execute the following command `java -jar extractor. jar 19026 output.jar` on further investigation, but it throws the following exception: `Exception in thread "main" java.lang.NoClassDefFoundError: com/sun/tools/attach/VirtualMachine`, and JDK version is Oracle JDK 1.8.0_321 – Poison Oct 16 '22 at 03:11
  • I add the option `-Xbootclasspath/a:$JAVA_HOME/lib/tools.jar` and throw the following exception: `Exception in thread "main" com.sun.tools.attach.AgentLoadException: Agent JAR not found or no Agent-Class attribute `, does [class-file-extractor](https://github.com/apangin/class-file-extractor) work for JDK 8? – Poison Oct 16 '22 at 14:18
  • I used [jvm-explorer](https://github.com/Naton1/jvm-explorer) to see the enhanced class, and now I need to troubleshoot why `jcmd` and `jmap` have inconsistent line numbers for the same class. – Poison Oct 16 '22 at 14:30

0 Answers0