Skip to main content

Notice: this Wiki will be going read only early in 2024 and edits will no longer be possible. Please see: https://gitlab.eclipse.org/eclipsefdn/helpdesk/-/wikis/Wiki-shutdown-plan for the plan.

Jump to: navigation, search

Difference between revisions of "EclipseLink/UserGuide/JPA/Advanced JPA Development/Performance/Performance Monitoring and Profiling/Performance Monitoring"

(New page: {{EclipseLink_UserGuide |info=y |toc=n |eclipselink=y |eclipselinktype=JPA |api=y |apis= * [http://www.eclipse.org/eclipselink/api/latest/org/eclipse/persistence/tools/profiler/package-sum...)
 
m
 
(13 intermediate revisions by 2 users not shown)
Line 1: Line 1:
 +
----
 +
 +
 +
'''[[Image:Elug_draft_icon.png|Warning]] This page is now obsolete. '''
 +
 +
For current information, please see "Performance Monitoring" in the ''EclipseLink Concepts Guide'':
 +
http://www.eclipse.org/eclipselink/documentation/latest/concepts/monitoring003.htm
 +
 +
 +
----
 +
 
{{EclipseLink_UserGuide
 
{{EclipseLink_UserGuide
 
|info=y
 
|info=y
Line 6: Line 17:
 
|api=y
 
|api=y
 
|apis=
 
|apis=
−
* [http://www.eclipse.org/eclipselink/api/latest/org/eclipse/persistence/tools/profiler/package-summary.html profiler]
+
* [http://www.eclipse.org/eclipselink/api/latest/org/eclipse/persistence/tools/profiler/PerformanceMonitor.html PerformanceMonitor]
−
* [http://www.eclipse.org/eclipselink/api/latest/org/eclipse/persistence/tools/profiler/PerformanceProfiler.html PerformanceProfiler]
+
 
}}
 
}}
−
=Performance Profiling=
+
=Performance Monitoring=
  
 +
Use the Performance Monitor to provide detailed profiling and monitoring information in a multithreaded server environment.
  
−
==Measuring EclipseLink Performance with the EclipseLink Profiler==
+
Enable the monitor in <tt>persistence.xml</tt> as follows:
−
The most important challenge to performance tuning is knowing what to optimize. To improve the performance of your application, identify the areas of your application that do not operate at peak efficiency. The EclipseLink performance profiler helps you identify performance problems by logging performance statistics for every executed query in a given session.
+
  
−
{{EclipseLink_Note
+
<source lang="xml">
−
|note=You should also consider using general performance profilers such as JDeveloper or JProbe to analyze performance problems. These tools can provide more detail that may be required to properly diagnose a problem.
+
<property name="eclipselink.profiler" value="PerformanceMonitor"/>
−
}}
+
</source>
  
 +
The performance monitor can also be enabled through code using a SessionCustomizer.
  
−
The EclipseLink performance profiler logs the following information to the EclipseLink log file (for general information about EclipseLink logging, see [[Introduction%20to%20EclipseLink%20Sessions%20(ELUG)#Logging|Logging]]):
+
The performance monitor will output a dump of cumulative statistics every minute to the EclipseLink log.
−
* query class;
+
−
* domain class;
+
−
* total time, total execution time of the query, including any nested queries (in milliseconds);
+
−
* local time, execution time of the query, excluding any nested queries (in milliseconds);
+
−
* number of objects, the total number of objects affected;
+
−
* number of objects handled per second;
+
−
* logging, the amount of time spent printing logging messages (in milliseconds);
+
−
* SQL prepare, the amount of time spent preparing the SQL script (in milliseconds);
+
−
* SQL execute, the amount of time spent executing the SQL script (in milliseconds);
+
−
* row fetch, the amount of time spent fetching rows from the database (in milliseconds);
+
−
* cache, the amount of time spent searching or updating the object cache (in milliseconds);
+
−
* object build, the amount of time spent building the domain object (in milliseconds);
+
−
* query prepare, the amount of time spent to prepare the query prior to execution (in milliseconds);
+
−
* SQL generation, the amount of time spent to generate the SQL script before it is sent to the database (in milliseconds).
+
  
 +
The statics contains three sets of information:
 +
* <b>Info</b>: Statistics that are constant informational data, such as the session name, or time of login.
 +
* <b>Counter</b>: Statistics that are cumulative counters of total operations, such as cache hits, or query executions.
 +
* <b>Timer</b>: Statistics that are cumulative measurements of total time (in nano seconds) for a specific type of operation, reading, writing, database operations.
  
−
{{EclipseLink_Note
+
Statistics are generally grouped in total and also by query type, query class, and query name.  Counters and timers are generally recorded for the same operations, so the time per operation could also be calculated.
−
|note=Use the EclipseLink profiler to profile single-threaded finite use cases to determine the bottle neck.
+
−
 
+
−
Do not use the EclipseLink profiler to enable monitoring of a long-running multi-threaded server.
+
−
}}
+
−
 
+
−
 
+
−
This section includes information on the following topics:
+
−
* [[#How to Configure the EclipseLink Performance Profiler|How to Configure the EclipseLink Performance Profiler]]
+
−
* [[#How to Access the EclipseLink Profiler Results|How to Access the EclipseLink Profiler Results]]
+
−
 
+
−
 
+
−
===How to Configure the EclipseLink Performance Profiler===
+
−
 
+
−
When using JPA the profiler can be set in your <tt>persistence.xml</tt> through the persistence property <tt>"eclipselink.profiler"</tt> to <tt>"PerformanceProfiler"</tt>.  See the [http://www.eclipse.org/eclipselink/api/latest/org/eclipse/persistence/config/ProfilerType.html<tt>ProfilerType</tt>] in the <tt>config</tt> package for other profiling options.
+
−
 
+
−
The EclipseLink performance profiler is an instance of [http://www.eclipse.org/eclipselink/api/latest/org/eclipse/persistence/tools/profiler/PerformanceProfiler.html <tt>org.eclipse.persistence.tools.profiler.PerformanceProfiler</tt>] class. It provides the following public API:
+
−
* <tt>logProfile</tt> – enables the profiler;
+
−
* <tt>dontLogProfile</tt> – disables the profiler;
+
−
* <tt>logProfileSummary</tt> – organizes the profiler log into a summary of all the individual operation profiles including operation statistics like the shortest time of all the operations that were profiled, the total time of all the operations, the number of objects returned by profiled queries, and the total time that was spent in each kind of operation that was profiled;
+
−
* <tt>logProfileSummaryByQuery</tt> – organizes the profiler log into a summary of all the individual operation profiles by query;
+
−
* <tt>logProfileSummaryByClass</tt> – organizes the profiler log into a summary of all the individual operation profiles by class.
+
−
 
+
−
===How to Access the EclipseLink Profiler Results===
+
−
The simplest way to view EclipseLink profiler results is to read the EclipseLink log files with a text editor. For general information about EclipseLink logging, such as logging file location, see [[Introduction%20to%20EclipseLink%20Sessions%20(ELUG)#Logging|Logging]].
+
−
 
+
−
This example shows an example of the EclipseLink profiler output.
+
−
 
+
−
<span id="Example 11-1"></span>
+
−
''''' Performance Profiler Output'''''
+
−
<source lang="text">
+
−
Begin Profile of{
+
−
ReadAllQuery(com.demos.employee.domain.Employee)
+
−
Profile(ReadAllQuery,# of obj=12, time=1399,sql execute=217,
+
−
prepare=495, row fetch=390, time/obj=116,obj/sec=8)
+
−
} End Profile
+
−
</source>
+
−
 
+
−
The second line of the profile contains the following information about a query:
+
−
 
+
−
{{EclipseLink_Vote
+
−
|bug=310820
+
−
|description=to add nanosecond (10^6 ms) resolution
+
−
}}
+
  
−
* <tt>ReadAllQuery(com.demos.employee.domain.Employee)</tt><nowiki>: specific query profiled, and its arguments.</nowiki>
+
The time in between statistic dumps can be configured through the <code>PerformanceMonitor</code> API using the <code>setDumpTime(long)</code> API. If dumping the results is not desired, then dumpTime can be set to be very large such as Long.MAX_VALUE.  The statistic can also be accessed programatically using the <code>getOperationTime(String)</code> API.
−
* <tt>Profile(ReadAllQuery</tt><nowiki>: start of the profile and the type of query.</nowiki>
+
−
* <tt><nowiki># of obj=12</nowiki></tt><nowiki>: number of objects involved in the query.</nowiki>
+
−
* <tt>time=1399</tt><nowiki>: total execution time of the query (in milliseconds).</nowiki>  
+
−
* <tt>sql execute=217</tt><nowiki>: total time spent executing the SQL statement.</nowiki>
+
−
* <tt>prepare=495</tt><nowiki>: total time spent preparing the SQL statement.</nowiki>
+
−
* <tt>row fetch=390</tt><nowiki>: total time spent fetching rows from the database.</nowiki>
+
−
* <tt>time/obj=116</tt><nowiki>: number of milliseconds spent on each object.</nowiki>
+
−
* <tt>obj/sec=8</tt><nowiki>: number of objects handled per second.</nowiki>
+
  
 +
The performance monitor can also be configured with a profile weight.
  
 +
The profile weights are defined on <code>SessionProfiler</code> and include:
 +
* <b>NONE</b> - No statistics are recorded.
 +
* <b>NORMAL</b> - Informational statistics are recorded.
 +
* <b>HEAVY</b> - Informational, counter and timer statistics are recorded.
 +
* <b>ALL</b> - All statistics are recorded (this is the default).
  
 +
===Example Output===
 +
<pre>
 +
Performance Monitor:1279113281664
 +
Operation Value (ns)
 +
Counter:CacheHits 1,375,664
 +
Counter:CacheMisses 327
 +
Counter:ClientSessionCreates 1,204,817
 +
Counter:ConnectCalls 2
 +
Counter:DataModifyQuery 48
 +
Counter:DataModifyQuery:inventory 21
 +
Counter:DataModifyQuery:order 27
 +
Counter:DeleteObjectQuery 67,792
 +
Counter:DeleteObjectQuery:Customer 1
 +
...
 +
Counter:ReadAllQuery 1,041,767.
 +
Counter:ReadAllQuery:Item.findByCategory 733,827
 +
Counter:ReadAllQuery:Item.findByCategory:CacheHits 733,779
 +
Counter:ReadAllQuery:Item.findByCategory:CacheMisses 50
 +
...
 +
Counter:ReadObjectQuery 1,058,273
 +
Counter:ReadObjectQuery:Item:item 130,063
 +
Counter:ReadObjectQuery:Item:item:CacheHits 130,063
 +
Counter:ReadObjectQuery:Item:item:CacheMisses 1
 +
Counter:UnitOfWorkCommits 72,568
 +
Counter:UnitOfWorkCreates 471,491
 +
Counter:UnitOfWorkRollbacks 1
 +
Counter:UpdateObjectQuery 71,498
 +
Counter:UpdateObjectQuery:Customer 62,531
 +
...
 +
Info:LoginTime Wed Jul 14 08:55:41 EDT 2010
 +
Info:SessionName file:/scratch/user_domains/servers/mt-1/app.jar
 +
Timer:Caching 6,411,372,000
 +
Timer:ConnectionManagement 17,225,641,000
 +
Timer:DeleteObjectQuery 41,351,430,000
 +
Timer:DeleteObjectQuery:Customer 4,441,000
 +
Timer:DeleteObjectQuery:Customer:QueryPreparation 86,000
 +
Timer:DeleteObjectQuery:Customer:SqlGeneration 28,000
 +
Timer:DeleteObjectQuery:Customer:SqlPrepare 72,000
 +
Timer:DeleteObjectQuery:Customer:StatementExecute 2,265,000
 +
...
 +
Timer:InsertObjectQuery 69,111,086,000
 +
Timer:Logging 4,236,000
 +
Timer:Merge 1,144,400,000
 +
Timer:ObjectBuilding 31,914,397,000
 +
Timer:QueryPreparation 984,396,000
 +
Timer:ReadAllQuery 260,943,930,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory 14,790,333,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory:ObjectBuilding 250,959,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory:QueryPreparation 1,880,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory:RowFetch 113,552,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory:SqlGeneration 522,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory:SqlPrepare 2,055,000
 +
Timer:ReadAllQuery:Item:Item.findByCategory:StatementExecute 107,382,000
 +
...
 +
Timer:Register 3,272,443,000
 +
Timer:RowFetch 25,340,990,000
 +
Timer:Sequencing 1,352,326,000
 +
Timer:SqlGeneration 6,646,000
 +
Timer:SqlPrepare 19,536,031,000
 +
Timer:StatementExecute 508,589,220,000
 +
Timer:TXAfterCompletion 1,854,152,000
 +
Timer:TXBeforeCompletion 169,381,843,000
 +
Timer:UnitOfWorkCommit 167,483,825,000
 +
Timer:UpdateObjectQuery 46,440,589,000
 +
Timer:UpdateObjectQuery:Customer 40,466,433,000
 +
Timer:UpdateObjectQuery:Customer:QueryPreparation 867,496,000
 +
Timer:UpdateObjectQuery:Customer:SqlGeneration 98,000
 +
Timer:UpdateObjectQuery:Customer:SqlPrepare 1,319,333,000
 +
Timer:UpdateObjectQuery:Customer:StatementExecute 32,901,366,000
 +
</pre>
  
 
{{EclipseLink_JPA
 
{{EclipseLink_JPA
−
|previous=[[EclipseLink/UserGuide/JPA/Advanced_JPA_Development/Performance|Performance]]
+
|previous=[[EclipseLink/UserGuide/JPA/Advanced JPA Development/Performance/Performance Monitoring and Profiling/Fetch Group Monitoring|Fetch Group Monitoring]]  
−
|next    =[[EclipseLink/UserGuide/JPA/Advanced_JPA_Development/Performance/Weaving|Weaving]]
+
|next    =[[EclipseLink/UserGuide/JPA/Advanced JPA Development/Performance/Performance Monitoring and Profiling/Query Monitoring|Query Monitoring]]  
−
|up      =[[EclipseLink/UserGuide/JPA/Advanced_JPA_Development/Performance|Performance]]
+
|up      =[[EclipseLink/UserGuide/JPA/Advanced JPA Development/Performance/Performance Monitoring and Profiling|Performance Monitoring and Profiling]]
 
|version=2.2.0 DRAFT}}
 
|version=2.2.0 DRAFT}}

Latest revision as of 07:41, 17 April 2013


Warning This page is now obsolete.

For current information, please see "Performance Monitoring" in the EclipseLink Concepts Guide: http://www.eclipse.org/eclipselink/documentation/latest/concepts/monitoring003.htm



EclipseLink JPA

Eclipselink-logo.gif
EclipseLink
Website
Download
Community
Mailing List • Forums • IRC • mattermost
Issues
Open • Help Wanted • Bug Day
Contribute
Browse Source

Performance Monitoring

Use the Performance Monitor to provide detailed profiling and monitoring information in a multithreaded server environment.

Enable the monitor in persistence.xml as follows: 

<property name="eclipselink.profiler" value="PerformanceMonitor"/>

The performance monitor can also be enabled through code using a SessionCustomizer.

The performance monitor will output a dump of cumulative statistics every minute to the EclipseLink log.

The statics contains three sets of information:

  • Info: Statistics that are constant informational data, such as the session name, or time of login.
  • Counter: Statistics that are cumulative counters of total operations, such as cache hits, or query executions.
  • Timer: Statistics that are cumulative measurements of total time (in nano seconds) for a specific type of operation, reading, writing, database operations.

Statistics are generally grouped in total and also by query type, query class, and query name. Counters and timers are generally recorded for the same operations, so the time per operation could also be calculated.

The time in between statistic dumps can be configured through the PerformanceMonitor API using the setDumpTime(long) API. If dumping the results is not desired, then dumpTime can be set to be very large such as Long.MAX_VALUE. The statistic can also be accessed programatically using the getOperationTime(String) API.

The performance monitor can also be configured with a profile weight.

The profile weights are defined on SessionProfiler and include:

  • NONE - No statistics are recorded.
  • NORMAL - Informational statistics are recorded.
  • HEAVY - Informational, counter and timer statistics are recorded.
  • ALL - All statistics are recorded (this is the default).

Example Output

Performance Monitor:1279113281664
Operation	Value (ns)
Counter:CacheHits	1,375,664
Counter:CacheMisses	327
Counter:ClientSessionCreates	1,204,817
Counter:ConnectCalls	2
Counter:DataModifyQuery	48
Counter:DataModifyQuery:inventory	21
Counter:DataModifyQuery:order	27
Counter:DeleteObjectQuery	67,792
Counter:DeleteObjectQuery:Customer	1
...
Counter:ReadAllQuery	1,041,767.
Counter:ReadAllQuery:Item.findByCategory	733,827
Counter:ReadAllQuery:Item.findByCategory:CacheHits	733,779
Counter:ReadAllQuery:Item.findByCategory:CacheMisses	50
...
Counter:ReadObjectQuery	1,058,273
Counter:ReadObjectQuery:Item:item	130,063
Counter:ReadObjectQuery:Item:item:CacheHits	130,063
Counter:ReadObjectQuery:Item:item:CacheMisses	1
Counter:UnitOfWorkCommits	72,568
Counter:UnitOfWorkCreates	471,491
Counter:UnitOfWorkRollbacks	1
Counter:UpdateObjectQuery	71,498
Counter:UpdateObjectQuery:Customer	62,531
...
Info:LoginTime	Wed Jul 14 08:55:41 EDT 2010
Info:SessionName	file:/scratch/user_domains/servers/mt-1/app.jar
Timer:Caching	6,411,372,000
Timer:ConnectionManagement	17,225,641,000
Timer:DeleteObjectQuery	41,351,430,000
Timer:DeleteObjectQuery:Customer	4,441,000
Timer:DeleteObjectQuery:Customer:QueryPreparation	86,000
Timer:DeleteObjectQuery:Customer:SqlGeneration	28,000
Timer:DeleteObjectQuery:Customer:SqlPrepare	72,000
Timer:DeleteObjectQuery:Customer:StatementExecute	2,265,000
...
Timer:InsertObjectQuery	69,111,086,000
Timer:Logging	4,236,000
Timer:Merge	1,144,400,000
Timer:ObjectBuilding	31,914,397,000
Timer:QueryPreparation	984,396,000
Timer:ReadAllQuery	260,943,930,000
Timer:ReadAllQuery:Item:Item.findByCategory	14,790,333,000
Timer:ReadAllQuery:Item:Item.findByCategory:ObjectBuilding	250,959,000
Timer:ReadAllQuery:Item:Item.findByCategory:QueryPreparation	1,880,000
Timer:ReadAllQuery:Item:Item.findByCategory:RowFetch	113,552,000
Timer:ReadAllQuery:Item:Item.findByCategory:SqlGeneration	522,000
Timer:ReadAllQuery:Item:Item.findByCategory:SqlPrepare	2,055,000
Timer:ReadAllQuery:Item:Item.findByCategory:StatementExecute	107,382,000
...
Timer:Register	3,272,443,000
Timer:RowFetch	25,340,990,000
Timer:Sequencing	1,352,326,000
Timer:SqlGeneration	6,646,000
Timer:SqlPrepare	19,536,031,000
Timer:StatementExecute	508,589,220,000
Timer:TXAfterCompletion	1,854,152,000
Timer:TXBeforeCompletion	169,381,843,000
Timer:UnitOfWorkCommit	167,483,825,000
Timer:UpdateObjectQuery	46,440,589,000
Timer:UpdateObjectQuery:Customer	40,466,433,000
Timer:UpdateObjectQuery:Customer:QueryPreparation	867,496,000
Timer:UpdateObjectQuery:Customer:SqlGeneration	98,000
Timer:UpdateObjectQuery:Customer:SqlPrepare	1,319,333,000
Timer:UpdateObjectQuery:Customer:StatementExecute	32,901,366,000

Eclipselink-logo.gif
Version: 2.2.0 DRAFT
Other versions...

Retrieved from "https://wiki.eclipse.org/index.php?title=EclipseLink/UserGuide/JPA/Advanced_JPA_Development/Performance/Performance_Monitoring_and_Profiling/Performance_Monitoring&oldid=334146"

This page was last modified 07:41, 17 April 2013 by Rick Sapir. Based on work by James and Ben Gelernter.

Back to the top