Profiling puzzle

[mcek]

Hi All!

I was profiling my app using TPTP in Eclipse and I found one thing I
don't understand. The following method takes almost the whole time of
the execution and what concerns me is that the Base Time is 96% of the
Cumulative Time.

from help:
Base Time:
For any invocation, the base time is the time taken to execute the
invocation, excluding the time spent in other methods that were called
during the invocation.

Cumulative Time:
For any invocation, the cumulative time is the time taken to execute
all methods called from an invocation. If an invocation has no
additional method calls, then the cumulative time will be equal to the
base time.

But when I look at the method:

public evacuationSimulator2005.Point3D getPoint3D( String name
)
{
String strX = getProperty( name + "X" );
String strY = getProperty( name + "Y" );
String strZ = getProperty( name + "Z" );

return( new evacuationSimulator2005.Point3D(
Double.parseDouble( strX ),
Double.parseDouble( strY ),
Double.parseDouble( strZ ) ) );
}

I cannot see what is it doing apart from calling other methods, so what
is happening all this time?

Cheers
Maciek

 

[Oliver Wong]

Hi All!

I was profiling my app using TPTP in Eclipse and I found one thing I
don't understand. The following method takes almost the whole time of
the execution and what concerns me is that the Base Time is 96% of the
Cumulative Time.

from help:
Base Time:
For any invocation, the base time is the time taken to execute the
invocation, excluding the time spent in other methods that were called
during the invocation.

Cumulative Time:
For any invocation, the cumulative time is the time taken to execute
all methods called from an invocation. If an invocation has no
additional method calls, then the cumulative time will be equal to the
base time.

But when I look at the method:

public evacuationSimulator2005.Point3D getPoint3D( String name
)
{
String strX = getProperty( name + "X" );
String strY = getProperty( name + "Y" );
String strZ = getProperty( name + "Z" );

return( new evacuationSimulator2005.Point3D(
Double.parseDouble( strX ),
Double.parseDouble( strY ),
Double.parseDouble( strZ ) ) );
}

I cannot see what is it doing apart from calling other methods, so what
is happening all this time?

String concatenation. (e.g. name + "X").

An old profiling story I like to tell is my buddy wrote some math
processing program which took less than 1 second to run, but my buddy wanted
to optimize it anyway. So he took out his book on numerical processing and
thought up ways to improve the speed of the arithmetic expression he was
working with. I told him to profile, and when he did, he found out that
string concatenation was taking up almost all of the time within the method.
That is to say, the slowest part of his code was this:

<slowCode>
System.out.println("The answer is " + answer);
</slowCode>

Java is really fast a math, not so fast at String manipulation.

- Oliver

 

[Chris Uppal]

I was profiling my app using TPTP in Eclipse and I found one thing I
don't understand. The following method takes almost the whole time of
the execution and what concerns me is that the Base Time is 96% of the
Cumulative Time.

Profiling is an inexact art, and interpreting the results of any profiling tool
requires -- amongst other things -- a recognition of that fact.

In this case, however, I don't see any obvious explanation. But what I
/really/ don't understand is why a method which apparently uses getProperty(),
and which does all that messing around with String concatenation and number
parsing, is called often enough to show up as a hot spot at all. I would
expect such a method to be called maybe a handful of times at most, and if that
were the case then the profiler wouldn't have enough data to resolve[*] what
was happening inside the method.

([*] assuming a sampling-based profiling technique)

-- chris

 

[mcek]

It's an abuse of the Properties class. In fact it is called thousands
of times. The funny story is that it works very fast (getProperty())

 

[mcek]

I guess I got it! It seems that the profiler doesn't count the CPU
time, but the real time. Therefore the 'lost' time is just when other
tasks in the OS are executed. In this case it is most probably the
profiler itself processing the input (I checked it, it takes almost the
whole CPU while profiling). It just happens that my app is interrupted
most often inside the getPoint3D method, because it is called so many
times and therefore my app spends most of its time in it.

In the statistics the information about all of it is lost, but when I
checked times of each one execution it appeared that I have like 15
super quick ones and then one that lasts 1 second (and includes this
weird delay).

So, lots of hassle for nothing! Thanks everyone!

-- Maciek

 

[mcek]

String concatenation. (e.g. name + "X").

An old profiling story I like to tell is my buddy wrote some math
processing program which took less than 1 second to run, but my buddy wanted
to optimize it anyway. So he took out his book on numerical processing and
thought up ways to improve the speed of the arithmetic expression he was
working with. I told him to profile, and when he did, he found out that
string concatenation was taking up almost all of the time within the method.
That is to say, the slowest part of his code was this:

<slowCode>
System.out.println("The answer is " + answer);
</slowCode>

Java is really fast a math, not so fast at String manipulation.

The '+' operator is converted to the append() method, so it doesn't
count to the Base Time either.

 

[Roedy Green]

this code does quite a bit behind the scenes.

1. converts the answer to a String. This requires successive
divisions to peel off the digits.

2. allocates a StringBuilder.

3. copies two strings into the StringBuilder.

4. allocates a new String object, the contents of the StringBuilder

5. passes the string off to I/O routines to be displayed on the
console.

6. converts the string into bit glyphs to display on the simulated
console.

7. shifts the entire console window up one line by copying a screenful
of bits.

Depending on how your friend did the profiling, he may be blaming all
that on the concatenation.