Previous topic  Top  Next topic  Print this Topic
 

Profile: profile

 

This query option helps you to track down performance problems. It logs some of the statistics on the most expensive rules. This query option is useful for tracking down performance problems. It shows :

The most expensive builtins and operators (e.g. join operations)
The most expensive rules

Here is a small example. The following ObjectLogic program calculates the transitive closure of a graph:

edge(a,b).

edge(b,c).

edge(c,d).

edge(d,e).

edge(e,f).

 

@{r1} closure(?X,?Y,f(?Y,f(?X,nil))) :- edge(?X,?Y).

@{r2} closure(?X,?Y,f(?Y,?U)) :- edge(?Z,?Y) AND closure(?X,?Z,?U).

When you execute the query with the "profile" option:

@{q1, options[profile]} ?- closure(?X,?Y,?Z).

then you get something like:

---------------------------------------------------

Preparation(#selected: 3, #final: 4)

---------------------------------------------------

11 ms  PARSER       [OntoBrokerReasoner]           Parse and compile query

9 ms   PREPARATION  [OntoBrokerReasoner]           Compile operatornet

6 ms   PREPARATION  [Evaluator]                    BottomUp preparation

5 ms   REWRITER     [SchemaOptimizer]            

4 ms   PREPARATION  [OntoBrokerReasoner]           Selection of required rules

1 ms   REWRITER     [PropagateConstantsRewriter]  

... (plus 29 event(s) which took 4 ms)

Preparation time: 42 ms (wall time).

---------------------------------

Most expensive operations

---------------------------------

... (plus 11 operation(s) which took 0 ms)

Operation times: 3 ms (wall time).

---------------------------------

Operator statistics

---------------------------------

bu3joinIDB  5 ms  5 calls    [bu3joinIDB [segment { [closure(?X,?Z,?U,_defaultModule), "assign"(?_X1,f(?Y,?U))}]]

bu3joinEDB  0 ms  1 call     [bu3joinEDB [edge(?X,?Y,_defaultModule), "assign"(?_X0,f(?Y,f(?X,nil)))]]

bu3joinEDB  0 ms  1 call     [bu3joinEDB [edge(?Z,?Y,_defaultModule)]]

bu3move     0 ms  1 call     [bu3move [segment { [closure(?X,?Y,?Z,_defaultModule)}]]

bu3move     0 ms  1 call     [bu3move [segment { ["$QUERY$obl:default:q1"(?X,?Y,?Z)}]]

Operator times: 6 ms (wall time).

---------------------------------------------------

Rule statistics

---------------------------------------------------

5 ms    r2  closure(?X,?Y,?_X1,_defaultModule) :- edge(?Z,?Y,_defaultModule) AND closure(?X,?Z,?U,_defaultModule) AND "assign"(?_X1,f(?Y,?U)).

0 ms    r1  closure(?X,?Y,?_X0,_defaultModule) :- edge(?X,?Y,_defaultModule) AND "assign"(?_X0,f(?Y,f(?X,nil))).

0 ms    q1  "$QUERY$obl:default:q1"(?X,?Y,?Z) :- closure(?X,?Y,?Z,_defaultModule).

0 ms    q1  ?- "$QUERY$obl:default:q1"(?X,?Y,?Z).

Rule times: 6 ms (wall time).

---------------------------------------------------

Operatornet execution times

---------------------------------------------------

Wall time: 6 ms.

CPU time: N/A

The results above are for "Storage=RAM.TS" and the bottom-up evaluator "BottomUp3". Note that the output for other storage settings and other evaluation methods may be different. The administration console will show the result of "profile" in a separate window:

adminconsole_profile

How to Interpret Profiling Results

The whole point of the "profile" option is to give some ideas on where the evaluation time is spent and to identify the problematic rules. The first section will show the query compilation time. This includes parsing, rewriting and compiling the query.

---------------------------------------------------

Preparation(#selected: 3, #final: 4)

---------------------------------------------------

11 ms  PARSER       [OntoBrokerReasoner]           Parse and compile query

9 ms   PREPARATION  [OntoBrokerReasoner]           Compile operatornet

6 ms   PREPARATION  [Evaluator]                    BottomUp preparation

5 ms   REWRITER     [SchemaOptimizer]            

4 ms   PREPARATION  [OntoBrokerReasoner]           Selection of required rules

1 ms   REWRITER     [PropagateConstantsRewriter]  

... (plus 29 event(s) which took 4 ms)

Preparation time: 42 ms (wall time).

The most expensive operation is to parse and to compile the query (11 ms). The total preparation time is 42 ms, which means that there is no special performance issue in the preparation phase. The next section shows the most expensive low-level operations:

---------------------------------

Most expensive operations

---------------------------------

... (plus 11 operation(s) which took 0 ms)

Operation times: 3 ms (wall time).

 

Well, at least it would show something if there were some expensive low-level operations (e.g. database accesses or very large joins). But our example ontology is too small and so not much time was spent on low-level operations.
The next section shows the most expensive operators.

---------------------------------

Operator statistics

---------------------------------

bu3joinIDB  5 ms  5 calls    [bu3joinIDB [segment { [closure(?X,?Z,?U,_defaultModule), "assign"(?_X1,f(?Y,?U))}]]

bu3joinEDB  0 ms  1 call     [bu3joinEDB [edge(?X,?Y,_defaultModule), "assign"(?_X0,f(?Y,f(?X,nil)))]]

bu3joinEDB  0 ms  1 call     [bu3joinEDB [edge(?Z,?Y,_defaultModule)]]

bu3move     0 ms  1 call     [bu3move [segment { [closure(?X,?Y,?Z,_defaultModule)}]]

bu3move     0 ms  1 call     [bu3move [segment { ["$QUERY$obl:default:q1"(?X,?Y,?Z)}]]

Operator times: 6 ms (wall time).

 

Operators are typically

Join operations
Match operations
Built-ins
Connectors

This means when you have an expensive connector to an external database it will show up in this list. The next section is probably the one on that you should look at first. It shows the most expensive rules of the evaluation:

---------------------------------------------------

Rule statistics

---------------------------------------------------

5 ms    r2  closure(?X,?Y,?_X1,_defaultModule) :- edge(?Z,?Y,_defaultModule) AND closure(?X,?Z,?U,_defaultModule) AND "assign"(?_X1,f(?Y,?U)).

0 ms    r1  closure(?X,?Y,?_X0,_defaultModule) :- edge(?X,?Y,_defaultModule) AND "assign"(?_X0,f(?Y,f(?X,nil))).

0 ms    q1  "$QUERY$obl:default:q1"(?X,?Y,?Z) :- closure(?X,?Y,?Z,_defaultModule).

0 ms    q1  ?- "$QUERY$obl:default:q1"(?X,?Y,?Z).

Rule times: 6 ms (wall time).

In this example the rule "r2" is the most expensive rule because it will be executed multiple times (it is a recursive rule).