ResulSet.next takes too long an blocks

K_Nag · November 29, 2016, 6:35pm

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++;
		    }

raj · November 30, 2016, 2:45pm

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

raj · November 30, 2016, 4:51pm

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

K_Nag · November 30, 2016, 5:31pm

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

raj · December 1, 2016, 5:47am

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

K_Nag · December 1, 2016, 2:08pm

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)

K_Nag · December 5, 2016, 5:01pm

Hi Raj,

Any suggestion ?

Topic		Replies	Views
Issue with Multiple threads executing queryAggregate Query & Indexing	4	1753	October 29, 2014
Poor streaming UDF performance Tuning secondary , udf , index	4	2051	January 1, 2018
Slow UDF issue and how to do partial reads/writes on maps User Defined Functions (UDF)	26	4802	February 18, 2015
Does queryAggregate() return Single or Multiple results or rows from ResultSet Java Client query , java , udf , aggregation	6	63	April 11, 2024
Counting distinct (unique) Query & Indexing query , secondary , udf , aggregation , index	4	5981	August 16, 2014

ResulSet.next takes too long an blocks

Related Topics