A performance trace can be obtained using the TRACE statement modifier.
When executing a TRACE statement, it executes the statement and records the timings of every MAL statement.
It returns both the results of the statement execution and the trace information.
In mclient, jdbcclient and some GUI clients, both results are displayed automatically.
The last trace information can also be queried from the system view
sys.tracelog or the system function sys.tracelog().
sql>SELECT * FROM sys.tracelog;
+-------+------+-------+
| ticks | stmt | event |
+=======+======+=======+
+-------+------+-------+
0 tuples
For a more detailed performance analysis consider using the Stethoscope.
First the mclient timer flag is set to performance to also print 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 execution time in the kernel,
and clk: the clock time as measured by mclient.
Next we execute trace select count(*) from sys.tables; statement.
The example below illustrates what you can expect.
It first shows the result of the statement execution.
Next the execution trace information where the usec column reports the execution time in microseconds.
At the end we run query: SELECT * FROM sys.tracelog; again.
sql>\t performance
sql>trace select count(*) from sys.tables;
+------+
| %2 |
+======+
| 143 |
+------+
1 tuple
sql:0.931 opt:0.489 run:5.154 clk:5.869 ms
+------+-----------------------------------------------------------------------------------+
| usec | statement |
+======+===================================================================================+
| 5 | X_1=0@0:void := querylog.define("trace select count(*) from sys.tables;":str, |
: : "default_pipe":str, 25:int); :
| 5 | X_4=0:int := sql.mvc(); |
| 14 | X_5=435[143]:bat[:oid] := sql.tid(X_4=0:int, "sys":str, "_tables":str); |
| 7 | X_23=443[0]:bat[:oid] := sql.tid(X_4=0:int, "tmp":str, "_tables":str); |
| 3 | X_34=0:lng := aggr.count(X_23=443[0]:bat[:oid]); |
| 8 | X_37=443[1]:bat[:lng] := bat.single(X_34=0:lng); |
| 2 | X_22=143:lng := aggr.count(X_5=435[143]:bat[:oid]); |
| 5 | X_35=435[1]:bat[:lng] := bat.single(X_22=143:lng); |
| 7 | X_36=452[1]:bat[:lng] := mat.packIncrement(X_35=435[1]:bat[:lng], 2:int); |
| 5 | X_38=452[2]:bat[:lng] := mat.packIncrement(X_36=452[2]:bat[:lng], X_37=443[1] |
: : :bat[:lng]); :
| 5 | X_39=143:lng := aggr.sum(X_38=452[2]:bat[:lng]); # sum: no candidates, no gro |
: : ups :
| 511 | barrier X_99=false:bit := language.dataflow(); |
| 33 | X_41=0:int := sql.resultSet(".%2":str, "%2":str, "bigint":str, 63:int, 0:int, |
: : 7:int, X_39=143:lng); :
+------+-----------------------------------------------------------------------------------+
13 tuples
sql:0.931 opt:0.000 run:0.000 clk:5.949 ms
sql>SELECT * FROM sys.tracelog;
+------+-----------------------------------------+-----------------------------------------+
| tick | stmt | event |
: s : : :
+======+=========================================+=========================================+
| 5 | X_1=0@0:void := querylog.define("tr | {"sessionid":"0","clk":13188078549,"thr |
: : ace select count(*) from sys.tables;":s : ead":19,"phase":"mal_engine","pc":1,"ta :
: : tr, "default_pipe":str, 25:int); : g":153,"module":"querylog","function":" :
: : : define","usec":5,"args":[{"ret":0,"var" :
: : : :"X_1","type":"void","const":0,"value": :
: : : "0@0","eol":1},{"arg":1,"var":"X_2","ty :
: : : pe":"str","const":1,"value":"trace sele :
: : : ct count(*) from sys.tables;","eol":1}, :
: : : {"arg":2,"var":"X_3","type":"str","cons :
: : : t":1,"value":"default_pipe","eol":1},{" :
: : : arg":3,"var":"X_48","type":"int","con...>
| 5 | X_4=0:int := sql.mvc(); | {"sessionid":"0","clk":13188078677,"thr |
: : : ead":3,"phase":"mal_engine","pc":3,"tag :
: : : ":153,"module":"sql","function":"mvc"," :
: : : usec":5,"args":[{"ret":0,"var":"X_4","t :
: : : ype":"int","const":0,"value":0,"eol":6} :
: : : ]} :
| 14 | X_5=435[143]:bat[:oid] := sql.tid(X | {"sessionid":"0","clk":13188078733,"thr |
: : _4=0:int, "sys":str, "_tables":str); : ead":3,"phase":"mal_engine","pc":4,"tag :
: : : ":153,"module":"sql","function":"tid"," :
: : : usec":14,"args":[{"ret":0,"var":"X_5"," :
: : : type":"bat[:oid]","mode":"transient","s :
: : : orted":1,"revsorted":0,"nonil":1,"nil": :
: : : 0,"key":1,"nestimate":"143","file":"35" :
: : : ,"width":0,"bid":435,"count":143,"size" :
: : : :143,"eol":5},{"arg":1,"var":"X_4","typ :
: : : e":"int","const":0,"value":0,"eol":6},{ :
: : : "arg":2,"var":"X_6","type":"str","con...>
| 7 | X_23=443[0]:bat[:oid] := sql.tid(X_ | {"sessionid":"0","clk":13188078784,"thr |
: : 4=0:int, "tmp":str, "_tables":str); : ead":3,"phase":"mal_engine","pc":6,"tag :
: : : ":153,"module":"sql","function":"tid"," :
: : : usec":7,"args":[{"ret":0,"var":"X_23"," :
: : : type":"bat[:oid]","mode":"transient","s :
: : : orted":1,"revsorted":1,"nonil":1,"nil": :
: : : 0,"key":1,"file":"43","width":0,"bid":4 :
: : : 43,"count":0,"size":0,"eol":7},{"arg":1 :
: : : ,"var":"X_4","type":"int","const":0,"va :
: : : lue":0,"eol":6},{"arg":2,"var":"X_24"," :
: : : type":"str","const":1,"value":"tmp","...>
| 3 | X_34=0:lng := aggr.count(X_23=443[0 | {"sessionid":"0","clk":13188078825,"thr |
: : ]:bat[:oid]); : ead":3,"phase":"mal_engine","pc":7,"tag :
: : : ":153,"module":"aggr","function":"count :
: : : ","usec":3,"args":[{"ret":0,"var":"X_34 :
: : : ","type":"lng","const":0,"value":0,"eol :
: : : ":10},{"arg":1,"var":"X_23","type":"bat :
: : : [:oid]","mode":"transient","sorted":1," :
: : : revsorted":1,"nonil":1,"nil":0,"key":1, :
: : : "file":"43","width":0,"bid":443,"count" :
: : : :0,"size":0,"eol":7}]} :
| 8 | X_37=443[1]:bat[:lng] := bat.single | {"sessionid":"0","clk":13188078878,"thr |
: : (X_34=0:lng); : ead":3,"phase":"mal_engine","pc":10,"ta :
: : : g":153,"module":"bat","function":"singl :
: : : e","usec":8,"args":[{"ret":0,"var":"X_3 :
: : : 7","type":"bat[:lng]","mode":"transient :
: : : ","sorted":1,"revsorted":1,"nonil":1,"n :
: : : il":0,"key":1,"minpos":"0","maxpos":"0" :
: : : ,"nestimate":"1","file":"43","width":8, :
: : : "bid":443,"count":1,"size":8,"eol":11}, :
: : : {"arg":1,"var":"X_34","type":"lng","con :
: : : st":0,"value":0,"eol":10}]} :
| 2 | X_22=143:lng := aggr.count(X_5=435[ | {"sessionid":"0","clk":13188078907,"thr |
: : 143]:bat[:oid]); : ead":3,"phase":"mal_engine","pc":5,"tag :
: : : ":153,"module":"aggr","function":"count :
: : : ","usec":2,"args":[{"ret":0,"var":"X_22 :
: : : ","type":"lng","const":0,"value":143,"e :
: : : ol":8},{"arg":1,"var":"X_5","type":"bat :
: : : [:oid]","mode":"transient","sorted":1," :
: : : revsorted":0,"nonil":1,"nil":0,"key":1, :
: : : "nestimate":"143","file":"35","width":0 :
: : : ,"bid":435,"count":143,"size":143,"eol" :
: : : :5}]} :
| 5 | X_35=435[1]:bat[:lng] := bat.single | {"sessionid":"0","clk":13188078946,"thr |
: : (X_22=143:lng); : ead":3,"phase":"mal_engine","pc":8,"tag :
: : : ":153,"module":"bat","function":"single :
: : : ","usec":5,"args":[{"ret":0,"var":"X_35 :
: : : ","type":"bat[:lng]","mode":"transient" :
: : : ,"sorted":1,"revsorted":1,"nonil":1,"ni :
: : : l":0,"key":1,"minpos":"0","maxpos":"0", :
: : : "nestimate":"1","file":"35","width":8," :
: : : bid":435,"count":1,"size":8,"eol":9},{" :
: : : arg":1,"var":"X_22","type":"lng","const :
: : : ":0,"value":143,"eol":8}]} :
| 7 | X_36=452[1]:bat[:lng] := mat.packIn | {"sessionid":"0","clk":13188078979,"thr |
: : crement(X_35=435[1]:bat[:lng], 2:int); : ead":3,"phase":"mal_engine","pc":9,"tag :
: : : ":153,"module":"mat","function":"packIn :
: : : crement","usec":7,"args":[{"ret":0,"var :
: : : ":"X_36","type":"bat[:lng]","mode":"tra :
: : : nsient","sorted":1,"revsorted":1,"nonil :
: : : ":1,"nil":0,"key":1,"minpos":"0","maxpo :
: : : s":"0","nestimate":"1","file":"52","wid :
: : : th":8,"bid":452,"count":1,"size":8,"eol :
: : : ":11},{"arg":1,"var":"X_35","type":"bat :
: : : [:lng]","mode":"transient","sorted":1...>
| 5 | X_38=452[2]:bat[:lng] := mat.packIn | {"sessionid":"0","clk":13188079026,"thr |
: : crement(X_36=452[2]:bat[:lng], X_37=443 : ead":3,"phase":"mal_engine","pc":11,"ta :
: : [1]:bat[:lng]); : g":153,"module":"mat","function":"packI :
: : : ncrement","usec":5,"args":[{"ret":0,"va :
: : : r":"X_38","type":"bat[:lng]","mode":"tr :
: : : ansient","sorted":0,"revsorted":1,"noni :
: : : l":1,"nil":0,"key":1,"minpos":"1","maxp :
: : : os":"0","nestimate":"1","file":"52","wi :
: : : dth":8,"bid":452,"count":2,"size":16,"e :
: : : ol":12},{"arg":1,"var":"X_36","type":"b :
: : : at[:lng]","mode":"transient","sorted"...>
| 5 | X_39=143:lng := aggr.sum(X_38=452[2 | {"sessionid":"0","clk":13188079078,"thr |
: : ]:bat[:lng]); # sum: no candidates, no : ead":3,"phase":"mal_engine","pc":12,"ta :
: : groups : g":153,"module":"aggr","function":"sum" :
: : : ,"usec":5,"algorithm":"sum: no candidat :
: : : es, no groups","args":[{"ret":0,"var":" :
: : : X_39","type":"lng","const":0,"value":14 :
: : : 3,"eol":14},{"arg":1,"var":"X_38","type :
: : : ":"bat[:lng]","mode":"transient","sorte :
: : : d":0,"revsorted":1,"nonil":1,"nil":0,"k :
: : : ey":1,"minpos":"1","maxpos":"0","nestim :
: : : ate":"1","file":"52","width":8,"bid":...>
| 511 | barrier X_99=false:bit := language.data | {"sessionid":"0","clk":13188079134,"thr |
: : flow(); : ead":19,"phase":"mal_engine","pc":2,"ta :
: : : g":153,"module":"language","function":" :
: : : dataflow","barrier":"barrier","usec":51 :
: : : 1,"args":[{"ret":0,"var":"X_99","type": :
: : : "bit","const":0,"value":"false","eol":1 :
: : : 3}]} :
| 33 | X_41=0:int := sql.resultSet(".%2":s | {"sessionid":"0","clk":13188079195,"thr |
: : tr, "%2":str, "bigint":str, 63:int, 0:i : ead":19,"phase":"mal_engine","pc":14,"t :
: : nt, 7:int, X_39=143:lng); : ag":153,"module":"sql","function":"resu :
: : : ltSet","usec":33,"args":[{"ret":0,"var" :
: : : :"X_41","type":"int","const":0,"value": :
: : : 0,"eol":14},{"arg":1,"var":"X_42","type :
: : : ":"str","const":1,"value":".%2","eol":1 :
: : : 4},{"arg":2,"var":"X_43","type":"str"," :
: : : const":1,"value":"%2","eol":14},{"arg": :
: : : 3,"var":"X_44","type":"str","const":1," :
: : : value":"bigint","eol":14},{"arg":4,"v...>
+------+-----------------------------------------+-----------------------------------------+
13 tuples !7 fields truncated!
note: to disable dropping columns and/or truncating fields use \w-1
sql:0.115 opt:0.435 run:1.682 clk:3.803 ms
sql>