Runtime features

Runtime features mk Sun, 03/28/2010 - 23:51

The SQL statement modifiers provide system specific information over e.g. relational query plan, MAL execution plan, performance, and access to the debugger.

EXPLAIN SQL STMT

EXPLAIN SQL STMT mk Sun, 03/28/2010 - 23:24

The intermediate code produced by the SQL compiler can be made visible using the explain statement modifier. It gives a detailed description of the actions taken to produce the answer.  The example below illustrates what you can expect when a simple query is starts with  the explain modifier. The output strongly depends on the optimizer pipeline. The details of this program are better understood when you have read the MAL  reference.

sql>select count(*) from tables;
+------+
| L41  |
+======+
|   93 |
+------+
1 tuple
clk: 1.993ms
sql>explain select count(*) from tables;
+------------------------------------------------------------------------------------------------------------------------+
| mal                                                                                                                    |
+========================================================================================================================+
| function user.s6_1():void;                                                                                             |
|     X_1:void := querylog.define("select count(*) from tables;":str, "default_pipe":str, 30:int);                       |
| barrier X_104:bit := language.dataflow();                                                                              |
|     X_38:bat[:lng] := bat.new(nil:lng);                                                                                |
|     X_4:int := sql.mvc();                                                                                              |
|     X_18:bat[:sht] := sql.bind(X_4:int, "sys":str, "_tables":str, "type":str, 0:int);                                  |
|     C_5:bat[:oid] := sql.tid(X_4:int, "sys":str, "_tables":str);                                                       |
|     C_89:bat[:oid] := algebra.thetaselect(X_18:bat[:sht], C_5:bat[:oid], 2:sht, "!=":str);                             |
|     (X_21:bat[:oid], X_22:bat[:sht]) := sql.bind(X_4:int, "sys":str, "_tables":str, "type":str, 2:int);                |
|     C_90:bat[:oid] := algebra.thetaselect(X_22:bat[:sht], nil:bat[:oid], 2:sht, "!=":str);                             |
|     X_20:bat[:sht] := sql.bind(X_4:int, "sys":str, "_tables":str, "type":str, 1:int);                                  |
|     C_92:bat[:oid] := algebra.thetaselect(X_20:bat[:sht], C_5:bat[:oid], 2:sht, "!=":str);                             |
|     C_27:bat[:oid] := sql.subdelta(C_89:bat[:oid], C_5:bat[:oid], X_21:bat[:oid], C_90:bat[:oid], C_92:bat[:oid]);     |
|     X_8:bat[:int] := sql.bind(X_4:int, "sys":str, "_tables":str, "id":str, 0:int);                                     |
|     (X_13:bat[:oid], X_14:bat[:int]) := sql.bind(X_4:int, "sys":str, "_tables":str, "id":str, 2:int);                  |
|     X_11:bat[:int] := sql.bind(X_4:int, "sys":str, "_tables":str, "id":str, 1:int);                                    |
|     X_29:bat[:int] := sql.projectdelta(C_27:bat[:oid], X_8:bat[:int], X_13:bat[:oid], X_14:bat[:int], X_11:bat[:int]); |
|     X_31:lng := aggr.count(X_29:bat[:int]);                                                                            |
|     X_37:bat[:lng] := sql.single(X_31:lng);                                                                            |
|     C_32:bat[:oid] := sql.tid(X_4:int, "tmp":str, "_tables":str);                                                      |
|     X_34:bat[:int] := sql.bind(X_4:int, "tmp":str, "_tables":str, "id":str, 0:int);                                    |
|     X_35:bat[:int] := algebra.projection(C_32:bat[:oid], X_34:bat[:int]);                                              |
|     X_36:lng := aggr.count(X_35:bat[:int]);                                                                            |
|     X_40:bat[:lng] := bat.append(X_38:bat[:lng], X_37:bat[:lng], true:bit);                                            |
|     X_42:bat[:lng] := bat.append(X_40:bat[:lng], X_36:lng, true:bit);                                                  |
|     X_43:lng := aggr.sum(X_42:bat[:lng]);                                                                              |
|     language.pass(C_5:bat[:oid]);                                                                                      |
| exit X_104:bit;                                                                                                        |
|     sql.resultSet(".L41":str, "L41":str, "bigint":str, 64:int, 0:int, 7:int, X_43:lng);                                |
| end user.s6_1;                                                                                                         |
...
+------------------------------------------------------------------------------------------------------------------------+
55 tuples
clk: 3.942 ms

 

The SQL compiler maintains a cache of compiled (or prepared) queries. Each query is looked up in this cache based on an expression pattern match where the constants may take on different values. If it doesn't exist, the query is converted into a code block and stored in the module user.s0.

The call to the cached function is included in a wrapper function main, which is the only piece of code produced if the query is used more than once. The query cache disappears when the server is brought to a halt.

     +----------------------------+
     | function user.main():void; |
     |     mdb.start();           |
     |     user.s3_2();           |
     |     mdb.stop();            |
     | end main;                  |
     +----------------------------+

TRACE SQL STMT

TRACE SQL STMT mk Sun, 03/28/2010 - 23:27

A performance trace can be obtained using the TRACE statement modifier. It collects all the trace information in a table reproduced by tracelog(), which can be queried using ordinary SQL statements. The internal trace table is reset at each query being traced. Its definition is given below:

create function sys.tracelog()
    returns table (
        event integer,      -- event counter
        clk varchar(20),    -- wallclock, no mtime in kernel
        pc varchar(50),     -- module.function[nr]
        thread int,         -- thread identifier
        ticks bigint,       -- time in microseconds
        rrsMB bigint,       -- resident memory in MB
        vmMB bigint,        -- virtual size in MB
        reads bigint,       -- number of blocks read
        writes bigint,      -- number of blocks written
        minflt bigint,      -- minor page faults
        majflt bigint,      -- major page faults
        nvcsw bigint,       -- non-volantary context switch
        stmt string         -- actual statement executed
    )
    external name sql.dump_trace;

  Field Description Example
1 event An event counter 38
2 clk The wall-clock time in microseconds "13:11:16.710180",
3 pc Name of the query execution plan name; followed by the program counter in the execution plan (denoted in the square brackets ‘[‘ and ‘]’) indicating the position of the MAL instruction in its defining block; and finally a unique call identifier to distinguish recursion. "user.s5_1[14]12",
4 thread Id of the worker thread processing this MAL instruction. 3
5 usec The actual execution time (at "done") for the MAL instruction, measured in microseconds 207,
6 rssMB Memory Resident Set Size (RSS), i.e., the portion of memory occupied by a process that is held in main memory, in MB. 54
7 vmMB Estimated cumulative query plan footprint, in MB. For a query, the maximal value of “tmpspace” gives a fairly good estimation of the memory consumption of this query. 0,
8 reads The number of disk blocks read ** 0,
9 writes The number of disk blocks written ** 0,
10 majflt The number of major page faults 0,
11 switch The number of context switches 0,
12 stmt The MAL statement being executed, with argument statistics "sql.exportResult(X_21=\"104d2\":streams,X_16=4:int);”

 

* In addition, the “state” field denotes two special events. The “wait” event is received when the worker threads cannot find an eligible MAL instruction and have to wait for other worker threads to deliver results. The “ping” event provides a synopsis of the CPU processing loads.

** Please be aware that these values reflect system wide activities, thus they include not only MonetDB activities. Additionally, these I/O counts do not reflect the actual amount of data read/written from/to the hardware drives, as this information is generally not available to all users of a Linux system.

DEBUG SQL STMT

DEBUG SQL STMT mk Sun, 03/28/2010 - 23:26

The SQL statements are translated into MAL programs, which are optimized and stored away in an user module. The generated code can be inspected with the MAL debugger.

The example below illustrates the start of such a session:

>debug select count(*) from tables;
#    mdb.start()
mdb>next
#    user.s1_0()
mdb>next
#    _2:bat[:oid,:int]  := sql.bind(_3="sys", _4="ptables", _5="id", _6=0)
mdb>next
#    _8:bat[:oid,:int]  := sql.bind(_3="sys", _4="ptables", _5="id", _9=1)
mdb> ...
mdb>help
next             -- Advance to next statement
continue         -- Continue program being debugged
catch            -- Catch the next exception 
break [<var>]    -- set breakpoint on current instruction or <var>
delete [<var>]   -- remove break/trace point <var>
debug <int>      -- set kernel debugging mask
dot <obj> [<file>]     -- generate the dependency graph for MAL block
step             -- advance to next MAL instruction
module           -- display the module signatures
atom             -- show atom list
finish           -- finish current call
exit             -- terminate execution
quit             -- turn off debugging
list <obj>       -- list a MAL program block
list #  [+#],-#  -- list current program block slice
List <obj> [#]   -- list MAL block with type information[slice]
list '['<step>']'  -- list program block after optimizer step
List #[+#],-#    -- list current program block slice
var  <obj>       -- print symbol table for module
optimizer <obj>  -- display optimizer steps
print <var>      -- display value of a variable
print <var> <cnt>[<first>]   -- display BAT chunk
info <var>       -- display bat variable properties
run              -- restart current procedure
where            -- print stack trace
down             -- go down the stack
up               -- go up the stack
trace <var>      -- trace assignment to variables
help             -- this message

PLAN SQL STMT

PLAN SQL STMT mk Fri, 12/26/2014 - 13:59

The relational plan used in the SQL optimizer can be obtained by prepending the query with the keyword PLAN.

sql>plan select count(*) from tables;
+----------------------------------------------------------------------------+
| rel                                                                        |
+============================================================================+
| project (                                                                  |
| | group by (                                                               |
| | | union (                                                                |
| | | | group by (                                                           |
| | | | | project (                                                          |
| | | | | | select (                                                         |
| | | | | | | table(sys._tables) [ "_tables"."id", "_tables"."type" ] COUNT  |
| | | | | | ) [ "_tables"."type" != smallint "2" ]                           |
| | | | | ) [ "_tables"."id" as "tables"."id" ]                              |
| | | | ) [  ] [ sys.count() NOT NULL as "L41"."L41" ],                      |
| | | | group by (                                                           |
| | | | | project (                                                          |
| | | | | | table(tmp._tables) [ "_tables"."id" ] COUNT                      |
| | | | | ) [ "_tables"."id" as "tables"."id" ]                              |
| | | | ) [  ] [ sys.count() NOT NULL as "L41"."L41" ]                       |
| | | ) [ "L41"."L41" ]                                                      |
| | ) [  ] [ sys.sum no nil ("L41"."L41") as "L41"."L41" ]                   |
| ) [ "L41"."L41" NOT NULL ]                                                 |
+----------------------------------------------------------------------------+
18 tuples
clk: 1.158 ms

PREPARE SQL STMT

PREPARE SQL STMT mk Sun, 10/13/2013 - 16:33

The PREPARE statement compiles an SQL statement into its execution plan. The plan is given a name and stored in the query cache. A subsequent EXECUTE command retrieves it from the cache and executes it.

PREPARE statement executions can be given positional arguments to replace any literal constant in the query.  Each argument is denoted with a '?'.

sql>prepare select * from tables where name = ?;
execute prepared statement using: EXEC 15(...)
clk: 4.123 ms
+----------+---------+-------+--------+--------+---------------+
| type     | digits  | scale | schema | table  | column        |
+==========+=========+=======+========+========+===============+
| int      |      32 |     0 |        | tables | id            |
| varchar  |    1024 |     0 |        | tables | name          |
| int      |      32 |     0 |        | tables | schema_id     |
| varchar  |    2048 |     0 |        | tables | query         |
| smallint |      16 |     0 |        | tables | type          |
| boolean  |       1 |     0 |        | tables | system        |
| smallint |      16 |     0 |        | tables | commit_action |
| smallint |      16 |     0 |        | tables | access        |
| tinyint  |       8 |     0 |        | tables | temporary     |
| varchar  |    1024 |     0 | null   | null   | null          |
+----------+---------+-------+--------+--------+---------------+
10 tuples
clk: 4.123 ms

sql>exec 15('_tables');
+------+---------+-----------+-------+------+--------+---------------+--------+-----------+
| id   | name    | schema_id | query | type | system | commit_action | access | temporary |
+======+=========+===========+=======+======+========+===============+========+===========+
| 2067 | _tables |      2000 | null  |   10 | true   |             0 |      0 |         0 |
| 2115 | _tables |      2114 | null  |   10 | true   |             2 |      0 |         0 |
+------+---------+-----------+-------+------+--------+---------------+--------+-----------+
2 tuples
clk: 2.692 ms

sql>exec 15('table_types');
+------+-------------+-----------+-------+------+--------+---------------+--------+-----------+
| id   | name        | schema_id | query | type | system | commit_action | access | temporary |
+======+=============+===========+=======+======+========+===============+========+===========+
| 7322 | table_types |      2000 | null  |   10 | true   |             0 |      1 |         0 |
+------+-------------+-----------+-------+------+--------+---------------+--------+-----------+
1 tuple
clk: 2.364 ms