Description Michael OBrien 2010-04-28 09:48:54 EDT

>The output of the performance profile is too granular with an effective resolution of 15 ms (0.015s)
>The reported duration of 0 for a typical update query is not detailed enough when run on a fast system.
System = Corei7 2.7GHz running a local derby 10.5.3.0 database on the server version of the 64-bit SUN 1.6 JVM

>We can increase the resolution by using the new SE5 nanoTime() function with a resolution (relative timing only) of 1 ns (0.000000001s) - an increase of 1 million

>for example if we use the following property we get output such as the following
<property name="eclipselink.profiler" value="PerformanceProfiler"/>

Begin profile of{DataModifyQuery(sql="UPDATE DPAR_PACKET_SEQ SET SEQ_DPAR_P_COUNT = SEQ_DPAR_P_COUNT + ? WHERE SEQ_DPAR_P_NAME = ?")
Profile(DataModifyQuery,
	number of objects=1,
	total time=0,
	local time=0,
)
or
Begin profile of{DataModifyQuery(sql="UPDATE DPAR_PACKET_SEQ SET SEQ_DPAR_P_COUNT = SEQ_DPAR_P_COUNT + ? WHERE SEQ_DPAR_P_NAME = ?")
Profile(DataModifyQuery,
	number of objects=1,
	total time=10,
	local time=10,
	sql execute=10,
	time/object=10,
	objects/second=100,
)

>all the times are either 0 or 10 ms (nothing in between)
>According to our documentation this time in milliseconds is the time to execute the query - a duration of 0.000s
This value is not really correct, because the query actually does take some portion of a millisecond.
http://wiki.eclipse.org/Optimizing_the_EclipseLink_Application_%28ELUG%29#Measuring_EclipseLink_Performance_with_the_EclipseLink_Profiler

>Proposal: if we switch to nanosecond resolution we will get 2 benefits
- use the OS instead of Java timer - to break the 15ms interval resolution issue
- get nanosecond resolution for faster machines

The API for nonoTime() returns the same long - except that the number will be closer to 100k to 100000k instead of a 1-100.

>Scope:
The scope of this millisecond to nanosecond change may affect the other parts of JPA and Core such as the timestamp used for logging if we wish to modify this code as well.


>results (time has been changed from milliseconds to nanoseconds)

Begin profile of{DataModifyQuery(sql="UPDATE DPAR_ROUTER_SEQ SET SEQ_DPAR_R_COUNT = SEQ_DPAR_R_COUNT + ? WHERE SEQ_DPAR_R_NAME = ?")
Profile(DataModifyQuery,
	number of objects=1,
	total time=1997526,
	local time=1997526,
	profiling time=2450231,
	sql prepare=432688,
	sql execute=1515563,
	time/object=1997526,
)
}End profile