Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timestamp arithmetic very slow (especially on Windows) #3084

Closed
monetdb-team opened this issue Nov 30, 2020 · 0 comments
Closed

Timestamp arithmetic very slow (especially on Windows) #3084

monetdb-team opened this issue Nov 30, 2020 · 0 comments

Comments

@monetdb-team
Copy link

@monetdb-team monetdb-team commented Nov 30, 2020

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
1 participant