A performance trace can be obtained using the TRACE statement modifier.
The trace information is returned as a result set and
displayed automatically when using mclient.
It is also saved in a temporary table, called sys.tracelog(), and queried for e.g.
top most expensive operations.
CREATE FUNCTION sys.tracelog()
RETURNS table (
ticks bigint, -- time in microseconds
stmt string -- actual MAL statement executed
)
EXTERNAL NAME sql.dump_trace;
CREATE VIEW sys.tracelog AS SELECT * FROM sys.tracelog();
For a more detailed performance analysis consider using the Stethoscope.
The small example below illustrates what you can expect. Each row contains the
execution time in microseconds. The timing flag is set to identify where
time goes. The term sql: is the time spent in the SQL parser and optimizer,
opt: the time spent in the MAL optimizers, run: the actual executiontime
in the kernel, and clk: the walk clock as measured in the Mclient
The large difference of the clk:6.435 ms compared to the sum of sql + opt + run
= 1.797 ms stems from the client-server protocol. In the embedded version of MonetDB
these numbers will be much more close.
sql>\t performance
sql>trace select count(*) from sys.tables;
+------+
| %10 |
+======+
| 126 |
+------+
1 tuple
sql:0.964 opt:0.227 run:0.606 clk:6.435 ms
+------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| usec | statement |
+======+============================================================================================================================================================================================================+
| 4 | X_0=0@0:void := querylog.define("trace select count(*) from sys.tables;":str, "default_pipe":str, 27:int); |
| 4 | X_1=0:int := sql.mvc(); |
| 15 | C_2=[126]:bat[:oid] := sql.tid(X_1=0:int, "sys":str, "_tables":str); |
| 20 | X_3=[0]:bat[:lng] := bat.new(nil:lng); |
| 17 | (X_4=[0]:bat[:oid], X_5=[0]:bat[:sht]) := sql.bind(X_1=0:int, "sys":str, "_tables":str, "type":str, 2:int); |
| 8 | C_7=[0]:bat[:oid] := algebra.thetaselect(X_5=[0]:bat[:sht], nil:bat[:oid], 2:sht, "!=":str); # select: trivially empty |
| 15 | X_6=[126]:bat[:sht] := sql.bind(X_1=0:int, "sys":str, "_tables":str, "type":str, 0:int); |
| 14 | C_8=[0]:bat[:oid] := sql.tid(X_1=0:int, "tmp":str, "_tables":str); |
| 4 | X_9=0:lng := aggr.count(C_8=[0]:bat[:oid]); |
| 33 | C_10=[126]:bat[:oid] := algebra.thetaselect(X_6=[126]:bat[:sht], C_2=[126]:bat[:oid], 2:sht, "!=":str); # select: densescan !((v) == ((sht) (-32767-1)+1)-1) && (v <= vl || v >= vh) (canditer_next_dense) |
| 2 | C_11=[126]:bat[:oid] := sql.subdelta(C_10=[126]:bat[:oid], C_2=[126]:bat[:oid], X_4=[0]:bat[:oid], C_7=[0]:bat[:oid]); |
| 1 | X_12=0@0:void := language.pass(C_2=[126]:bat[:oid]); |
| 4 | X_13=126:lng := aggr.count(C_11=[126]:bat[:oid]); |
| 7 | X_14=[1]:bat[:lng] := bat.single(X_13=126:lng); |
| 6 | X_15=[1]:bat[:lng] := bat.append(X_3=[1]:bat[:lng], X_14=[1]:bat[:lng], true:bit); |
| 3 | X_16=[2]:bat[:lng] := bat.append(X_15=[2]:bat[:lng], X_9=0:lng, true:bit); |
| 6 | X_17=126:lng := aggr.sum(X_16=[2]:bat[:lng]); # sum: no candidates, no groups |
| 562 | barrier X_18=false:bit := language.dataflow(); |
| 34 | X_19=0:int := sql.resultSet(".%10":str, "%10":str, "bigint":str, 64:int, 0:int, 7:int, X_17=126:lng); |
+------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
19 tuples
sql:0.964 opt:0.000 run:0.000 clk:6.505 ms