Using the profiler command-line interface
You can profile applications written with EPL in Apama Studio. 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. Or, you might want to obtain profile information without the overhead of Apama Studio. In these situations, you can use the command-line interface to the profiler, which is described here.
The command-line interface to the profiler consists of specifying the -r | --dorequest option with the engine_management utility:
engine_management -r "profiling on"
engine_management -r "profiling off"
engine_management -r "profiling get"
engine_management -r "profiling gettotal"
engine_management -r "profiling reset"
engine_management -r "profiling frequency"
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, either CPU, Plugin, Blocked, or Runnable).
Plugin — the correlator is executing a plugin 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 "profiling get" or "profiling 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,Plugin,Blocked,total ticks:573
3,3,processor:processor.::listenerAction::,/users/ukcam/cr/dev/4.3.0.0/apama-test/
system/correlator/corba/testcases/correctness/Corr_Corba_cor_543/Input/
create-state.mon:50,556,293,0,556,0,0,263,0
In the previous 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 plugin (263 samples). Each context spent similar amounts of time executing EPL and executing plug-ins but in different listeners (notice the different line numbers).
Here is more sample output:
3,3,Idle,,1,1,0,1,14,0,0,0
3,3,Only just started profiling,,0,0,0,0,2,0,0,0
3,3,Monitor:processor,,556,0,0,0,0,0,0,0
2,2,processor:processor.::listenerAction::,/users/ukcam/cr/dev/4.3.0.0/apama-test/
system/correlator/corba/testcases/correctness/Corr_Corba_cor_543/Input/create-state.mon:
34,556,261,0,556,0,0,295,0
2,2,Idle,,1,1,0,1,14,0,0,0
2,2,Only just started profiling,,0,0,0,0,2,0,0,0
2,2,Monitor:processor,,556,0,0,0,0,0,0,0
4,4,processor:processor.::listenerAction::,/users/ukcam/cr/dev/4.3.0.0/apama-test/
system/correlator/corba/testcases/correctness/Corr_Corba_cor_543/Input/create-state.mon:
65,556,296,0,556,0,0,260,0
4,4,Idle,,1,1,0,1,14,0,0,0
4,4,Only just started profiling,,0,0,0,0,2,0,0,0
4,4,Monitor:processor,,556,0,0,0,0,0,0,0
1,main,processor:processor.::listenerAction::,/users/ukcam/cr/dev/4.3.0.0/apama-test/
system/correlator/corba/testcases/correctness/Corr_Corba_cor_543/Input/create-state.mon:
18,556,283,0,556,0,0,273,0
1,main,Idle,,1,1,0,1,14,0,0,0
1,main,Only just started profiling,,0,0,0,0,2,0,0,0
1,main,Monitor:processor,,556,0,0,0,0,0,0,0
This output is intended to be imported to a spreadsheet, such as Excel. If you do that, then the values in one sample (one row) provide the following information in the following order:
Column Content | Description |
Context ID | ID of the context. A context ID is not present in data returned by -r "profiler gettotal". |
Context Name | Name of the context. A context name is not present in data returned by -r "profiler 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 chastenment 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.I |
CPU time | Number of samples in which the correlator is executing the location/action and is not in a plugin (see Plugin 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, Plugin, 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 |
Plugin | Number of samples in which the location is executing a correlator 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. |