3.2.4 Query History

The SQL implementation comes with a simple query profiler to detect expensive queries. It is centered around two predefined tables that stores information about all SQL queries definitions and their execution time.

The history table is controlled by the boolean system variable 'history', which relies on the execution of the 'history.sql' script once. Whenever a query is compiled and added to the cache, it is also entered into the 'queryHistory' table using a hardwired call to 'keepQuery'.

create table queryHistory(
    id wrd primary key,
    defined timestamp,  -- when entered into the cache
    name string,        -- database user name
    query string,
    parse bigint,       -- time in usec
    optimize bigint     -- time in usec
);

The query performance is stored in the 'callHistory tabe. The key timing attributes are 'xtime' and 'rtime'. Together they form the total elapsed time of running the query within the database engine. The 'xtime' denotes the time taken to prepare for the result set, while 'rtime' covers the time to contruct and sent the result set to the user. All timing in usec.

The remainging parameters illustrate the resource claims. The 'tuples' attribute denotes the size of the result set in number of rows. The 'foot'-print depicts the maximum amount of memory used to keep all relevant intermediates and persistent bats in memory at any given time during query execution. The 'memory' parameter is total amount of BAT storage claimed during query execution. All storage in K/M/G bytes. The 'inblock' and 'oublock' indicate the physical IOs during.

create table callHistory(
    id wrd references queryHistory(id), -- references query plan
    ctime timestamp,    -- time the first statement was executed
    arguments string,
    xtime bigint,       -- time from the first statement until result export
    rtime bigint,       -- time to ship the result to the client
    foot bigint,        -- footprint for all bats in the plan
    memory bigint,      -- storage size of intermediates created
    tuples wrd,         -- number of tuples in the result set
    inblock bigint,     -- number of physical blocks read
    oublock bigint      -- number of physical blocks written
);

create view queryLog as
select * from queryHistory qd, callHistory ql
where qd.id= ql.id;

In the example below, we assume that this script has been ran already.

sql> set history=true;
0 tuples
sql> select 1;
+--------------+
| single_value |
+==============+
|            1 |
+--------------+
Rows affected 1
sql> select 1;
....
sql> select * from queryHistory;
+---------+--------------------+---------+--------------------+-------+-------+
| id      | defined            | name    | query              | parse | optim |
:         :                    :         :                    :       : ize   :
+=========+====================+=========+====================+=======+=======+
| 1002344 | 2008-11-07         | monetdb | select 1;          |  1522 |   112 |
:         : 06:50:46.000000    :         :                    :       :       :
| 1002468 | 2008-11-07         | monetdb | select * from      |   297 |   605 |
:         : 06:50:54.000000    :         : queryhistory;      :       :       :
+---------+--------------------+---------+--------------------+-------+-------+
2 tuples
Rows affected 1
sql> select * from callHistory;
+------+-------+-------+-------+-------+------+-------+-------+-------+-------+
| id   | ctime | argum | xtime | rtime | foot | memor | tuple | inblo | oublo |
:      :       : ents  :       :       :      : y     : s     : ck    : ck    :
+======+=======+=======+=======+=======+======+=======+=======+=======+=======+
| 1002 | 2008- | user. |     1 |     5 |    0 |     0 |     1 |     0 |     0 |
:  344 : 11-07 : s2_1( :       :       :      :       :       :       :       :
:      : 06:50 : 1);   :       :       :      :       :       :       :       :
:      : :46.0 :       :       :       :      :       :       :       :       :
:      : 00000 :       :       :       :      :       :       :       :       :
| 1002 | 2008- | user. |     0 |     7 |   67 |    67 |     1 |     0 |     0 |
:  344 : 11-07 : s2_1( :       :       :      :       :       :       :       :
:      : 06:50 : 1);   :       :       :      :       :       :       :       :
:      : :46.0 :       :       :       :      :       :       :       :       :
:      : 00000 :       :       :       :      :       :       :       :       :
| 1002 | 2008- | user. |     0 |     7 |   59 |    59 |     1 |     0 |     0 |
:  344 : 11-07 : s2_1( :       :       :      :       :       :       :       :
:      : 06:50 : 1);   :       :       :      :       :       :       :       :
:      : :47.0 :       :       :       :      :       :       :       :       :
:      : 00000 :       :       :       :      :       :       :       :       :
| 1002 | 2008- | user. |   435 |    56 |  152 |   355 |     2 |     0 |     0 |
:  468 : 11-07 : s3_1( :       :       :      :       :       :       :       :
:      : 06:50 : );    :       :       :      :       :       :       :       :
:      : :54.0 :       :       :       :      :       :       :       :       :
:      : 00000 :       :       :       :      :       :       :       :       :
+------+-------+-------+-------+-------+------+-------+-------+-------+-------+
4 tuples
sql> select id , avg(xtime) from queryLog group by id;
+---------+------------------------+
| id      | avg_xtime              |
+=========+========================+
| 1002344 |    0.33333333333333331 |
| 1002468 |                    435 |
| 1002581 |                    939 |
+---------+------------------------+
3 tuples

QueryHistory and callHistory are ordinary tables, which can be cleaned using tuple deletion. The update procedures can be refined to filter events to be retained.