Date: 2012-05-22 22:48:11 +0200
From: Richard Hughes <>
To: GDK devs <>
Version: 11.11.5 (Jul2012)

Last updated: 2013-02-19 13:17:59 +0100

Comment 17275

Date: 2012-05-22 22:48:11 +0200
From: Richard Hughes <>

User-Agent: Opera/9.80 (Windows NT 6.1; WOW64; U; en) Presto/2.10.229 Version/11.64
Build Identifier: v11.9.1 "Apr2012" amd64

Queries which rely on performing certain mathematical operations on timestamps run significantly slower than they could because of a lot of time spent locking and unlocking mutexes. The problem is compounded on Windows because pthread_mutex_lock() and pthread_mutex_unlock() are implemented using WaitForSingleObject() and ReleaseMutex(), which both involve a user<->kernel transition. The operations I have observed to have this problem so far are subtraction of two timestamps and extract(hour from ts).

Reproducible: Always

Steps to Reproduce:

1. Create a file with 10000 lines of timestamps in it, all the same
2. create table times (t timestamp);
3. copy 10000 records into times from 'times.txt';
4. select count(*) from times A,times B where A.t-B.t<>0;

Actual Results:

The select query takes 428s to complete (on a Sandy Bridge @ 3.4GHz).

Expected Results:

The identical query "select count(*) from times A,times B where A.t<>B.t;" takes 910ms to complete.

System timing says that mserver5 spends 74% of its time in kernel mode when executing that slow query. Stack trace of a random mutex lock mid-query:

libbat!pthread_mutex_lock [gdk\gdk_system.c @ 295]
libbat!incref+0x109 [gdk\gdk_bbp.mx @ 2237]
libmonetdb5!BATdescriptor+0x66 [gdk\gdk.h @ 2507]
libmonetdb5!BKCinsert_bun+0x1e [monetdb5\modules\kernel\bat5.mx @ 1463]
libmonetdb5!runMALsequence+0x8c93 [monetdb5\mal\mal_interpreter.mx @ 1967]
libmonetdb5!callMAL+0x16b [monetdb5\mal\mal_interpreter.mx @ 2591]
lib_sql!SQLexecutePrepared+0x20b [sql\backends\monet5\sql_scenario.c @ 1642]
lib_sql!SQLengineIntern+0xb6 [sql\backends\monet5\sql_scenario.c @ 1695]
libmonetdb5!runScenarioBody+0x21e [monetdb5\mal\mal_scenario.c @ 574]
libmonetdb5!runScenario+0x22 [monetdb5\mal\mal_scenario.c @ 601]
libmonetdb5!MSserveClient+0xe0 [monetdb5\mal\mal_session.c @ 439]
libbat!thread_starter+0x10 [gdk\gdk_system.c @ 172]
kernel32!BaseThreadInitThunk+0xd
ntdll!RtlUserThreadStart+0x1d

FYI, the query above is obviously an artificial test-case for this bug report. The actual query I was doing was select * from bigtable where endtime-starttime>20000;

sql>explain select count(*) from times A,times B where A.t<>B.t;
+----------------------------------------------------------------------+
| mal |
+======================================================================+
| function user.s28_1{autoCommit=true}():void; |
| X_23 := nil:wrd; |
| barrier X_46 := language.dataflow(); |
| X_2 := sql.mvc(); |
| X_10:bat[:oid,:timestamp] := sql.bind(X_2,"sys","times","t",0); |
| X_8:bat[:oid,:timestamp] := sql.bind(X_2,"sys","times","t",2); |
| X_12 := algebra.kdifference(X_10,X_8); |
| X_13 := algebra.kunion(X_12,X_8); |
| X_4:bat[:oid,:timestamp] := sql.bind(X_2,"sys","times","t",1); |
| X_14 := algebra.kunion(X_13,X_4); |
| X_15:bat[:oid,:oid] := sql.bind_dbat(X_2,"sys","times",1); |
| X_16 := bat.reverse(X_15); |
| X_17 := algebra.kdifference(X_14,X_16); |
| X_18 := bat.reverse(X_17); |
| X_19 := algebra.antijoin(X_17,X_18); |
| X_20 := algebra.markT(X_19,0@0:oid); |
| X_21 := bat.reverse(X_20); |
| X_22 := algebra.leftjoin(X_21,X_14); |
| X_23 := aggr.count(X_22); |
| exit X_46; |
| sql.exportValue(1,"sys.a","L1":str,"wrd",64,0,6,X_23,""); |
| end s28_1; |
+----------------------------------------------------------------------+

sql>explain select count(*) from times A,times B where A.t-B.t<>0;
+----------------------------------------------------------------------+
| mal |
+======================================================================+
| function user.s29_1{autoCommit=true}(A0:lng):void; |
| X_27 := nil:bat[:oid,:timestamp]; |
| X_31:bat[:oid,:timestamp] := nil:bat[:oid,:timestamp]; |
| barrier X_62 := language.dataflow(); |
| X_3 := sql.mvc(); |
| X_11:bat[:oid,:timestamp] := sql.bind(X_3,"sys","times","t",0); |
| X_9:bat[:oid,:timestamp] := sql.bind(X_3,"sys","times","t",2); |
| X_13 := algebra.kdifference(X_11,X_9); |
| X_14 := algebra.kunion(X_13,X_9); |
| X_5:bat[:oid,:timestamp] := sql.bind(X_3,"sys","times","t",1); |
| X_15 := algebra.kunion(X_14,X_5); |
| X_16:bat[:oid,:oid] := sql.bind_dbat(X_3,"sys","times",1); |
| X_17 := bat.reverse(X_16); |
| X_18 := algebra.kdifference(X_15,X_17); |
| X_23 := algebra.project(X_18,0:int); |
| X_19 := bat.reverse(X_18); |
| X_20 := bat.reverse(X_19); |
| X_21 := algebra.project(X_20,0:int); |
| X_22 := bat.reverse(X_21); |
| X_24 := algebra.join(X_23,X_22); |
| X_25 := algebra.markT(X_24,0@0:oid); |
| X_26 := bat.reverse(X_25); |
| X_27 := algebra.leftjoin(X_26,X_15); |
| X_28 := bat.reverse(X_24); |
| X_29 := algebra.markT(X_28,0@0:oid); |
| X_30 := bat.reverse(X_29); |
| X_31:bat[:oid,:timestamp] := algebra.leftjoin(X_30,X_15); |
| exit X_62; |
| X_70 := bat.new(nil:oid,nil:lng); |
| barrier (X_73,X_74,X_75) := bat.newIterator(X_27); |
| X_77 := algebra.find(X_31,X_74); |
| X_79 := mtime.diff(X_75,X_77); |
| bat.insert(X_70,X_74,X_79); |
| redo (X_73,X_74,X_75) := bat.hasMoreElements(X_27); |
| exit (X_73,X_74,X_75); |
| X_31:bat[:oid,:timestamp] := nil:bat[:oid,:timestamp]; |
| X_32:bat[:oid,:lng] := X_70; |
| X_35 := algebra.antiuselect(X_32,A0); |
| X_36 := algebra.markT(X_35,0@0:oid); |
| X_37 := bat.reverse(X_36); |
| X_38 := algebra.leftjoin(X_37,X_27); |
| X_39 := aggr.count(X_38); |
| sql.exportValue(1,"sys.a","L1":str,"wrd",64,0:int,6,X_39,""); |
| end s29_1; |
+----------------------------------------------------------------------+

Comment 17276

Date: 2012-05-22 23:10:56 +0200
From: @sjoerdmullender

I guess we need a bulk version of mtime.diff.

Comment 17704

Date: 2012-08-27 11:19:25 +0200
From: @sjoerdmullender

Changeset 536a859ef7d7 made by Sjoerd Mullender sjoerd@acm.org in the MonetDB repo, refers to this bug.

For complete details, see http//devmonetdborg/hg/MonetDB?cmd=changeset;node=536a859ef7d7

Changeset description:

Implemented bulk versions of mtime.diff.
This should fix bug #3084.

Comment 17705

Date: 2012-08-27 11:22:23 +0200
From: @sjoerdmullender

I implemented bulk versions of mtime.diff which should solve the problem. The implementation will be in the next feature release (probably October).

Comment 18514

Date: 2013-02-19 13:17:59 +0100
From: @sjoerdmullender

Feb2013 has been released.