ResulSet.next takes too long an blocks

java
udf

#1

Hi,

ResultSet.next takes too long, is there any solution to limit the number of records from the StreamUDF ? Java Code:

resultSet = client.queryAggregate(null, stmt, "linkbench", "get_records", Value.get(id1), Value.get(link_type), Value.get(VISIBILITY_DEFAULT));
		    Iterator<Object> res = resultSet.iterator();
		    
		    while (res.hasNext() && count <= limit) {
		        Object object = res.next();
		        //logger.info("Result #"+count+" for id1="+Value.get(id1)+" is: " + object);
		        id2s.add(Long.parseLong(object.toString()));
		        count++;
		    }

#2

K_Nag,

Does your aggregation UDF has reduce functions as well? And what is the expected number of record does your secondary index query select?

thanks – Raj


#4

Khaled,

Default size of result buffer is 2MB. You seem to be returning small value, so buffer takes time to fill up. What it really means is entire thing runs before sending back result.

Can you try setting query-buf-size config variable to smaller value say 20k to see if result stream out faster.

asinfo -v ‘set-config:context=service;query-buf-size=20000’

Raj


#5

Raj,

Its still very slow, should i change “query-threads” too ?

here is the java code that im running:

 private List<Long> getList(String dbid, long id1, long link_type, long minTimestamp, long maxTimestamp,
                        int offset, int limit) throws Exception {

                Statement stmt;
                ResultSet resultSet = null;
                List<Long> id2s = new ArrayList<Long>();

                stmt = new Statement();
                stmt.setNamespace(dbid);
                stmt.setSetName("links");
                stmt.setIndexName("time");
                stmt.setFilters(Filter.range("time", minTimestamp, maxTimestamp));
              
                int count = 0;
                try {

                        resultSet = client.queryAggregate(null, stmt, "linkmodule", "get_records", Value.get(id1),
                                         Value.get(link_type), Value.get(VISIBILITY_DEFAULT),Value.get(limit));
                    
                        while (resultSet.next() && count <= limit) {
                                Object object = resultSet.getObject();
                                logger.info("Result #"+count+" for id1="+Value.get(id1)+" is: " + object);
                                id2s.add(Long.parseLong(object.toString()));
                                count++;
                        }

                        if (count == 0) {
                                //System.out.println("No results returned.");
                                //return null;
                        }
                } finally {
                        resultSet.close();
                }
 return id2s;
 }

thanks


#6

Can you quantify slow. How much time is it taking.

And what does your histogram in server logs suggest time queries are taking to finish on server side.

– R


#7

Hi Raj,

with the AQL command below it takes all the Timeout:

aql> aggregate linkbench.get_records(336759,123456789,'1') on linkdbb.links
^C0 rows in set (60.027 secs)
Error: (9) Timeout: timeout=60000 iterations=1 failedNodes=0 failedConns=0

logs:

Dec 01 2016 21:33:44 GMT: INFO (nsup): (thr_nsup.c:1173) {linkdbc} nsup start
Dec 01 2016 21:33:44 GMT: INFO (nsup): (thr_nsup.c:1097) {linkdbc} Records: 0, 0 0-vt, 0(0) expired, 0(0) evicted, 0(0) set deletes. Evict ttl: 0. Waits: 0,0,0. Total time: 2 ms
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:169) NODE-ID bb99067580060c8 CLUSTER-SIZE 1
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:238)    system-memory: free-kbytes 26459224 free-pct 80
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:252)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:274)    fds: proto (0,2953,2953) heartbeat (0,0,0) fabric (16,16,0)
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:283)    heartbeat-received: self 48023 foreign 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:307)    early-fail: demarshal 0 tsvc-client 12187731 tsvc-batch-sub 0 tsvc-udf-sub 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:337) {test} objects: all 0 master 0 prole 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:398) {test} migrations: complete
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:417) {test} memory-usage: total-bytes 0 index-bytes 0 sindex-bytes 0 data-bytes 0 used-pct 0.00
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:337) {bar} objects: all 0 master 0 prole 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:398) {bar} migrations: complete
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:417) {bar} memory-usage: total-bytes 0 index-bytes 0 sindex-bytes 0 data-bytes 0 used-pct 0.00
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:337) {linkdbb} objects: all 7333775 master 7333775 prole 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:398) {linkdbb} migrations: complete
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:417) {linkdbb} memory-usage: total-bytes 2483977307 index-bytes 469361600 sindex-bytes 840666126 data-bytes 1173949581 used-pct 23.13
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:447) {linkdbb} device-usage: used-bytes 3312949376 avail-pct 79
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:490) {linkdbb} ldt-gc: cnt 0 io 0 gc 0 (0,0,0)
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:540) {linkdbb} client: tsvc (0,0) proxy (0,0,0) read (1214593,0,0,492662) write (849167,0,0) delete (20304,0,0,1) udf (0,0,0) lang (0,0,0,0)
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:596) {linkdbb} scan: basic (0,0,0) aggr (4,1,0) udf-bg (0,0,0)
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:621) {linkdbb} query: basic (0,0) aggr (7,0) udf-bg (0,0)
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-read (1707255 total) msec
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:171)  (00: 0001707145) (01: 0000000050) (02: 0000000060)
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-write (849167 total) msec
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:162)  (00: 0000848999) (01: 0000000110) (02: 0000000057) (04: 0000000001)
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-query (7 total) msec
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:171)  (15: 0000000007)
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-query-rec-count (2 total) count
Dec 01 2016 21:33:48 GMT: INFO (info): (hist.c:171)  (01: 0000000002)
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:337) {linkdbc} objects: all 0 master 0 prole 0
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:398) {linkdbc} migrations: complete
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:417) {linkdbc} memory-usage: total-bytes 73728 index-bytes 0 sindex-bytes 73728 data-bytes 0 used-pct 0.00
Dec 01 2016 21:33:48 GMT: INFO (info): (ticker.c:490) {linkdbc} ldt-gc: cnt 0 io 0 gc 0 (0,0,0)
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:169) NODE-ID bb99067580060c8 CLUSTER-SIZE 1
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:238)    system-memory: free-kbytes 26458380 free-pct 80
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:252)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:274)    fds: proto (0,2953,2953) heartbeat (0,0,0) fabric (16,16,0)
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:283)    heartbeat-received: self 48090 foreign 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:307)    early-fail: demarshal 0 tsvc-client 12187731 tsvc-batch-sub 0 tsvc-udf-sub 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:337) {test} objects: all 0 master 0 prole 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:398) {test} migrations: complete
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:417) {test} memory-usage: total-bytes 0 index-bytes 0 sindex-bytes 0 data-bytes 0 used-pct 0.00
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:337) {bar} objects: all 0 master 0 prole 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:398) {bar} migrations: complete
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:417) {bar} memory-usage: total-bytes 0 index-bytes 0 sindex-bytes 0 data-bytes 0 used-pct 0.00
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:337) {linkdbb} objects: all 7333775 master 7333775 prole 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:398) {linkdbb} migrations: complete
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:417) {linkdbb} memory-usage: total-bytes 2483977307 index-bytes 469361600 sindex-bytes 840666126 data-bytes 1173949581 used-pct 23.13
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:447) {linkdbb} device-usage: used-bytes 3312949376 avail-pct 79
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:490) {linkdbb} ldt-gc: cnt 0 io 0 gc 0 (0,0,0)
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:540) {linkdbb} client: tsvc (0,0) proxy (0,0,0) read (1214593,0,0,492662) write (849167,0,0) delete (20304,0,0,1) udf (0,0,0) lang (0,0,0,0)
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:596) {linkdbb} scan: basic (0,0,0) aggr (4,1,0) udf-bg (0,0,0)
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:621) {linkdbb} query: basic (0,0) aggr (7,0) udf-bg (0,0)
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-read (1707255 total) msec
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:171)  (00: 0001707145) (01: 0000000050) (02: 0000000060)
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-write (849167 total) msec
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:162)  (00: 0000848999) (01: 0000000110) (02: 0000000057) (04: 0000000001)
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-query (7 total) msec
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:171)  (15: 0000000007)
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:145) histogram dump: {linkdbb}-query-rec-count (2 total) count
Dec 01 2016 21:33:58 GMT: INFO (info): (hist.c:171)  (01: 0000000002)
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:337) {linkdbc} objects: all 0 master 0 prole 0
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:398) {linkdbc} migrations: complete
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:417) {linkdbc} memory-usage: total-bytes 73728 index-bytes 0 sindex-bytes 73728 data-bytes 0 used-pct 0.00
Dec 01 2016 21:33:58 GMT: INFO (info): (ticker.c:490) {linkdbc} ldt-gc: cnt 0 io 0 gc 0 (0,0,0)

#8

Hi Raj,

Any suggestion ?