This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 178384 - Invocations count is incorrect
Summary: Invocations count is incorrect
Status: RESOLVED INCOMPLETE
Alias: None
Product: profiler
Classification: Unclassified
Component: Base (show other bugs)
Version: 6.x
Hardware: Other Linux
: P1 normal (vote)
Assignee: issues@profiler
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-12-09 10:31 UTC by david_cogen
Modified: 2009-12-11 12:38 UTC (History)
0 users

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
This class's main() can be run under profiler to profile testNative and testNew. (960 bytes, text/x-java)
2009-12-09 10:31 UTC, david_cogen
Details
Screenshot with correct results (129.81 KB, image/png)
2009-12-09 13:16 UTC, Tomas Hurka
Details
This test file is a simpler version of the previous, that still demonstrates issue. (728 bytes, text/x-java)
2009-12-11 05:53 UTC, david_cogen
Details
netbeans screen shot showing incorrect profiler results. (151.93 KB, image/png)
2009-12-11 05:57 UTC, david_cogen
Details

Note You need to log in before you can comment on or make changes to this bug.
Description david_cogen 2009-12-09 10:31:28 UTC
Created attachment 92351 [details]
This class's main() can be run under profiler to profile testNative and testNew.

In netbeans profiler, debugging a small java application, the Invocations count is completely wrong. In the attached test, both pow() and ipow() are called 1,000,000 times. This is verified by the print statements at the end of the functions testNative() and testNew(). However, netbeans reports varying invocation counts of around 822,625 for ipow() and around 16611 for pow().

In addition, the Time values are also wrong. I won't provide details here because I don't want to clutter this report. However I will say that profiler shows that testNative() takes less time than testNew(), but my tests using System.nanotime() (as well as common sense) reveal that testNative() actually takes substantially more time than testNew() to run.

I marked this as P1 because the profiler is completely useless to me at present. (Assuming that I am not missing something incredibly obvious, except to me. But my coworkers also saw similar incorrect behavior.)
Comment 1 Tomas Hurka 2009-12-09 13:16:22 UTC
Created attachment 92362 [details]
Screenshot with correct results

I am sorry, but it works for me. See attached screenshot.
Comment 2 Tomas Hurka 2009-12-09 13:17:54 UTC
Closing as works-for-me.
Comment 3 david_cogen 2009-12-11 05:53:52 UTC
Created attachment 92415 [details]
This test file is a simpler version of the previous, that still demonstrates issue.
Comment 4 david_cogen 2009-12-11 05:56:05 UTC
This was closed with WORKSFORME, with a screen shot to prove it. However, it definitely doesn't work for me.

I've attached my own screen shot demonstrating that it doesn't work for me, as well as a new, even-simpler test function. Again, both Math.pow() and mypow() have been called 1000000 times, but the profiler reports times far less than that (in the Math.pow case, 1.5% of the correct number).

This must be a matter of finding the right combination of factors to reproduce the bug. I've been having suspicions of profiler problems since I first began using it, but this simple test file conclusively demonstrates the problem to me.
Comment 5 david_cogen 2009-12-11 05:57:07 UTC
Created attachment 92416 [details]
netbeans screen shot showing incorrect profiler results.
Comment 6 Tomas Hurka 2009-12-11 06:38:27 UTC
I again tested it on Linux and Mac OS X and it works fine. You need to provide _exact_ steps how to reproduce it, otherwise I am not able to find out what is going on.
Comment 7 Jiri Sedlacek 2009-12-11 07:15:22 UTC
David, please make sure the calibration data are up to date - use Profile | Advanced Commands | Run Profiler Calibration for the JDK used to run the test application.
Comment 8 Tomas Hurka 2009-12-11 07:55:42 UTC
Maybe I have the explanation, why you have lower number of invocations of the testmypow() method.
Can you please try to wait a few seconds before taking the snapshot? Your example generates a huge number of profiling data and it takes some time to process them. The lower number of Math.pow() is caused by JVM intrinsics, which completely eliminates call to Math.pow(). This only happens on JDK 1.6. If you run your example in interpreter mode (with -Xint flag), you will 1000000 invocations of Math.pow().
Comment 9 david_cogen 2009-12-11 10:33:07 UTC
Well, I am not sure what you mean by "wait a few seconds before taking the snapshot," because for me the snapshot opens automatically upon completion of running the profiler.

But I did add -Xint to the run options, and after that I consistently got 1000000 invocations for both functions.

But something strange is going on still. Without -Xint, if Math.pow() is being eliminated, why 16000 iterations - why not 0? And my function mypow() is not intrinsic; why 700000 invocations - why not 1000000 or 0?

I am more confused then ever. Something still seems wrong, but I cannot seem to define it. When you tested it, were you running with -Xint? And did you "wait a few seconds before taking the snapshot" and if so, how?

For now, maybe I should just run when profiling with -Xint if I am interested in correct counts as opposed to realistic execution times. I don't know how you want to handle the bug report now; I'll leave that up to you. If you choose to pursue it you can count on me to stay in touch and provide more info, test results, etc. I did make a list of the exact steps, starting from creating a new netbeans project for Test.java, as you suggested earlier, and will send this if you wish.

If the bug is to be closed I may take this up in the forums to see what light others can shed on this.
Comment 10 Tomas Hurka 2009-12-11 12:38:15 UTC
> Well, I am not sure what you mean by "wait a few seconds before taking the
> snapshot," because for me the snapshot opens automatically upon completion of
> running the profiler.
When profiled application finish, you will get dialog informing you that the application finished and if you want to get snapshot of gathered data. This dialog also has a checkbox with 'Do not show again'. So in the past you checked this checkbox and clicked 'Yes'. From that time on, the snapshot is automatically taken whenever profiled application finish. To reset this setting go to 'Preferences->Miscellaneous->Profiler' and click 'Reset' next to 'Click the Reset button to reset state of Do Not Show Again confirmations in all Profiler dialogs'. 

>But I did add -Xint to the run options, and after that I consistently got
>1000000 invocations for both functions.
Yes, because profiled application is running in interpreted mode and generated profiled data at slower rate, which NetBeans can process without delay so at the time the application finishes, all profiled data is processed and you will get complete snapshot.

>But something strange is going on still. Without -Xint, if Math.pow() is being
>eliminated, why 16000 iterations - why not 0? 
This is how HotSpot JVM works. 

>And my function mypow() is not intrinsic; 
Right, only call to well known functions from JDK core libraries can be eliminated. There is also method inlining, which a little bit different thing. Any sufficiently small and simple method can be inlined by HotSpot compiler.

>why 700000 invocations - why not 1000000 or 0?
This number of invocations has nothing to do with method intrinsic. This is simply the result of taking snapshot before all data is processed.

In summary there are two things: 
1) Math.pow() call gets completely eliminated by HotSpot intrinsic to speed mathematics computations in Java. This happens only on JDK 6 and this optimization can be disabled by disabling HotSpot compiler with -Xint flag.
2) Your example generates a huge number of profiling data in a very short time. When the application finishes, there is still some data to be processed. The snapshot is taken from currently processed data and therefore some of them are missing in the snapshot. Note that lower number of invocations is always for your second method and also there are no data from System.err.println() statement in your screenshot. This is something, which can be fixed in the next release.

I hope that everything is now clear. If you have more questions, please, let me know via email.