12. Profiler

12.1. Introduction

The Gentics Portal.Node Profiler allows users to inspect the performance of their portal. Various performance aspects can be easily verified. The main questions answered by the profiler include:

  • What is the bottleneck of my portal? (templates, SQL statements, 3rd party portlets, pluggable actions, ...)
  • Is the expiration cache applied correctly to all portlets?
  • Which portlet requires most time to render or process its actions?
  • Should I optimize a Gentics .Node ContentRepository attribute? Is the datasource caching configuration effective?
  • For implementations based on the “ViewPlugin” (Section 2.2):
    • How fast are my actions processed? How often are they actually called?
    • Are the velocity templates eating performance?

12.2. Accessing the profiler

For security reasons the Gentics Portal.Node Profiler is protected by a security constraint which only allows users with the role manager or gentics to access the profiler. This requires a corresponding user configuration for your application server.

Example 3.23. Tomcat User Configuration

When using Apache Tomcat, the user configuration is usually handled by the file tomcat/conf/tocmat-users.xml. The following is a very simple example for a user with the username: tomcat and password: tomcat who has access to the Gentics Portal.Node Profiler.


<tomcat-users>
  <role rolename="tomcat" />
  <role rolename="manager" />
  <role rolename="gentics" />
  <user name="tomcat" password="tomcat" roles="manager"/>
</tomcat-users>

			

After successfully configuring your application server you can access the Gentics Portal.Node Profiler by opening the url /Portal.Node/profiler in your browser. For example for Gentics Portal.Node SDK Users: http://localhost:42880/Portal.Node/profiler.

12.3. Commands

Below the list of sections is a list of commands which can be executed:

  • Start: Start recording of profiler marks.
  • Stop: Stop recording.
  • Reset: Discard all recorded profiler marks.
  • Refresh: Reload the current page showing up to date information.
  • Call GC: Invokes the Garbage Collector of the Java Virtual Machine.

12.4. Performance Impact

Before the Gentics Portal.Node Profiler can display detailed performance statistics it has to record invocations of specific profiler marks. This means that starting the profiler can have an impact on two performance aspects of your portal:

  • Memory: By default every invocation will be stored in memory for immediate analysis. This can mean up to 200 bytes per invocation. You can see the number of invocations recorded so far in the “Status View” (Section 12.5).
  • CPU Performance: Every recorded invocation will have a minor cpu performance impact. Usually this has almost no noticeable effect but it should be considered before activating the profiler in a production environment.

12.5. Status View

When first accessing the Gentics Portal.Node Profiler the "Status" view is opened. It gives a very brief overview of the status of the profiler itself, and the Java Virtual Machine in general.

12.5.1. Statistic Table

The table to the left shows general information about your installation. The most important data are:

  • Profiler Status: Shows if the profiler is currently recording invocations.
  • Recorded Invocations: If this is non-zero there are already requests which were recorded and you can switch into the Basic View for analyzing the performance of your portal.
  • Memory: Gives you insight in how much memory the Java Virtual Machine currently uses. This is also displayed in the memory graph on the right.
  • Portal Server: Displays the version, codename and build number of the Gentics Portal.Node instance currently running on the server.

12.5.2. Memory

In a production environment the memory graph to the right should give a good insight if your memory settings are in effect and if the full capacity is used by the portal.

  • Free Memory: Memory within the java heap space which is not in use.
  • Used Memory: Memory that was allocated by the portal server including garbage memory which will be collected and freed by the JVM automatically or when manually manually invoking the 'Call GC' (Call Garbage Collector) link. (Free Memory + Used Memory = Total Memory currently in use by the JVM process)
  • Unallocated Memory: Memory that will be allocated by the JVM before running out of memory. (This maximum memory is usually defined by a JVM specific setting like '-Xmx' for the Sun JVM.)

12.6. Profiler Basic

The basic profiler view is the main part of the profiler, giving an overview of the overall performance of the portal and each portlet.

12.6.1. Summary

On the top of the basic view is a short summary which gives you a reference for all performance measurements by providing information on how much requests were recorded and how long they have taken in total.

This can be compared to the duration of every measured point to get an idea how much impact it has on the overall performance.

12.6.2. Overview Tab

The overview pie chart gives a good overview of what section is responsible for most of the time of a request. The total 100% of this chart represent the total request duration with every section having its own tab (described below) showing more detailed information. All sections in the pie chart are "exclusive times" only counting times which they are directly responsible for, without anything that is already counted for another section. (e.g. Datasource Queries which are executed within a velocity template are only counted once for 'SQL Queries' and not for rendering templates.)

12.6.3. Portlets Tab

The Portlets Tab shows the total time every portlet required for its action and render phase. Probably the most important are the number of invocations per portlet because it can be a good indicator if the portlet cache is working properly.

[Note]Note

Times in this tab will be much higher from what is shown in the “Overview Tab” (Section 12.6.2). This is because the overview excludes times which are already measured in other sections (like database access, template rendering or pluggable actions).

12.6.4. SQL Queries Tab

This tab shows the slowest SQL queries produced by Gentics Portal.Node APIs (within views or by directly using Gentics Portal.Node datasources). (These are usually generated from expression strings from the “ExpressionParser” (Section 10).)

  • Invocations: A very high number of invocations can indicate that there is a problem with the datasource cache - for example by including a variable in an expression which changes for every request like a timestamp or counter.
  • Time: If there are few very slow queries it might be possible to improve performance by creating optimized attributes for Gentics .Node ContentRepository attributes or by adding additional database indices.

12.6.5. Pluggable Actions Tab

Shows the total runtime of all pluggable actions used in views.

12.6.6. Templates Tab

This graph shows the slowest velocity templates. It includes the time required by velocity to render the template as well as subsequent method calls not recorded by other invocations. (E.g. generating portlet URLs will be included in these time statistics, but rendering of child components or executing sql statements are not included.)

12.7. Profiler Advanced

In the advanced section of the Gentics Portal.Node Profiler every single profiler mark can be seen in a flat overview as well as a hierarchical caller tree.

[Warning]Warning

Because of the vast amounts of profiler marks and the complexity required to show detailed performance measurements, the advanced profiler section is still considered beta and is provided AS IS without any warranty or support.

12.7.1. Flat

The flat view lists all recorded profiler marks with their number of invocations and performance statistics. By clicking on a profiler mark you can switch into the tree mode to see a hierarchical invocation tree.

[Note]Note

Profiler marks are listed once for every 'instance key' (for example for portlets the name of the portlet) and once summed up without an instance key.

12.7.2. Tree

The tree has two modes: The default mode which is opened when clicking on any profiler mark in the flat view shows a tree with the root node being the outer most profiler mark which invokes all others.

The second mode is the 'Caller Tree' which can be opened by right clicking on a profiler mark and selecting 'Caller Tree'. This shows the inner most profiler mark as root node and below it are profiler marks from where it was called.

12.7.3. Inclusive / Exclusive Times

In the flat and tree view there are two radio boxes in the header which allow switching between an 'Inclusive' and an 'Exclusive' mode.

The inclusive mode shows times from the start of the profiler mark until the end.

The exclusive mode only shows the time required by the current profiler mark - any time which is already counted for another profiler mark is subtracted.

[Note]Note

Exclusive times are calculated no matter how the profiler settings are configured. Usually when adding up all exclusive 'Total' times in the flat view (without view limit) it would result in the same time displayed for the 'Gentics' profiler mark in inclusive mode, or the 'Total recorded request duration' in the Basic Profiler. But when profiler marks are not recorded the sum of all exclusive profiler marks will be much lower.

12.7.4. View Limit

The view limit, which can be customized with the combo box in the 'Percent' column, is used to hide all profiler marks under a certain percent threshold.

12.7.5. Time Units / 90% Line

By default all time values are displayed in milliseconds (ms). But it can be customized to display either seconds or nano seconds (in a Java 1.5 environment). To do so click on the '(ms)' link in any column header which displays time values.

The same way it is possible to switch the 90% line to any other xx% of your choosing. (The 90% line shows the average time per invocation for the fastest 90%.)

12.7.6. Snapshots

It is possible to store a profiler run in a 'Profiler Snapshot' by simply clicking on the 'Save Snapshot' link. It can then be loaded into any other Gentics Portal.Node (or Gentics Portal.Node SDK) installation.

The 'Load Snapshot' functionality can be used for either snapshots saved through the 'Save Snapshot' link, or for files created by “Recording to file” (Section 12.8.1).

12.7.7. Velocity Profiler Mark Directive

To make it possible to benchmark custom templates in greater detail, a velocity directive is provided to allow implementors to add custom profiler marks to their velocity templates.

The profiler mark used has the syntax: #profilermark( "profiler mark" "instance key (optional)" ). (The profiler mark has to be a string, while the optional instance key can be any serializable object.)

Example 3.24. Profiling component template

The following example profiles the rendering of a simple ButtonComponent.


#profilermark( "custom/velocitymark/button" $button.name )
   <input id="$button.name" value="$button.label" name="$button.name" type="submit" />
#end

				

The custom profiler marks can then be seen in the advanced profiler section as shown below. (Make sure that all marks are recorded in the “Recording Settings” (Section 12.8.2) as well as that there is no viewlimit in place which might prevent these marks from showing up.)

[Warning]Warning

Adding customized profiler marks can distort the overview of the basic view, because these profiler marks will be excluded from the render times of templates.

12.8. Profiler Settings

This section allows users to customize the way the profiler records invocations.

12.8.1. Recording to file

Instead of holding all data in memory for analyzing this option allows using the profiler just to record data and imediately write them out into the filesystem without holding them in memory. This is especially useful to allow recording of profiler marks under decent load (e.g. in a minor load test, or even a production environment).

[Warning]Warning

The profiler will still decrease overall system performance. It is not recommended to be activated on any system which is already under heavy load.

When recording to a file no statistics can be viewed. After finishing a recording session download the file and load it into the Gentics Portal.Node Profiler in the “Profiler Advanced” (Section 12.7) (see Section 12.7.6, “Snapshots”).

12.8.2. Recording Settings

This setting allows customization on what profiler marks are recorded and therefore limit memory and CPU overhead produced by the Gentics Portal.Node Profiler. The default marks which are activated are the Minimal Recording Settings which define a minimum of profiler marks required for the “Profiler Basic” (Section 12.6) . If you are exploring the “Profiler Advanced” (Section 12.7) you can try activating the Normal Recording Settings for more runtime information. If even more information is required, for example when using the “Velocity Profiler Mark Directive” (Section 12.7.7) the Verbose Recording Settings can be used.

12.9. Cache (JCS)

The JCS Cache section shows a brief overview of all cache regions used by Gentics Portal.Node and their total contained items with the corresponding cache hits and cache misses. Please see Section 10, “Cache” for more information on the cache and cache regions.