Community
Participate
Working Groups
Driver: tptp.runtime-TPTP-4.4.0-200705310943 (4.4 RC2) O/S: Windows XP IA-32, Windows XP 64 EM64T When attaching to the JVMTI Call Graph profiler launched in "execution details" mode, many method and class names appear as "unknown????" (where ???? is a number) To reproduce: 1. Launch the JVMTI Call Graph profiler from the command line in "enabled" mode, setting the "execution details" option to "true": -agentlib:JPIBootLoader=JPIAgent:server=enabled;CGProf:execdetails=true 2. Attach to the Agent and start profiling. 3. Note that many class and method names appear as "unknown".
Created attachment 69885 [details] Screenshot of the "execution summary" page
Created attachment 69886 [details] Screenshot of the "call tree" page
JVMTI profiler (including Martini) does not contain a code that can generate names in format "unknown????". This may be client issue rather than the agent. Possibly it may be manifest of 187006 ([CGProf] Crash on multi-core platforms when printing <methodDef> element). Due to this defect profiler can generate broken or empty class or method names and client might have substituted the names. The bug 187006 was fixed after TPTP-4.4.0-200705310943 release. I can't reproduce the bug.
Asaf, could you please check the bug with the next driver. Probably the bug is fixed.
I built the JVMTI runtime from CVS HEAD and was able to reproduce this bug. I will test again with tomorrow's build.
Created attachment 70287 [details] Proposed patch This patch enables only aggregated cg profiling in enabled mode. In enabled mode execution detailed (ExecDetails=true) profiling is impossible because detailed information about complete call tree usually is lost.
Comment on attachment 70287 [details] Proposed patch Patch reviewed
Created attachment 70492 [details] Broken trace file Attached is trace file produced by debug version of agent. Encloding <TRACE> and </TRACE> were added manually. Verification issues missing thread starts: at 29: <threadEnd threadIdRef="8" time="1181219099.467956611"/> RULE_T02: Thread start event must precede thread end. ThreadID=8 and unknown id refs: at 1555: <agMethodEntry threadIdRef="3" methodIdRef="66352" baseTime="0.000107554" minTime="0.000027658" maxTime="0.000050005" count="3"/> RULE_M02: Method must be defined before being referenced. Unknown methodID=66352 at 1556: <agMethodEntry threadIdRef="3" methodIdRef="65551" baseTime="0.000027098" minTime="0.000007543" maxTime="0.000011733" count="3"/> RULE_M02: Method must be defined before being referenced. Unknown methodID=65551 at 1558: <agMethodEntry threadIdRef="3" methodIdRef="66441" baseTime="0.000027099" minTime="0.000008660" maxTime="0.000009499" count="3"/> RULE_M02: Method must be defined before being referenced. Unknown methodID=66441 at 1560: <agMethodEntry threadIdRef="3" methodIdRef="66367" baseTime="0.000034642" minTime="0.000011174" maxTime="0.000012293" count="3"/> RULE_M02: Method must be defined before being referenced. Unknown methodID=66367 ...
I am seeing this bug with agntctrl.win_ia32-TPTP-4.4.0-200706110100.zip and the corresponding full Eclipse+TPTP distribution.
It looks like the issue is in client side.
(In addition to comment #8) I imported the trace and I get only one unknown element, thread Unknown0 which is triggered by fact that none of the classDef have threadIdRef in them. A classDef event should always include a threadIdRef that points to the thread that loaded the class, see any PI trace. To debug this problem set a conditional breakpoint with newName.equals("Unknown0") condition in TRCThreadImpl.setName(String) line: 302. I don't see the additional problems shown in the attached screenshots, please attach the traces and specify the import mode. See the call stack dump when the breakpoint is hit bellow: Thread [Worker-1] (Suspended (breakpoint at line 302 in TRCThreadImpl)) TRCThreadImpl.setName(String) line: 302 XMLclassDefLoader(TraceXMLFragmentLoader).getThreadByIdRef(TRCProcess) line: 311 XMLclassDefLoader.createTRCType() line: 339 XMLclassDefLoader.addYourselfInContext() line: 141 XMLLoader.endElement(String, int) line: 312 SAXFragmentHandler$RegularHandler.endElement(String, String, String) line: 175 SAXParserImpl$JAXPSAXParser(AbstractSAXParser).endElement(QName, Augmentations) line: not available SAXParserImpl$JAXPSAXParser(AbstractXMLDocumentParser).emptyElement(QName, XMLAttributes, Augmentations) line: not available XMLDocumentScannerImpl(XMLDocumentFragmentScannerImpl).scanStartElement() line: not available XMLDocumentScannerImpl$ContentDispatcher(XMLDocumentFragmentScannerImpl$FragmentContentDispatcher).dispatch(boolean) line: not available XMLDocumentScannerImpl(XMLDocumentFragmentScannerImpl).scanDocument(boolean) line: not available XIncludeAwareParserConfiguration(XML11Configuration).parse(boolean) line: not available XIncludeAwareParserConfiguration(XML11Configuration).parse(XMLInputSource) line: not available SAXParserImpl$JAXPSAXParser(XMLParser).parse(XMLInputSource) line: not available SAXParserImpl$JAXPSAXParser(AbstractSAXParser).parse(InputSource) line: not available SAXParserImpl$JAXPSAXParser.parse(InputSource) line: not available SAXParserImpl.parse(InputSource, DefaultHandler) line: not available SAXFragmentHandler.parse(InputStream, DefaultHandler) line: 128 SAXFragmentHandler.scanContent(InputStream, long, long) line: 431 XMLLoader.loadEvents(InputStream, long, long) line: 760 ImportTracePage1$3.run(IProgressMonitor) line: 896 Worker.run() line: 55
In progress investigation: I have caught following cut events when outputting trace from both back and front ends: Comparing files dump_1182174751139_1.out and TRACE.TRCXML ***** dump_1182174751139_1.out <threadEnd threadIdRef="17" time="1182174750.914430304"/> <objAlloc threadIdRef="9" time="1182174751.154049585" objId="23" classIdRef="2147483649" isArray="0" size="40"/> ***** TRACE.TRCXML <threadEnd threadIdRef="17" time="1182174750.914430304"/> <classDef name="[F" sourceName="<Unknown>" classId="2147483649" time="1182174750.998982112"/> <objAlloc threadIdRef="9" time="1182174750.999010328" objId="1" classIdRef="2147483649" isArray="0" size="40"/> <classDef name="[I" sourceName="<Unknown>" classId="2147483650" time="1182174750.999091064"/> <objAlloc threadIdRef="9" time="1182174750.999100563" objId="3" classIdRef="2147483650" isArray="0" size="32"/> <classDef name="[B" sourceName="<Unknown>" classId="2147483651" time="1182174751.000047890"/> <objAlloc threadIdRef="9" time="1182174751.000068842" objId="5" classIdRef="2147483651" isArray="0" size="32"/> <objAlloc threadIdRef="9" time="1182174751.000089794" objId="7" classIdRef="2147483649" isArray="0" size="176"/> <objAlloc threadIdRef="9" time="1182174751.000135331" objId="8" classIdRef="2147483649" isArray="0" size="40"/> <objAlloc threadIdRef="9" time="1182174751.000208525" objId="9" classIdRef="2147483650" isArray="0" size="32"/> <objAlloc threadIdRef="9" time="1182174751.000251826" objId="10" classIdRef="2147483649" isArray="0" size="40"/> <objAlloc threadIdRef="9" time="1182174751.000327534" objId="11" classIdRef="2147483650" isArray="0" size="40"/> <objAlloc threadIdRef="9" time="1182174751.000487052" objId="12" classIdRef="2147483650" isArray="0" size="216"/> <objAlloc threadIdRef="9" time="1182174751.000520017" objId="13" classIdRef="2147483650" isArray="0" size="416"/> <objAlloc threadIdRef="9" time="1182174751.000546277" objId="14" classIdRef="2147483650" isArray="0" size="616"/> <objAlloc threadIdRef="9" time="1182174751.003022569" objId="15" classIdRef="2147483649" isArray="0" size="40"/> <objAlloc threadIdRef="9" time="1182174751.003084030" objId="16" classIdRef="2147483650" isArray="0" size="32"/> <objAlloc threadIdRef="9" time="1182174751.003844462" objId="17" classIdRef="2147483651" isArray="0" size="32"/> <objAlloc threadIdRef="9" time="1182174751.003873795" objId="18" classIdRef="2147483649" isArray="0" size="176"/> <objAlloc threadIdRef="9" time="1182174751.003907319" objId="19" classIdRef="2147483649" isArray="0" size="40"/> <objAlloc threadIdRef="9" time="1182174751.003942519" objId="20" classIdRef="2147483650" isArray="0" size="32"/> <objAlloc threadIdRef="9" time="1182174751.003972970" objId="21" classIdRef="2147483649" isArray="0" size="40"/> <objAlloc threadIdRef="9" time="1182174751.004002582" objId="22" classIdRef="2147483650" isArray="0" size="40"/> <gcStart time="1182174751.012670723"/> <gcFinish time="1182174751.129372147"/> <objFree time="1182174751.129416008" objIdRef="1" age="1"/> <objFree time="1182174751.129429417" objIdRef="3" age="1"/> <objFree time="1182174751.129439474" objIdRef="5" age="1"/> <objFree time="1182174751.129448414" objIdRef="7" age="1"/> <objFree time="1182174751.129457633" objIdRef="8" age="1"/> <objFree time="1182174751.129466852" objIdRef="9" age="1"/> <objFree time="1182174751.129475792" objIdRef="10" age="1"/> <objFree time="1182174751.129485011" objIdRef="11" age="1"/> <objFree time="1182174751.129494230" objIdRef="12" age="1"/> <objFree time="1182174751.129504008" objIdRef="13" age="1"/> <objFree time="1182174751.129513227" objIdRef="14" age="1"/> <objFree time="1182174751.129522725" objIdRef="15" age="1"/> <objFree time="1182174751.129531665" objIdRef="16" age="1"/> <objFree time="1182174751.129540605" objIdRef="17" age="1"/> <objFree time="1182174751.129549824" objIdRef="18" age="1"/> <objFree time="1182174751.129559601" objIdRef="19" age="1"/> <objFree time="1182174751.129568541" objIdRef="20" age="1"/> <objFree time="1182174751.129577760" objIdRef="21" age="1"/> <objFree time="1182174751.129586700" objIdRef="22" age="1"/> <objAlloc threadIdRef="9" time="1182174751.154049585" objId="23" classIdRef="2147483649" isArray="0" size="40"/> ***** TRACE.TRCXML - back-end - all event are OK dump_1182174751139_1.out - dump in XMLLoader.loadEvent(byte[] buffer, int offset, int length, boolean loadToModel) after scanner.scanContent(buffer, offset, length); Note that <threadEnd threadIdRef="17" time="1182174750.914430304"/> is not correctly paired event. ...
The dependency bug 193304 may have been fixed, but the current bug is still present in TPTP-4.4.0-200706220100 - just seen when profiling Tomcat with the complete TPTP+Eclipse package with matching agent controller on WinXP SP2.
Thanks for the input Oliver. We are looking into the defect and its high on the priority to be resolved.
(In reply to comment #13) > The dependency bug 193304 may have been fixed, but the current bug is still > present in TPTP-4.4.0-200706220100 - just seen when profiling Tomcat with the > complete TPTP+Eclipse package with matching agent controller on WinXP SP2. If it used command line options described in this bug then there is still 'agent parameter' bug. How tomcat was profiled? There were two 'unknown' reasons: 1. agent parameters (see comment #6) 2. transport issues (dependency bug 193304) 2. - was fixed and applied 1. - I do not see that patch from comment #6 was applied. Shouldn't it be applied?
(In reply to comment #15) > How tomcat was profiled? I start the external AC and then launch Tomcat with -agentlib:JPIBootLoader=JPIAgent:server=enabled;CGProf:execdetails=true Do you mean in comment #6 that this case cannot be made to work at all? That would be sad, because detailed profiling works with the old JVMPI interface (not available in the 1.6 JVM) and with the integrated AC (supposedly; I have not been able to launch Tomcat with the integrated AC).
Ruslan - Why was the patch in comment #6 missed - that has to be checked in from the meeting discussions we had. Can you ask Slava about it. Oliver, We have a few differences between PI and TI (new interface). Due to the differences in the profiling modes the features are not comparable 1:1.
(In reply to comment #16) > (In reply to comment #15) > > How tomcat was profiled? > I start the external AC and then launch Tomcat with > -agentlib:JPIBootLoader=JPIAgent:server=enabled;CGProf:execdetails=true > Do you mean in comment #6 that this case cannot be made to work at all? That > would be sad, because detailed profiling works with the old JVMPI interface > (not available in the 1.6 JVM) and with the integrated AC (supposedly; I have > not been able to launch Tomcat with the integrated AC). In ENABLED mode The following will not work without patch: -agentlib:JPIBootLoader=JPIAgent:server=enabled;CGProf:execdetails=true // with that patch execdetails will be ignored The following should work OK (aggregated info is collected): -agentlib:JPIBootLoader=JPIAgent:server=enabled;CGProf OR -agentlib:JPIBootLoader=JPIAgent:server=enabled;CGProf:execdetails=false Note, execution details will not be available in ENABLED mode by design.
(In reply to comment #16) Oliver - the decision not to support full execution flow details in ENABLED mode is by design. As opposed to JVMPI, the Method Enter/Leave notifications in JVMTI (which are the basis for constructing a call-graph and computing method execution times) are generated by instrumentation. In theory, this instrumentation is applied only when the profiler is attached (though this is temporarily disabled due to bug 179354). To correctly support full execution details in ENABLED mode, we need to reconstruct the "execution context" of each thread at the attach point. This can be done by examining the call-stack of each thread at the point of attach. The main problem here is that the call-stack information in incomplete (mainly due to method inlining). Therefore, it is not possible to construct a *correct* execution context for each thread at the point of attach. An alternative is instrument all classes and maintain an "shadow stack" for each thread even when the profiler is attached, but of-course this approach has too much overhead and therefore does not make sense. If you feel that execution flow details in ENABLED mode should be supported, even if the data is not 100% accurate, please open an enhancement request in Bugzilla for the JVMTI Profiler component.
As I understand it, there are two possible ways to implement the "enabled" use case, where the profiler can attach to the profiled process at any time: (a) incur no overhead initially, at the cost of having no accurate call stacks when the profiler is attached (as you describe), (b) follow the call graph right from the start (thus incurring overhead), thus enabling execution detail when the profiler is attached later. So it seems that (a) does not work. You categorically state that (b) "does not make sense", which I disagreee with. It seems to be the approach taken by the Eclipse Profiler (http://eclipsecolorer.sourceforge.net/index_profiler.html), which also worked by class instrumentation and which I have used successfully for several years. Unfortunately, it seems to have been a single-person project that is not under development any more. I had hoped that TPTP would eventually get the functionality of the Eclipse Profiler, but years later, that still does not seem to be the case. Given that approach (b) seems to be a way to make execution details available in "enabled" mode, I suggest that implementing it should be the fix to this bug rather than disabling the feature. Is there any other way to profile server applications remotely? Having to resort to commercial tools would be rather painful.
(In reply to comment #20) I don't consider option (b) as a "dynamic attach" use-case, as the profiler needs to be loaded into the JVM when it starts. Looking forward, we strive to enable true dynamic attach profiling, where the profiler libraries are not even loaded into the JVM until you attach (this is already supported in Java 6, but we don't utilize this capability yet). Therefore I "categorically state" that this use case does not make sense. An alternative to enable option (b) is to add an option for the profiler to start with data collection "paused". Note that this is not the same as running in ENABLED mode (which is a dymamic attach use case). I believe this use case was supported in the old profiler, and given enough resources and community interest, it can be also implemented for the JVMTI profiler. This way, we can "silently" track the call-graph when data collection is paused (as you suggested). Does it make sense?
Yes it does; thank you. Please add this naming suggestion to the enhancement request which I just posted as bug 194385.
Guru, what is the status of this defect ?
The patch was not checked in for this defect. The patch attached to the bugzilla does resolve the issue
Thanks Guru Can you then ask for approval for checking this in 4.4.0.1
Proposed patch checked into CVS HEAD at 28-July-2007 10:18 AM (GMT+3)
As of TPTP 4.6.0, TPTP is in maintenance mode and focusing on improving quality by resolving relevant enhancements/defects and increasing test coverage through test creation, automation, Build Verification Tests (BVTs), and expanded run-time execution. As part of the TPTP Bugzilla housecleaning process (see http://wiki.eclipse.org/Bugzilla_Housecleaning_Processes), this enhancement/defect is verified/closed by the Project Lead since this enhancement/defect has been resolved and unverified for more than 1 year and considered to be fixed. If this enhancement/defect is still unresolved and reproducible in the latest TPTP release (http://www.eclipse.org/tptp/home/downloads/), please re-open.
