SQL Timing

Timing a query execution is supported in multiple ways, but largely depends on what you want to measure. Point-to-point wall clock time, or the actual behaviour of kernel operations.

1. The baseline is to use simple command line tools, such at time on Linux to assess the performance of running a script against mclient. Beware that /bin/time and /usr/bin/time are not the same, they mainly measure and report the wall-clock time spent by the given command/process. See their respective man pages for details.

2. The next approach is to use the --interactive option of the mclient tool, which will report on the timing of each individual SQL query in a script in easy human consumable terms. It returns the wall-clock time between sending the query to the server and receiving the first block of answers.

3. The query history can also be maintained in a separate log for post analysis. (see below)

Thus, (1) includes everything from loading the mclient binary and starting the mclient process, parsing the query in mclient, sending to the server, having the server execute the query and serialise the result, sending the result back to the client, to the client receiving, parsing and rendering the result, and sending the result to /dev/null ("for free"), to a file (I/O), or to a terminal (scrolling). (2) merely includes the time the server spends on receiving and executing the query and creating the result. The above-mentioned costs on the client side to receive, parse, render, etc. The result are excluded. The same holds for (3).

A detailed time of an SQL query can be obtained with prepending the query with the modifier TRACE. It will produce a queryable table called sys.tracelog with a break down of all relational algebra operations (see TRACE command).

Timing a database query should be done with care. Often you will notice differences in response time for the same query ran multiple times. The underlying cause can be that the data itself resides on disk (slow) or is already available in the memory caches (fast), a single user runs queries (fast) or has to compete with other users (slow), including competing with other processes on your box fighting over cpu, memory, and IO resources. As a precaution you might want to flush the system caches. The Windows tool flushes the cache. You'll need to press the "Flush Cache WS" and "Flush All Standby" buttons. On Linux you have to create a little job that consumes all memory.

Query History

The SQL implementation comes with a simple query profiler to detect expensive queries. It is centered around two predefined internal tables (sys.querylog_catalog)[./sql-catalog/querylog-calls-history-queue/#sysquerylog_catalog] and (sys.querylog_calls)[./sql-catalog/querylog-calls-history-queue/#sysquerylog_calls] that store information on all executed SQL queries and their execution time.

These querylog tables are initially empty when you startup a MonetDB server. For logging SQL queries you will need to enable query logging first.

Query Log procedures

Query logging is started by calling the procedure sys.querylog_enable() or sys.querylog_enable(threshold_in_ms). When the query log is enabled with a threshold_in_ms parameter value (the number of milliseconds), it will only log those queries whose execution times are higher than the threshold value. This feature is usefull to prevent the database from being swarmed by too many short running queries, hence reduce the overhead incurred by the query log (see below), while helping the DBA detecting expensive queries.

Disabling the query log will not remove existing query logs; it only prevents subsequent queries to be logged.

Once the query log is re-enabled, information of subsequently executed queries will be appended to the existing query log tables.

To discard query log data call procedure sys.querylog_empty().

The queries are stored in the table sys.querylog_catalog. It contains following columns:

The owner of the query definition is also the one who is referenced implicitly by the id of a call event.

The query execution times are stored in the table sys.querylog_calls. It contains following columns:

The key timing attributes are run, i.e. the time to execute the query to produce the result set,
and ship, i.e. the time to render the result set and send it to the client. All times are in microseconds.

The remaining parameters illustrate resource claims.
The tuples attribute denotes the size of the result set in the number of rows.
The cpu load is derived from the operating system statistics (Linux only) and is given as a percentage.
The same holds for the io waiting time.

The utility system view (sys.querylog_history)[./sql-catalog/querylog-calls-history-queue/#sysquerylog_catalog] combines the information from sys.querylog_catalog and sys.querylog_calls but filters on listing only those queries issued by the current user, so where querylog_catalog."owner" = user.

Note as of release Dec2025 (11.55) the query log tables are longer stored in persistent tables, ie they will be empty after a MonetDB server restart. If you want to keep the query log data, make a copy into an SQL table.

Query Log examples

-- inspect query log views, initially they are all empty, so return no rows.
select * from sys.querylog_catalog;

select * from sys.querylog_calls;

select * from sys.querylog_history;

-- enable query logging
call sys.querylog_enable();

-- run some queries
select count(*) from sys.columns where name like '%a%';

-- disable query logging
call sys.querylog_disable();

-- inspect query log tables
select * from sys.querylog_catalog;

select stop - start as duration, qlc.* from sys.querylog_calls qlc;
-- note: the computed duration column is of type 'interval second(3)' and does not include the micro-seconds precision part

-- use next query to also compute the micro-seconds part
select stop - start as duration_milli_secs, "second"(stop) - "second"(start) as micro_secs_part, qlc.* from sys.querylog_calls qlc;

select stop - start as duration, qlh.* from sys.querylog_history qlh;

-- empty query log tables
call sys.querylog_empty();

-- enable query logging but with a threshold of 1000 ms (is 1 second)
call sys.querylog_enable(1000);

-- run some queries
select count(*) from sys.columns where name like '%a%';

-- inspect querylog_catalog, but newest shown first
select * from sys.querylog_catalog order by -id;

-- inspect querylog_calls, but slowest shown first
select stop - start as duration, qlc.* from sys.querylog_calls qlc order by duration desc;

-- inspect querylog_history, but slowest shown first
select stop - start as duration, qlh.* from sys.querylog_history qlh order by duration desc;

-- note that the querylog_* queries are also logged in sys.querylog_catalog table
-- but they do not (yet) become visble in views: querylog_calls and querylog_history
-- when we disable query logging they will become visible provided they took more than 1 second

-- disable query logging
call sys.querylog_disable();

-- inspect querylog_catalog, but newest shown first
select * from sys.querylog_catalog order by -id;

-- inspect querylog_calls, but slowest shown first
select stop - start as duration, qlc.* from sys.querylog_calls qlc order by duration desc;

-- inspect querylog_history, but slowest shown first
select stop - start as duration, qlh.* from sys.querylog_history qlh order by duration desc;

-- empty query log tables
call sys.querylog_empty();