Bugzilla – Full Text Bug Listing
| Summary: | Method Invocation Details: cannot understand "invoked by" and "invokes" columns | ||
|---|---|---|---|
| Product: | z_Archived | Reporter: | changzhouwang <changzhouwang> |
| Component: | TPTP | Assignee: | Ritwik Lodhiya <ritwikl> |
| Status: | CLOSED FIXED | QA Contact: | |
| Severity: | critical | ||
| Priority: | P1 | CC: | analexee, chris.l.elford, ewchan, jkubasta, mikhail.sennikovskiy, paulslau |
| Version: | unspecified | Keywords: | plan |
| Target Milestone: | --- | Flags: | paulslau:
review-
analexee: review+ ewchan: review+ |
| Hardware: | PC | ||
| OS: | Windows XP | ||
| Whiteboard: | closed460 | ||
| Bug Depends on: | |||
| Bug Blocks: | 208746 | ||
| Attachments: | |||
|
Description
changzhouwang
I thought for each selected method, the total number of calls equal to the sum of "Invoked by" numbers. But this is definitely not true. Created attachment 81668 [details]
trace file from running hello world type app with sun vm (win32)
sample showing problem
I believe this is something significantly more serious than a documentation flaw. I think it is a serious problem in the view or import into the data model. i've attached a sample trace file. If you take the most frequently called method and look at the invocation stats, you will see that the invoked by column in the middle section is off by several orders of magnitude from the total call count. Looking thru the xml file indicates that the total call count is correct. I'm downloading TPTP 4.3 and will load the trace there to see if this is a 4.4 regression. Thx, Chris Note that I have verified that this has the same behavior importing in to TPTP the 4.3.1 release. Thus, it does not appear to be a recent regression. Thx, Chris Joanna, would you please take a look into this problem? I see [part of] what is causing part of the problem....
It looks like the method invocation details view is not designed around aggregated records but instead assumes that each stack corresponds to a single instance.
In the the trace that I uploaded, charAt() is invoked 1226 times. There are 43 distinct stacks/callchains documented in the aggregated file (grep 65552 trace-sun.trcxml | grep Entry | wc). If you sum up the invokedby column, you see that it adds to 43. So it looks like each distinct stack/callchain increments the invoked by by 1 instead of by the "count" associated with each aggregated record. I'm guessing that the invokes data at the bottom of the view is similar.
Looking thru the view code, I believe the view part of the issue is in MethodDetailsStatistic.java (dev.eclipse.org\trace\org.eclipse.hyades.trace.views\src\org\eclipse\hyades\trace\views\internal)
-------------
Iterator iterator = method.getInvocations().iterator();
while(iterator.hasNext())
{
TRCMethodInvocation inv = (TRCMethodInvocation) iterator.next();
if(inv.getInvokedBy() == null)
continue;
TRCMethod m = inv.getInvokedBy().getMethod();
Object value = tmpMap.get(m);
if(value != null)
{
int i = ((Integer)value).intValue()+1;
tmpMap.put(m, new Integer(i));
}
else
tmpMap.put(m, new Integer(1));
}
------------------
If I read this correctly (and I'm not sure I do... :-), if a new invoker is found, it installs 1 in the map, if a duplicate is found, it increments it by one. This should work fine in non-aggregating mode. In aggregating mode, I believe that the value should be inserted or added by the COUNT of the aggregation record instead of by 1. I'm not certain this data is in the model but I assume it is in there somewhere... I was assuming that it would be a field in AggregatedInvocation but I don't see it there... I'm somewhat worried that the count might not exist in the model at all... Though if that is true, one wonders how the total adds up correctly to 1226 at the top of the view that shows total invocations of the method.
I started looking at this from the data loader perspective to see if the data is loaded into the model but haven't gotten too far there yet.
-------------------
This is turning out to be a blocker for an Asia summit presentation that we're trying to wrap up to demonstrate how to use TPTP to optimize Harmony. We need to run some of or stuff without filters because we're trying to find Harmony classlibs that need optimization (requiring us to use aggregated mode).
I don't suppose we'd be so lucky that the TRCMethod.getCalls() has the count for the stack instance versus the total count of times that that method was called and the following would magically work?
while(iterator.hasNext())
{
TRCMethodInvocation inv = (TRCMethodInvocation) iterator.next();
if(inv.getInvokedBy() == null)
continue;
TRCMethod m = inv.getInvokedBy().getMethod();
Object value = tmpMap.get(m);
if(value != null)
{
int i = ((Integer)value).intValue()+m.getCalls();
tmpMap.put(m, new Integer(i));
}
else
tmpMap.put(m, new Integer(m.getCalls()));
}
If I could build, I might try it just to see what would happen...
----
Note that I have verified that the callee section seems to have the same basic code so I really do suspect it has the same problem...
Guru gave me a little tuturial on building the necessary plugins. Unfortunately, this mod doesn't help for several reasons. One being that it doesn't actually show up in the view after the change... I tweaked it a bit to dump some information to System.out. It appears at this point m.getCount() only has the count from the last call stack. So if 2 different callstacks can result in a() calling b(), I get 2*the_count_of_second(a()->b()) instead of the_count_of_first(a()->b())+the_count_of_second(a()->b()). I wonder if the information that is needed is in the model at all. Please raise priority!
Note that the codepath below doesn't do anything useful. I did find the "right" place to tweak the code...
It is in MethodStatisticLabelProvider
TRCMethodInvocation mi = ((TRCMethodInvocation)i.next()).getInvokedBy();
if(mi != null && mi.getMethod().equals(m))
nb++;
I tweaked the body to be:
{
if(mi instanceof TRCAggregatedMethodInvocation) {
nb+=((TRCAggregatedMethodInvocation)mi).getCount();
} else {
nb++;
}
}
Unfortunately, this just makes the column equivalent to the "calls" column. i suspect the issue to be both here and in the loader. I went tweaking the loader of aggregatedmethodenter records but didn't find anything that actually causes anything to change.
The views seem to have some issues. I'm not sure if its just because we're using the same code for TI and PI or if its something more fundamental. Joanna, Is supporting the view code one of the things that you will have a resource starting for in a few months?
Yes, resource will be on board in January *** Bug 208746 has been marked as a duplicate of this bug. *** Created attachment 82737 [details]
patch moved from 208746
Created attachment 87456 [details]
4 Pics in jpg
I checked this bug and tried various ways to see if the program produces a mistake. I could not reproduce the error that was reported with the TestProfiler program.
I have screenshots for methods m1, m2, m3, m4 in jpg format. I'm pretty sure that the resuts given by the "invoked by" and "invokes" columns are correct.
Mr. Changzhou Wang, can you please try to reproduce the error and see if you still get the same results?
I used Windows XP Opersting System with TPTP-4.5.0-200712211700
PS - sorry I forgot to mention this in my previous post, but I used JDK 1.5 to test the program. Created attachment 87463 [details]
showing failure with 4.5I4
Note that when I tried the version with Alex's patch the problem was resolved and it does not look like the patch has been integrated as of TPTP-4.5.0-200712211700.
Can you load the trace that is the first attachment, load it and look at method invocation details for java.lang.String.charAt(int) char.
Screenshot attached.
Created attachment 87464 [details]
Europa plus Alex patch showing same situation
This one shows the same trace file loaded with Alex' patch (this was a Europa base)
note that the values don't add up in the "good" screenshot because there is a scrollbar to show the remaining invokers. When I add them up they do indeed add to the number of times that charAt was invoked. -- thx, Chris Created attachment 87550 [details]
Unable to properly open the profiling file
Hi Chris,
I'm having difficulty reproducing the error still. Can you please tell me how you got the screen you have shown in the screenshots? When I tried to view the trace file from the 1st attachment, I did not get anything on my screen (I have attached my screenshot for reference).
I took the following steps, please indicate if I should've done something differently:
1) File -> Import... -> Profiling and Logging -> Profiling File
2) Browse trace-sun.trcxml
3) Select Full for Range, and Show Full Data
4) Select No Filters
when you try to open full details I think it defaults to UML trace. import->profiling file-> full range, no filters, show full data openwith->execution statistics browse to java.lang.String.Charat (open package java.lang, open class string, click CharAt) choose method invocationdetails tab. Created attachment 87584 [details] Some more Screenshots Hello, I tried applying Alex's patch and it seems to solve the problem. The charAt method shows the right number in the "invoked by" column. I also used the patch to try and see if it addresses the problem of the initial program TestProfiler and it turns out that it works fine as well. I have the screenshots for the 2 tests in the zipped attachment. Alex's patch works but there is one situation which needs to be addressed. If you notice the screenshot charAt(int).jpg, its clear that the function that sorts the number of "invoked by" calls is not correct. I believe that is the last thing that has to be fixed before bug 197176 can be resolved. Yes, I noticed some anomolies with sorting on that column after the patch as well. I was able to make forward progress with the immediate analysis I was trying to do even with that flaw. It would be great for the sort to work correctly. Should be a simple tweak. I suspect its sorting based on the original incorrect number instead of the correct number that the patch calculates. I'd actually run into this problem independent of the TestProfiler test in this bug and found this one searching bugzilla before filing a new bug. Its good to see independent confirmation that it was indeed the same bug... :-) Thx, Chris Created attachment 87807 [details]
Proposed Patch
Infact, that's exactly what the problem was.
I have attached a patch which primarily addresses the problem of bad sorting. However, Alex's patch is included as a part of this patch just to keep it simple and fix the defect internally, and on display.
Cutoff for i5 defect check in is Friday. Please review the latest patch before then. Thanks. I reviewed the patch and everything looks fine (my only comment would be updating the copyright date on the source file). However, I am not familiar with the code so I recommend Eugene review the patch as well. I think that commented snippets of code worth to remove. We always can use CVS history to restore. -1. I found a problem with the sorting function. Profile the original testprofiler application, create a new filter set and add java.lang* * INCLUDE to the default filters. in execution statistic tab of view, double click on main() method, invocation detail view is opened, sort in 'Selected method invokes' 'Invokes' column, the value is not sorting correctly. I will attach screen shots. Created attachment 88452 [details]
screen shot shows problem in ascd sort
Created attachment 88453 [details]
screen shot shows problem in desc sort
Created attachment 88475 [details]
Proposed Patch v2.0
I believe this patch addresses the problems.
1) Now both "invokes" and "invoked by" columns show correct numbers with proper sorting
2) All commented snippets of codes have been removed
3) Copyright information is updated
If this patch is approved, then this patch will have patched the patch which was meant to have patched a patch that was not meant for this bug :).
The latest path loods good. Good Work Ritwik! The affected plugin was moved to the trace project and so the patch cannot be applied as is. Ritwik can you apply the same changes to org.eclipse.hyades.trace.views? Created attachment 88631 [details]
Patch for different plugin
Please review this one, because I have a small concern
In an empty workspace, I checked out the org.eclipse.hyades.trace.views plugin from trace project and made the necessary modifications on MethodDetailsStatistics.java file. I made the patch and posted it.
When I checked the patch, it looks exactly the same as the previous patch I had posted. Should I patch differently to accomodate for the change in the plugin's project?
Patch applied to Head. Thx Ritwik. Created attachment 92241 [details]
Example trcxml that fails with 4.5 I5
Should this be working in 4.5 I5? The attached is a trcxml is from running hello world under 4.5 I5 with a certain set of filters.
Note:
java.io.ByteArrayOutputStream.write(int) void is called 131114 times. Its "invokedby section" states that it was invoked by java.util.jar.InitManifest.nextChunk(java.io.InputStream,java...) all 131114 times. If I go look at java.util.jar.InitManifest.nextChunk and look at its "invokes section", it says that it only invoked java.io.ByteArrayOutputStream.write(int) 1229 times (once for each time it was called).
Similarly, in the display for java.io.ByteArrayOutputStream.write(int), it says that it invokes java.io.ByteArrayOutputStream.expand(int) 131114 times but java.io.ByteArrayOutputStream claims to only have been invoked a total of 2 times.
Thx,
Chris
On M5 problem reproduced with Chris's trace Created attachment 92292 [details]
fix for incorrect representation of trace attached by Chris
I have confirmed that this patch works for me. The numbers for invoked view seem to be consistent now with the numbers for the invokes(). This will make my demo at EclipseCon much more easily explained... :-) Thx! Chris change target to current itaration patch for Chris's bug committed to the head. Record can be closed 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. |