Apama 10.11.3 | Deploying and Managing Apama Applications | Correlator Utilities Reference | Shutting down and managing components | Using the CPU profiler
 
Using the CPU profiler
The information in this topic applies to the correlator only.
Using the CPU profiler, you can profile applications written with EPL. Data collected in the profiler allows you to identify possible bottlenecks in an EPL application. When testing an application, or after you deploy an application, you might find it handy to write a script that includes obtaining profile information. The CPU profiler that is described here allows you to obtain profile information without the overhead of Software AG Designer (see also Profiling EPL Applications).
The CPU profiler is invoked using the -r (or --dorequest) option of the engine_management tool:
engine_management -r cpuProfile argument
where argument can be one of the following:
Argument
Description
on
Starts to capture the state of all contexts in the correlator.
off
Stops capturing profile data.
get
Returns the samples collected since the correlator was started or since the profiler was reset. Returned data is in CSV (comma-separated values) format. A sample is the state of the correlator at the moment the profiler collects data.
gettotal
Returns totals for all contexts.
reset
Clears profiling samples collected.
frequency
Returns the profiling frequency in Hertz.
If a context is executing, it is typically in the EPL interpreter. However, it might also be doing something such as matching events or collecting garbage. For EPL execution, there is a call stack for each context. For the purposes of the profiler, there is one entry at the top for the monitor name, then comes the listener/onload action, and then any actions that is calling, and so on. The only action that the correlator is actually executing is at the bottom of the stack.
A context can be in one or two of the following states:
*CPU. The correlator is executing code in this context.
*Runnable. The correlator has work to do in this context, but it has been rescheduled because the correlator is executing code in another context.
*Idle. The correlator has no work to do in this context.
*Non-Idle. The correlator has work to do in this context. When a context is in this state, it is also in one other state: CPU, Plug-in, Blocked, or Runnable.
*Plug-in. The correlator is executing a plug-in in this context.
*Blocked. The correlator cannot make progress in this context. It is blocked because of a full queue. The full queue might be the correlator output queue (the context is trying to emit an event) or another context's input queue.
When the profiler takes a sample, it examines every context in the correlator. Every entry in each context's call stack results in addition or modification of a line in the profiler output. The Cumulative column is incremented for all samples, and one or more of the other columns is incremented for the lowest (deepest) call stack element according to what states the context is in.
When the correlator is not executing EPL code, there is only one element in the stack, for example, when the correlator is processing an event.
The profiler's resolution is to a EPL action. That is, the profiler does not distinguish between lines within an action. The line number in the output is the first line of the action that generates code. For example, variable declarations without initializers, and comments do not generate code, while statements, and declarations with initializers, do generate code. The profiler treats the body of a listener (the code the correlator executes when the listener fires) as an action with the name ::listenerAction::.
If you want to profile parts of a single large action, you need to split the action into multiple actions in order to determine where time is spent. Remember that action calls have some cost, so that could skew the results.
The cpuProfile get or cpuProfile gettotal request returns samples to stdout as lines of comma-separated values.
Output is sorted by context and then by CPU time. For example:
Context ID,Context name,Location,Filename and line number,Cumulative time,
CPU time,Empty,Non-Idle,Idle,Runnable,Plug-in,Blocked,Total ticks:573
3,3,processor:processor.::listenerAction::,create-state.mon:
50,556,293,0,556,0,0,263,0
In the above output, nearly all of the time of this context (3) is spent in the listener that starts on line 50 of create-state.mon. The time is spread between executing EPL code (293 samples) and executing a plug-in (263 samples). Each context spent similar amounts of time executing EPL and executing plug-ins but in different listeners (notice the different line numbers).
This output is intended to be imported to a spreadsheet, such as Microsoft Excel. If you do that, then the values in one sample (one row) provide the following information in the following order:
Column header
Information shown in this column
Context ID
ID of the context. A context ID is not present in data returned by -r cpuProfile gettotal.
Context name
Name of the context. A context name is not present in data returned by -r cpuProfile gettotal.
Location
What the correlator is doing or where the correlator is executing code at the moment the sample was collected. The value is one of the following:
*Monitor:monitor_name — The top-level entry for the monitor.
*monitor_name.code_owner.action_name — For example, if monitor monny calls an action act on event pkg.evie, this location would be monny.pkg.evie.act. If a listener has been triggered, the action name is always ::listenerAction::.
*monitor_name.;GC — Garbage collection.
*Event:event_name — Event matching or coassignment of an event of that type.
*Idle — Correlator has no work to do.
*There are other possible values that you might rarely see. They are self explanatory.
Filename and line number
If the correlator is executing EPL code, indicates the filename and line number of the beginning of the action that is executing.
Cumulative time
Cumulative time indicates time spent in this location or in something that this location was calling (directly or indirectly). CPU time shows time spent in this location, not the actions it called.
CPU time
Number of samples in which the correlator is executing the location/action and is not in a plug-in (see Plug-in later in this table). CPU time is a subset of Cumulative time. It does not include time spent in the location(s) called by this location.
Empty
Number of samples in which the context was empty. An empty context should happen very rarely. A context might be empty if there is a race between getting the location and the state.
Non-Idle
Number of samples in which the context was at this row's location and not idle. Each sample in this count is also in the count for CPU time, Runnable, Plug-in, or Blocked.
Idle
Number of samples in which the context was idle. This should correspond to a location of Idle or Only just started profiling, which means it is an unknown state.
As with other cumulative counters, races can result in misleading results. For example, Idle in an action, but those are best ignored and should be small.
Runnable
Number of samples in which the location was the lowest point on the call stack and the context was runnable. Runnable means it could have made progress, but the scheduler determined that the correlator should run something else instead.
When all rows contain 0 for this entry, it means that the correlator never (or very rarely) had to re-schedule one context to run another context. A non-zero value means this location was running for a long time, and it was suspended so that other contexts could run.
Plug-in
Number of samples in which the location is executing an EPL plug-in.
Blocked
Number of samples in which the context was unable to make progress. For example, it was trying to emit an event but the correlator output queue was full, or it was trying to enqueue an event to a particular context but that context's input queue was full.
The cpuProfile request returns the following string, in addition to the column headers described above:
"Version:version, Snapshot time:time, Profile start time:time, Component ID:id, Host:host-name, Port:port"
String element
Output
Version:version
Information on the correlator version.
Snapshot time:time
Time at which the CPU profiler has taken the snapshot. This is the date in milliseconds. The date 1446716459541, for example, translates into Thu Nov 05 2015 09:40:59 in UTC time.
Profile start time:time
Time at which the CPU profiler has been started. This is the date in milliseconds.
Component ID:id
Correlator component ID.
Host:host-name
Name of the host on which the correlator is running.
Port:port
Port number on the above host.