I can also reproduce this on 11.7.3 (dec2011) today. My question is, is this normal, and why? from iostat: Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.00 70.50 0.00 1452.00 0.00 22466.00 30.94 141.85 95.63 0.00 95.63 0.69 100.00 zack_pcd wrote:
The new version is much faster than before, the query takes 11 minutes to run (consistently so). However, I noticed that CPU usage was almost zero and most of the activity was disk writes still.
Counts:
sql>select count(distinct machine_uuid) from f_trigger; +---------+ | L12 | +=========+ | 5293197 | +---------+ 1 tuple (10.7s)
sql>select count(distinct script_id) from f_trigger; +------+ | L13 | +======+ | 208 | +------+ 1 tuple (365.408ms)
Query speed on dec2011 (fairly consistent):
sql>select script_id,count(distinct machine_uuid) from f_trigger group by script_id; ... 208 tuples (11m 10s)
sql>explain select script_id,count(distinct machine_uuid) from f_trigger group by script_id; +-------------------------------------------------------------------------------+ | mal | +===============================================================================+ | function user.s10_1{autoCommit=true}():void; | | X_11 := nil:bat[:oid,:str]; | | X_20:bat[:oid,:wrd] := nil:bat[:oid,:wrd]; | | barrier X_256 := language.dataflow(); | | X_2 := sql.mvc(); | | X_5:bat[:oid,:str] := sql.bind(X_2,"sys","f_trigger","script_id",0); | | (ext18,grp16) := group.done(X_5); | | X_10 := bat.mirror(ext18); | | X_11 := algebra.join(X_10,X_5); | | X_14:bat[:oid,:str] := sql.bind(X_2,"sys","f_trigger","machine_uuid",0); | | X_15 := algebra.selectNotNil(X_14); | | (X_16,grp33) := group.derive(ext18,grp16,X_15); | | X_18 := bat.mirror(X_16); | | X_19 := algebra.join(X_18,X_15); | | X_20:bat[:oid,:wrd] := aggr.count(X_19,grp16,X_10); | | exit X_256; | | X_21 := sql.resultSet(2,1,X_11); | | sql.rsColumn(X_21,"sys.f_trigger","script_id","varchar",32768,0,X_11); | | sql.rsColumn(X_21,"sys.f_trigger","L17","wrd",64,0,X_20); | | X_33 := io.stdout(); | | sql.exportResult(X_33,X_21); | | end s10_1; | +-------------------------------------------------------------------------------+ 22 tuples (1.352ms)
Stethoscope +rwpof output:
[1] # function, pc, operation, blk reads, blk writes, pg reclaim, pg faults, swaps, ctxt switch, inv switch, # name [1] [ "user.s11_1", 1, ":=", 2501160, 54445344, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 2, ":=", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 4, "sql.mvc", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 5, "sql.bind", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 9, "sql.bind", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 10, "algebra.selectNotNil", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 6, "group.done", 0, 2585824, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 7, "bat.mirror", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 8, "algebra.join", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 11, "group.derive", 0, 24246520, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 12, "bat.mirror", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 13, "algebra.join", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 14, "aggr.count", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 3, "language.dataflow", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 16, "sql.resultSet", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 17, "sql.rsColumn", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 18, "sql.rsColumn", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 19, "io.stdout", 0, 0, 0, 0, 0, 0, 0, ] [1] [ "user.s11_1", 20, "sql.exportResult", 0, 0, 0, 0, 0, 0, 0, ]
Most of the time was spent here: [1] [ "user.s11_1", 11, "group.derive", 0, 24246520, 0, 0, 0, 0, 0, ]
Using default stethoscope settings this step looks like: [1] [ 39, "done", "09:43:28.701994", 17, 1266986588, "(X_16=
[90715083],grp33) := group.derive(ext18=nil,grp16= [165492393],X_15= [165492393]);", ] Full default stethoscope output: [1] # event, status, time, thread, usec, stmt, # name [1] [ 19, "start", "09:43:24.240496", 2, 0, "X_11 := nil:bat[:oid,:str];", ] [1] [ 20, "done", "09:43:24.240496", 2, 114, "X_11 := nil:bat[:oid,:str];", ] [1] [ 21, "start", "09:43:24.240629", 2, 0, "X_20:bat[:oid,:wrd] := nil:bat[:oid,:wrd];", ] [1] [ 22, "done", "09:43:24.240629", 2, 18, "X_20:bat[:oid,:wrd] := nil:bat[:oid,:wrd];", ] [1] [ 23, "start", "09:43:24.240662", 2, 0, "barrier X_256 := language.dataflow();", ] [1] [ 24, "start", "09:43:24.240742", 17, 0, "X_2 := sql.mvc();", ] [1] [ 25, "done", "09:43:24.240742", 17, 92, "X_2 := sql.mvc();", ] [1] [ 26, "start", "09:43:24.240860", 17, 0, "X_5:bat[:oid,:str] := sql.bind(X_2=0,\"sys\",\"f_trigger\",\"script_id\",0);", ] [1] [ 27, "start", "09:43:24.240917", 8, 0, "X_14:bat[:oid,:str] := sql.bind(X_2=0,\"sys\",\"f_trigger\",\"machine_uuid\",0);", ] [1] [ 28, "done", "09:43:24.240860", 17, 63, "X_5:bat[:oid,:str] =
[165492393] := sql.bind(X_2=0,\"sys\",\"f_trigger\",\"script_id\",0);", ] [1] [ 29, "done", "09:43:24.240917", 8, 136, "X_14:bat[:oid,:str] = [165492393] := sql.bind(X_2=0,\"sys\",\"f_trigger\",\"machine_uuid\",0);", ] [1] [ 30, "start", "09:43:24.241090", 17, 0, "(ext18,grp16) := group.done(X_5= :bat[:oid,:str][165492393]);", ] [1] [ 31, "start", "09:43:24.241158", 8, 0, "X_15 := algebra.selectNotNil(X_14= :bat[:oid,:str][165492393]);", ] [1] [ 32, "done", "09:43:24.241158", 8, 28, "X_15= [165492393] := algebra.selectNotNil(X_14=nil:bat[:oid,:str]);", ] [1] [ 33, "done", "09:43:24.241090", 17, 4460657, "(ext18= [208],grp16= [165492393]) := group.done(X_5= :bat[:oid,:str][165492393]);", ] [1] [ 34, "start", "09:43:28.701926", 17, 0, "X_10 := bat.mirror(ext18= [208]);", ] [1] [ 35, "done", "09:43:28.701926", 17, 41, "X_10= [208] := bat.mirror(ext18= [208]);", ] [1] [ 36, "start", "09:43:28.701994", 17, 0, "(X_16,grp33) := group.derive(ext18= [208],grp16= [165492393],X_15= [165492393]);", ] [1] [ 37, "start", "09:43:28.702084", 34, 0, "X_11 := algebra.join(X_10= [208],X_5= :bat[:oid,:str][165492393]);", ] [1] [ 38, "done", "09:43:28.702084", 34, 525, "X_11= [208] := algebra.join(X_10= [208],X_5=nil:bat[:oid,:str]);", ] [1] [ 39, "done", "09:43:28.701994", 17, 1266986588, "(X_16= [90715083],grp33) := group.derive(ext18=nil,grp16= [165492393],X_15= [165492393]);", ] [1] [ 40, "start", "10:04:35.688738", 17, 0, "X_18 := bat.mirror(X_16= [90715083]);", ] [1] [ 41, "done", "10:04:35.688738", 17, 48, "X_18= [90715083] := bat.mirror(X_16=nil);", ] [1] [ 42, "start", "10:04:35.688813", 17, 0, "X_19 := algebra.join(X_18= [90715083],X_15= [165492393]);", ] [1] [ 43, "done", "10:04:35.688813", 17, 1885923, "X_19= [90715083] := algebra.join(X_18=nil,X_15=nil);", ] [1] [ 44, "start", "10:04:37.574908", 17, 0, "X_20:bat[:oid,:wrd] := aggr.count(X_19= [90715083],grp16= [165492393],X_10= [208]);", ] [1] [ 45, "done", "10:04:37.574908", 17, 2557404, "X_20:bat[:oid,:wrd] = [208] := aggr.count(X_19=nil,grp16=nil,X_10=nil);", ] [1] [ 46, "done", "09:43:24.240662", 2, 1275891844, "barrier X_256 := language.dataflow();", ] [1] [ 47, "start", "10:04:40.132654", 2, 0, "X_21 := sql.resultSet(2,1,X_11= [208]);", ] [1] [ 48, "done", "10:04:40.132654", 2, 46, "X_21 := sql.resultSet(2,1,X_11= [208]);", ] [1] [ 49, "start", "10:04:40.132718", 2, 0, "sql.rsColumn(X_21=4,\"sys.f_trigger\",\"script_id\",\"varchar\",32768,0,X_11= [208]);", ] [1] [ 50, "done", "10:04:40.132718", 2, 41, "sql.rsColumn(X_21=4,\"sys.f_trigger\",\"script_id\",\"varchar\",32768,0,X_11=nil);", ] [1] [ 51, "start", "10:04:40.132781", 2, 0, "sql.rsColumn(X_21=4,\"sys.f_trigger\",\"L21\",\"wrd\",64,0,X_20= :bat[:oid,:wrd][208]);", ] [1] [ 52, "done", "10:04:40.132781", 2, 34, "sql.rsColumn(X_21=4,\"sys.f_trigger\",\"L21\",\"wrd\",64,0,X_20=nil:bat[:oid,:wrd]);", ] [1] [ 53, "start", "10:04:40.132835", 2, 0, "X_33 := io.stdout();", ] [1] [ 54, "done", "10:04:40.132835", 2, 20, "X_33 := io.stdout();", ] [1] [ 55, "start", "10:04:40.132869", 2, 0, "sql.exportResult(X_33==\"39785280\":streams,X_21=4);", ] [1] [ 56, "done", "10:04:40.132869", 2, 400, "sql.exportResult(X_33==\"39785280\":streams,X_21=4);", ] [1] [ 57, "start", "10:04:40.133291", 2, 0, "end s12_1;", ] This is all using these database settings: type default database shared default yes nthreads default 32 optpipe default default_pipe master default no slave default <unknown> readonly local yes nclients default 64
--algorithms: where do you specify this option?
Thank you.
-- View this message in context: http://old.nabble.com/MonetDB-unexpected-count-group-by-slowdown-tp33137428p... Sent from the monetdb-users mailing list archive at Nabble.com.