6776 - Find Usages Performance

I noticed that Find Usages appeared to be using both cores of my
Intel Duel Core workstation Windows XP SP2, so I was interested
if there was a performance increase versus 6.0.x

I did a anecdotal performance test on a single class in my
project that has many usages: 11,441 usages. I did a Find
Usages in both 6.0.3 and Selena EAP 6776.

6.0.3: Single Threaded Find Usages Running in Foreground
Elapsed Wall Time: 5 min 50 sec or 350 sec

Selena EAP 6776: Multi-Threaded Find Usages Running in Foreground.
(I'm not sure how many threads it was using, but both cores were busy)
Elapsed Wall Time: 8 min 0 sec or 480 sec

So, Selena EAP 6776 appeared to be 37% slower than 6.0.3 which I thought
was surprising, because Selena EAP 6776 appeared to be utilizing both cores
whereas on 6.0.3 only one core was being used.

I realize that Selena EAP is a WIP and maybe debugging or something is slowing
it down, but since I did see it using both cores, it was veyr surpising that
it was 37% slower than 6.0.3 rather than closer to the theoretical 50% faster
I had exepcted.

Also, keep in mind I only did this test with a Find Usages on a single class,
although I did repeat th test once and got the same results.

22 comments
Comment actions Permalink

On 2007-03-26 14:49:25 +0400, Alex <no_reply@jetbrains.com> said:

I noticed that Find Usages appeared to be using both cores of my
Intel Duel Core workstation Windows XP SP2, so I was interested
if there was a performance increase versus 6.0.x

I did a anecdotal performance test on a single class in my
project that has many usages: 11,441 usages. I did a Find
Usages in both 6.0.3 and Selena EAP 6776.

6.0.3: Single Threaded Find Usages Running in Foreground
Elapsed Wall Time: 5 min 50 sec or 350 sec

Selena EAP 6776: Multi-Threaded Find Usages Running in Foreground.
(I'm not sure how many threads it was using, but both cores were busy)
Elapsed Wall Time: 8 min 0 sec or 480 sec

So, Selena EAP 6776 appeared to be 37% slower than 6.0.3 which I thought
was surprising, because Selena EAP 6776 appeared to be utilizing both cores
whereas on 6.0.3 only one core was being used.

I realize that Selena EAP is a WIP and maybe debugging or something is slowing
it down, but since I did see it using both cores, it was veyr surpising that
it was 37% slower than 6.0.3 rather than closer to the theoretical 50% faster
I had exepcted.

Also, keep in mind I only did this test with a Find Usages on a single class,
although I did repeat th test once and got the same results.


Well, with so many real usages most of the time is spent in UI thread
presenting results plus CG.
The real speed up shall hopefully be exibit when searching for some
more-or-less rarely used symbol, which name is used often, like add,
remove, etc.
In any case we're always interested in CPU snapshots.

0
Comment actions Permalink

Maxim Shafirov wrote:

Well, with so many real usages most of the time is spent in UI thread
presenting results plus CG.

Is there not any UI buffering you can do to maximise CPU available for
the working threads then? I think the user doesn't need progress updates
in realtime, half or 1 second latency would be fine.

Also what do you mean by CG here out of interest?

Cheers,
N.

0
Comment actions Permalink

As I understand, Selena's Find Usage (2 cores) was 37% slower, not
faster :)

Well, with so many real usages most of the time is spent in UI thread
presenting results plus CG.
The real speed up shall hopefully be exibit when searching for some
more-or-less rarely used symbol, which name is used often, like add,
remove, etc.
In any case we're always interested in CPU snapshots.

0
Comment actions Permalink

On 2007-03-26 13:29:00 +0400, Nathan Brown <nedski@yNaOhSoPo.cAoMm> said:

Maxim Shafirov wrote:

>> Well, with so many real usages most of the time is spent in UI thread
>> presenting results plus CG.

Is there not any UI buffering you can do to maximise CPU available for
the working threads then? I think the user doesn't need progress
updates in realtime, half or 1 second latency would be fine.

Also what do you mean by CG here out of interest?

Cheers,
N.


GC

0
Comment actions Permalink

On 2007-03-26 14:49:25 +0400, Alex <no_reply@jetbrains.com> said:

I noticed that Find Usages appeared to be using both cores of my
Intel Duel Core workstation Windows XP SP2, so I was interested
if there was a performance increase versus 6.0.x

I did a anecdotal performance test on a single class in my
project that has many usages: 11,441 usages. I did a Find
Usages in both 6.0.3 and Selena EAP 6776.

6.0.3: Single Threaded Find Usages Running in Foreground
Elapsed Wall Time: 5 min 50 sec or 350 sec

Selena EAP 6776: Multi-Threaded Find Usages Running in Foreground.
(I'm not sure how many threads it was using, but both cores were busy)
Elapsed Wall Time: 8 min 0 sec or 480 sec

So, Selena EAP 6776 appeared to be 37% slower than 6.0.3 which I thought
was surprising, because Selena EAP 6776 appeared to be utilizing both cores
whereas on 6.0.3 only one core was being used.

I realize that Selena EAP is a WIP and maybe debugging or something is slowing
it down, but since I did see it using both cores, it was veyr surpising that
it was 37% slower than 6.0.3 rather than closer to the theoretical 50% faster
I had exepcted.

Also, keep in mind I only did this test with a Find Usages on a single class,
although I did repeat th test once and got the same results.


One more guess. Could you please try testing with
"-Dnewlocalvcs.disabled=true" parameters to IDEA executable?

0
Comment actions Permalink

Uploaded 6776_alex_26.03.2007_16.25.50.zip
to ftp.intellij.net/.uploads

Steps followed:
0. Windows XP SP2, Intel Dual Core machine 3 GB RAM
1. Start IDEA 6776
2. Goto class that has11441 usages. Start Find Usages on it.

Elapsed Wall Time: 9 min 17 sec or 557 seconds

3. Close Find Results window and repeat 2.

Elapsed Wall Time: 8 min 10 sec or 490 seconds
It is a little faster the 2nd time. Maybe some things are cached?

4. Close Find Results. Start YourKit CPU profile.
Do Find Usages again. Stop YourKit CPU Profile.
Upload to ftp.intellij.net So, the YourKit CPU snapshot
captures the third run of the Find Usages.

0
Comment actions Permalink

I added this to my idea.properties file as

newlocalvcs.disabled=true

Assumming that is OK, it didn't have any effect with my results. It was
still taking over 8 minutes to do the Find Usages, almost the exact same
times as before.

HTH

0
Comment actions Permalink

I noticed that Find Usages appeared to be using both
cores of my
Intel Duel Core workstation Windows XP SP2


Maybe you should have bought a Dual Core workstation;
in a Duel core machine the processors probably keep shooting
at each other (which most likely hurts performance, too).

SCNR,
Jens

0
Comment actions Permalink

On 2007-03-27 11:02:06 +0400, Alex <no_reply@jetbrains.com> said:

Uploaded 6776_alex_26.03.2007_16.25.50.zip
to ftp.intellij.net/.uploads

Steps followed:
0. Windows XP SP2, Intel Dual Core machine 3 GB RAM
1. Start IDEA 6776
2. Goto class that has11441 usages. Start Find Usages on it.

Elapsed Wall Time: 9 min 17 sec or 557 seconds

3. Close Find Results window and repeat 2.

Elapsed Wall Time: 8 min 10 sec or 490 seconds
It is a little faster the 2nd time. Maybe some things are cached?

4. Close Find Results. Start YourKit CPU profile.
Do Find Usages again. Stop YourKit CPU Profile.
Upload to ftp.intellij.net So, the YourKit CPU snapshot
captures the third run of the Find Usages.


Thanks a lot for the snapshot. There are things indeed, which shall not
be there (mostly because of lots of jsp files).
BTW, isn't 1.5Gig a bit too large for Xmx? We have 256M here for IDEA
project, which isn't small either.

0
Comment actions Permalink

What are your recommendations for the Xmx setting?

I know that we've had to increase virtually all of our developer environments to use at least 3/4GB when using IDEA 6, because otherwise they end up spending half of their life in garbage collection. Enabling incremental garbage collection didn't help much either, unfortunately. Combined with the extra memory we have to allocate for the permgen space (integration with Magicdraw) it means that IDEA eats up a lot of system resources, ~1GB of RAM is allocated to the process.

Things we've noticed which eat of a lot of RAM and don't seem to give it back:

1) Working with webapps (frequent deployments, JSP editting)
2) Running unit tests repeatedly with code coverage on (one guy is having to restart his IDEA instance 3-4 times a day)
3) Working with a lot of large XML and complex XSD files

I'd take some memory snapshots, but I'm used to working with Selena now :)

0
Comment actions Permalink

A clarification of my original findings.
I wasn't clear that when I was doing Find Usages... of a class,
I was doing Find Usages of the type and also of the methods.
Specifically, when you popup Find Usages dialog on a class, you
check Usages and Usages of methods)

The Find Usages of methods is the part that is taking so long.
Out of the total 8 min 10 seconds runtime, the breakdown is something like this:
Usages of type: 25 seconds
Usages of method: 7 min 45 seconds

Also, even though there are over 11,000 matches, I don't think that is what
is causing the slowdown, because the progress bar is moving slowly for many
of the method searches while no results are being added. It appears to
caused by the search algorithm / data structure limitation.

I have the same project loaded in MyEclipse, and the "Search for references"
for the type takes 10 seconds, and the search for usages of methods takes
35 seconds. This is the same workspace using the same machine (Windows XP SP2,
Intel DualCore 3 GB mem). Note though that the Eclipse search for methods was
returning some extra matches: It reported 13,280 matches; It looks like it was
searching for inherited methods also like Object.toString(), Object.notify(), etc.
which seems really dumb; I might not be doing the search for method correctly,
so it could be user error on my part, or maybe eclipse really is that dumb....
Dumb but fast, in this case. :)

0
Comment actions Permalink

Simon,

We don't think something larger than 300M is needed for large (not huge)
code bases.

Anyway, if you feel that some operations consume but don't give back
memory we encourage you to take memory snapshots and upload them to our
ftp facility. Please keep in mind that analyzing >400m snapshot is not
practical, and >800m almost not possible technically.

0
Comment actions Permalink

The next time I get a chance I'll lower the memory settings back to default and send some snapshots.

0
Comment actions Permalink

I have repeated the test I did with the 6819 7.0 M1 build, and I saw a significant improvement. It looks like the main change was that find usages in JSP code
was significantly improved.

With build 6776, my Find Usages test took 9 min 17 sec to run
from a cold start, or 8 min 10 sec from a warm start (rerunning the find
usages after running once.)

With build 6819, my Find Usages test took 6 min 30 sec from a cold start
or 5 min 19 sec from a warm start.

IDEA 6.0.3 is taking 5 min 50 sec from a warm start. (Don't have a cold
start number.),

So, it looks like Selena EAP is 10% faster than 6.0.3 now for this test!
I feel better now that it isn't slower than the previous release now, but
still only 10% faster while using both cores of my dual core machine is
still unsatisfying...

There is still much room for improvement as MyEclipse with the same
source code can find all usages of the type and methods in 45 seconds.
(although as I noted, it is showing some other matches on superclass methods
which is incorrect.)

Besides using compiler caches to speed up the find usages,
(see IDEADEV-12010), the main inefficiency on the test class I was
finding usages on is that it had many overloaded static methods like
8 different methods called load(...), 5 different create(...), etc. and also
there were 6 different constructors. It appears that IDEA is not looking up
all the overloaded methods at once but one at a time because I would see
multiple messages like "Searching load...", "Searing load..." and these
searches were some of the longest.

0
Comment actions Permalink

If I click on one of the load() methods and invoke Find Usages and check "Include overloaded methods", the task progress only shows "Searching for load..." one time, and it seems to take about the same time to find usages of all the overloaded methods as it does to find usages of only one of the load() methods.

I think when you are finding type and methods usages of the entire class, that the Find Usages should use the same optimization for the overloaded methods.

Steps:

Invoke Find Usages on one of the eight load() methods in the class.
"include overloaded methods" is ON.
18 seconds, 791 usages found

Invoke Find Usages on the most used load() method in the class
"include overloaded methods" is OFF.
14 seconds, 571 usages.

Invoke Find Usages on the most used load() method in the class
"include overloaded methods" is OFF.
12 seconds, 6 usages

You can see that searching for each one separately really wastes a bunch
of time. Instead of taking only 18 seconds for all 8 load(...) methods, it is
taking approx. 8 * 12sec = 96 sec or 1 min 36 sec.

If all overloaded methods are searched for in one shot during the find usages
of all methods of a class, I think it would cut 2 minutes or more off the 6 min
30 sec it is currently taking in my Find Usages test.

That one change plus some cache optimiziation could really speed the
Find Usages up.

HTH
-Alex

0
Comment actions Permalink

Mike Aizatsky> We don't think something larger than 300M is needed for large (not huge)
Mike Aizatsky> code bases.

I don't know how you are getting IDEA to work with only 300M
memory. If I go with the default 256MB memory, IDEA crashes with
OutOfMemory when I run the Find Usages on this class with 11000
results. It crashes after only 4000 results are displayed.

With memory set to 1500M, this Find Usages command will use up
to 811M of memory. After closing all editor windows and pressing
the GC button twice, it shows 400M out of 811M. After closing
the Find Usages results window, and hitting GC again, it says
136M of 779M. So that Find Results window is taking a big chunk
of memory.

I was getting by with using setting max memory to 768M, but the
Analyze->Inspect Code are memory hogs, so I had to increase it
to 1500M. Even then, I can only run a subset of inspections on
the codebase for the server project I am working on. This
project has 1 million loc Java, 80k loc JSP, 20k loc
javascript, plus some misc xml css txt files.

0
Comment actions Permalink

When searching for all overloads we exploit the fact that all of them have the same name, so it is possible to query word index once with this name. For the situation you describe this would not be possible.

0
Comment actions Permalink

Eugene V> When searching for all overloads we exploit the fact
Eugene V> that all of them have the same name, so it is
Eugene V> possible to query word index once with this name. For
Eugene V> the situation you describe this would not be possible.

That's exactly what I want the Find usages for all methods of
the class to exploit also for all the overloaded methods in the
class. Maybe you misunderstood what I was saying.

To be more specific, if I invoke "Find Usages" on a class X,
and check the "Usages of methods", then IDEA should first
groups the methods which have the same name, and IDEA should run
the find method usages for all the overloaded methods with that
name exactly how Find Usages on a single method works when
you check "Include overloaded methods". For methods that aren't
overlaoded, IDEA would just do whatever it is currently doing.

At least in the code I am working with, it is pretty common to
have overloaded methods in a class, and if they are public static
with lots of usages, I find that those are the methods taking the
most time to find the usages of. So, that's why I think this
optimization is worthwhile. As I mentioned before, it would shave
minutes off of the example Find Usages I was doing for performance
test.

0
Comment actions Permalink

OK, that certainly makes sense.

0
Comment actions Permalink

Alex,

11,000 find usages results will indeed hog that much memory. IDEA needs
to keep every source file parsed if there was a hit in it. The same
applies for global inspections. If I need to run a global analysis for
IDEA I'm usually restarting it with much larger Xmx and reverting it
back after analysis.

The proposed Xmx applies to "normal", editor-centric activity. In fact I
have Xmx300M 90% of the time while working on IDEA.

0
Comment actions Permalink

I don't know how you are getting IDEA to work with
only 300M memory.


Hmm...


So, my project has around 50k files totalling 403MB. I'm using IDEA with the default memory settings, and all is right with the world. Global inspections used to be a problem, but I've offloaded global inspections to TeamCity (installed in another machine), so even those aren't a problem anymore.

0
Comment actions Permalink

Finally had some time to file a Jira on this issue.

It only helps speedup Find Usages on a class's method when the class has a number of overloaded methods, but in those cases, it will really save alot of time. In my example, at least 2 minutes of wall time.

Find Usages - Usages of Methods of a Class - Should do one search for each group of overloaded methods in a class
http://www.jetbrains.net/jira/browse/IDEA-12735

0

Please sign in to leave a comment.