JXInsight 4.1 delivers a new innovative profile
measurement,
Service Time, which provides
a clock time that reflects the level of concurrency
for a particular resource (JVM, Database) during
a measurement interval (Trace, Interception).
Having service time statistics in a
Profile model helps determine whether a resource contention
within the JVM could have potentially impacted
the response clock time. The feature can be
used to measure the level of concurrency for
any arbitrary resource including a JVM, a database
url, an application tier, a technology component,
a Java class, or a Java target object.
Calculation
The table below presents the timeline for 3
transactions having concurrent execution. The
profile interval is 30 seconds. The sum of the
transaction times is 30 (0..30) + 5 (5..10)
+ 10 (10..20) = 45 seconds. The sum of the transaction
times is greater than the profile interval because
of concurrent execution. Note that looking at
each individual clock time and comparing it
with the profile duration time does not provide
a clue to the degree of service concurrency
experienced during each transaction's execution.
| Transaction |
Start
Time |
End
Time |
| 1 |
0 |
30 |
| 2 |
5 |
10 |
| 3 |
10 |
20 |
The service time for a transaction is calculated
by dividing each time slice by the degree of
concurrency and summing all time slices.
| Concurrent |
Start
Time |
End
Time |
Clock
Time |
| 1 |
0 |
5 |
5 |
| 2 |
5 |
10 |
5 |
| 2 |
10 |
20 |
10 |
| 1 |
20 |
30 |
10 |
For transaction #1 the service time total is
5 (0..5) + 5/2 (5..10) + 10/2 (10..20) + 10
(20..30) = 20 5/2. The timeline is broken up
into slices marked by the starting or ending
of a transaction. The service time for transaction
#2 and #3 are 5/2 (5..10) = 5/2 and 10/2 (10..20)
= 5 respectively.
| Transaction |
Clock
Time |
Service
Time |
| 1 |
30 |
22.5 |
| 2 |
5 |
2.5 |
| 3 |
10 |
5 |
With the clock time and service time side by
side it is now possible to see concurrency execution
in an aggregated profile model. A
Transaction or
Trace clock time total greater than
a service time total indicates concurrent execution.
Example
The service time statistic can also be useful
in detecting remote invocations across collocated
components. An example of such a request process
pattern can be found in the BEA WebLogic sample
application - Avitek Medical Records. The
Patient
Lookup web page in the medical records
application allows for the searching of a patient
by last name or social security number.
During a single user test, executing the
Patient
Lookup use case, the following trace profile
was recorded. The servlet trace,
searchresults.do,
is the user transaction entry point. During
the execution of the
searchresults.do trace the method
searchPatients is
invoked on the session bean
java:/comp/env/PhysicianSessionEJB.
The clock total recorded for the servlet trace
is 778,760 microseconds. The service time is
509,755 microseconds.
The difference between the clock time
and service time for the
searchresults.do trace indicates that the traced servlet
request experienced concurrent execution within
the trace service. The reason for this is the
execution of the
MedRecWebServicesEJB web service component by the trace, PhysicianSessionEJB.searchPatients,
resulting in a remote and re-entrant call.
| Trace |
Clock
Time |
Service
Time |
| searchresults.do |
778,760 |
509,755 |
| findPatientByLastName |
296,722 |
148,361 |
| create |
241,288 |
120,644 |
| Total |
1,316,770 |
778,760 |
The following traces and transactions timeline
confirms the execution overlap. The first row
(
process/thread) in the graphic displays
the
searchresults.do trace. The second
row shows the traces resulting from the re-entrant
web service call.
In the next major release of JXInsight
this feature will be further expanded to allow
fine grain specification of what constitutes
a resource as well as multiple resources and
service times per trace and transaction.
William Louth, JXInsight's Product Architect
