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.
The last trace information can be queried from the system view
sys.tracelog or the system function sys.tracelog().
sql>SELECT * FROM sys.tracelog;
+-------+------+-------+
| ticks | stmt | event |
+=======+======+=======+
+-------+------+-------+
0 tuples
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.
After that, we run the query SELECT * FROM sys.tracelog; to get the
trace information where the ticks column reports the execution time in
microseconds.
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
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>