Query Aggregate works only on a partition of set's data

Client Libraries Java Client
1

Hi,

I am dealing with a big problem for which I don’t find a solution. I have two namespace, one in RAM and the second on hard disk. I would to launch a queryAggregate with udf module to get which records, pre-filtered with secondary index from RAM’s namespace, are got by hard disk’s namespace. My problem is that the scan aggregation job launched by Aerospike does not analyse all records of set but only a few. In particular Set in hard disk contains 5520 records, RAM’s set return 5148 and only 3311 records are considered in lua. In Java Client I do not receive any timeout errors or other kinds of error. Therefore could it be caused by a particular timeout or a limit on number of records that can be considered in udf module?

2

This is an aggregation feature usage question, so better fitted in

How are you getting the object count for a set? Are you using something like

$ asinfo -v sets ns=test:set=testset:objects=4800:tombstones=0:memory_data_bytes=0:deleting=false:stop-writes-count=0:set-enable-xdr=use-default:disable-eviction=false;

This number contains both master and replica counts. In a multi-node environment, scan aggregation only looks at the master objects.

3

Thank you for your reply. For the object count I look at aql because at the moment my environment is made up of only one local node so there is not any type of cluster. I think that the problem on aggregation is more connected with JAVA for this reason I have write in this topic. In JAVA I have used object Statement without filter to send a query on Hard Disk Namespace like a scan all through method client.queryAggregate and I apply an udf which take in input a list of string got by namespace in RAM and return only records of Hard Disk Namespace that are found in that list. IF I debug udf, I will see that only a portion of all records are analysed by udf and so I don’t understand the reason or cause of the problem. Could you help me?

4

Most likely there is some issue with the UDF being run. Some recommendation to help you troubleshoot -

  • Try do a simple scan, like the scanParallel example in the java example’s directory.
  • Then try to run the QueryFilter example, with a little modification to always filter the record to be returned.
  • You can also try running the same experiments in aql, and the same number of records will be returned.
5

Can you post your udf with some sample data - few records and walk thru what you are doing exactly?

6

Hi pgupta,

now I have a client Java with this statement:

Statement stmt = new Statement();
stmt.setNamespace(Constants.SSD_NAMESPACE);
stmt.setSetName(set);
stmt.setFilters(Filter.equal("passed",  1));

where passed is a secondary index with only two values ( 0 or 1) and launch a queryAggregate for calling udf:

client.queryAggregate(qp, stmt, "matching", "searchSSDonCluster", Value.get(fplong), Value.get(hamming));

where fplong is byte array and hamming is an int

Now my set’s structure is

----------------------------------------------------------------------------------------------------------------+--------+------+
| photoname                      | fplong                      | passed       | ar   |
+------------------------------+-------------------------------------------------------------------------------+--------+------+
| "Rollei_RCP-7325XS_2_43274"    | 83 D0 77 88 63 44 F4 E3 ... |    0         |    1333  |
| "Sony_DSC-T77_1_48947"         | D5 BD AA 72 7C A1 91 ...    |    1         |   1333   |

This set has 6060 records

The file Matching.lua is:

                      local function filter(element)
                          return element['hamming']~=0 and element['hamming']~=-1 
                      end
                      
                      local function aggregate_sts(lista, nextitem)
                          list.append(lista, nextitem)
                          return lista
                      end
                      
                      local function reduce_stats(a,b)
                           return list.merge(a,b)
                      end
                       local function searchSSD(long_query, thresholdSSD)
                          return function(record)
                             local fromlua=require("fromlua")
                                 -- FUNCTION C
                             local hamming = fromlua.matchSecondStep(record['fplong'], long_query, thresholdSSD)
                             return map {photoname = record['photoname'], hamming=hamming}
                           end 
                         end

                         function searchSSDonCluster(stream, long_query, thresholdSSD)
                              local mymap = searchSSD(long_query,thresholdSSD)
                              return stream : map(mymap) : filter(filter) : aggregate(list{},aggregate_sts) : reduce(reduce_stats)
                         end

Now my problem is that when you run using debug all works perfectly but when you run in execution only a part of all data are come back to JAVA and this result is not deterministic.

HERE YOU READ AEROSPIKE LOG AFTER EXECUTION:

    Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::868) Released qtr [base/thr_query.c:2048] 0x7fc9a074d008 1 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::2153) **start 1 end 1 @ 1 pimd found 10**
**Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::2516) Loop=6, Selected=10, ret=0**
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::880) Reserved qtr [base/thr_query.c:2017] 0x7fc9a074d008 2 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::1992) Processing Request 1
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1234) apply_stream: BEGIN
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1237) apply_stream: poll state
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::654) [CACHE] is disabled.
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (src/main/mod_lua.c::610) Size of the lua state created for the file matching in KB 79
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::666) [CACHE] state created: matching
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1252) apply_stream: push aerospike into the global scope
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1257) apply_stream: push apply_stream() onto the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1261) apply_stream: push function onto the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1266) apply_stream: push scope onto the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1270) apply_stream: push istream onto the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1273) apply_stream: push ostream onto the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1277) apply_stream: push each argument onto the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::807) pushargs: 3
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1288) apply_stream: apply the function matching.searchSSDonCluster
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::842) apply
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::857) call function
Feb 03 2017 09:53:57 GMT: INFO (aggr): ([C]::-1) SEARCH SSD as SECOND STEP: 216
Feb 03 2017 09:53:57 GMT: INFO (aggr): ([C]::-1) STREAM IS NOT PROBLEM
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0ce40)[photoname] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: photoname not modified, add for 0x7fc82b7bd450:0x7fc990a96540
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (photoname) [0x7fc82b7bd450,0x7fc990a96540]
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::80) ANALYSES Canon_Ixus70_1_3724
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(fplong)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(fplong) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: fplong find
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0e208)[fplong] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: fplong not modified, add for 0x7fc82b7bd450:0x7fc990a96560
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (fplong) [0x7fc82b7bd450,0x7fc990a96560]
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: photoname find
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::435) Bin photoname found, type(4)
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::81) ELEMENT Canon_Ixus70_1_3724 with Hamming 253851
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::175) AGGREGATE: Canon_Ixus70_1_3724
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0xae25b246260f8744a4a08808b7e9ec596e743d67
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(2) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0ce40)[photoname] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: photoname not modified, add for 0x7fc82b7bd450:0x7fc990a96500
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (photoname) [0x7fc82b7bd450,0x7fc990a96500]
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::80) ANALYSES Canon_Ixus70_1_3764
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(fplong)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(fplong) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: fplong find
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0e208)[fplong] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: fplong not modified, add for 0x7fc82b7bd450:0x7fc990a96600
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (fplong) [0x7fc82b7bd450,0x7fc990a96600]
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: photoname find
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::435) Bin photoname found, type(4)
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::81) ELEMENT Canon_Ixus70_1_3764 with Hamming 247876
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::175) AGGREGATE: Canon_Ixus70_1_3764
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0xcb45ee88c702dc48a19c7b2334f24cb82ada5790
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(2) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::1429) query_record_matches: sindex key does not matches bin value in record. bin value 0 skey value 1
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0x8b518642f808139501a5cd5454bed28399a7fc97
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(0) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::1429) query_record_matches: sindex key does not matches bin value in record. bin value 0 skey value 1
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0xb0acd615dd8e7b2e88363d0b4adc0c951f17329c
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(0) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::1429) query_record_matches: sindex key does not matches bin value in record. bin value 0 skey value 1
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0xbe782dd7460bb2259fe564ed9e15eb2cde7e3cae
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(0) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0ce40)[photoname] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: photoname not modified, add for 0x7fc82b7bd450:0x7fc990a96540
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (photoname) [0x7fc82b7bd450,0x7fc990a96540]
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::80) ANALYSES Canon_Ixus70_1_3769
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(fplong)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(fplong) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: fplong find
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0e208)[fplong] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: fplong not modified, add for 0x7fc82b7bd450:0x7fc990a966a0
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (fplong) [0x7fc82b7bd450,0x7fc990a966a0]
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: photoname find
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::435) Bin photoname found, type(4)
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::81) ELEMENT Canon_Ixus70_1_3769 with Hamming 248016
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::175) AGGREGATE: Canon_Ixus70_1_3769
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0x94d1fc088f15e149953a16301b2c4eb0c20c92b0
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(2) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::1429) query_record_matches: sindex key does not matches bin value in record. bin value 0 skey value 1
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0xf9374f526de228f7da65d317764cbd7a00caf3b3
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(0) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0ce40)[photoname] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: photoname not modified, add for 0x7fc82b7bd450:0x7fc990a96500
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (photoname) [0x7fc82b7bd450,0x7fc990a96500]
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::80) ANALYSES Canon_Ixus70_1_3888
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(fplong)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(fplong) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: fplong find
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::480) [ENTER] urecord(0x7fc82b7bd450) name(0x40a0e208)[fplong] dirty(0)
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::517) udf_record_set: fplong not modified, add for 0x7fc82b7bd450:0x7fc990a96740
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::731) udf_record_get: end (fplong) [0x7fc82b7bd450,0x7fc990a96740]
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::696) [ENTER] rec(0x7fc990a95a40) name(photoname)
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::429) [ENTER] BinName(photoname) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::431) udf_record_get: photoname find
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::435) Bin photoname found, type(4)
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::81) ELEMENT Canon_Ixus70_1_3888 with Hamming 255191
Feb 03 2017 09:53:57 GMT: INFO (aggr): (/opt/aerospike/sys/udf/lua/stream_ops.lua::175) AGGREGATE: Canon_Ixus70_1_3888
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0x1030b622a05552af3d6f73d4083d6abf962d1db6
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(2) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::1429) query_record_matches: sindex key does not matches bin value in record. bin value 0 skey value 1
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0x971c031b030abaafa3ab02731725b0fee92fb4c2
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(0) 
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_open:210) [ENTER] Opening record key:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::226) Opening Record 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_open:240) Open 0x7fc82b7bd450 c8 Digest:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_storage_record_open:84) [ENTER] Opening record key:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_open:117) Storage Open: Rec(0x7fc82b7bd450) flag(d8) Digest:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::1429) query_record_matches: sindex key does not matches bin value in record. bin value 0 skey value 1
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c:udf_record_close:271) [ENTER] Closing record key:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c::276) Closing Record
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_storage_record_close:183) Storage Close:: Rec(0x7fc82b7bd450) Flag(c8) Digest:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (udf_record.c:udf_record_close:281) Storage Close:: Rec(0x7fc82b7bd450) Flag(c0) Digest:<Digest>:0xfe50d0c011c55722d4e1daf266749c33e557edc8
Feb 03 2017 09:53:57 GMT: DEBUG (udf): (udf_record.c::446) [ENTER] NumUpdates(0) 
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::860) rc = 0
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::863) convert lua type to val
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::886) pop return value from the stack
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1293) apply_stream: lose the context
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::763) [CACHE] is disabled.
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::771) [CACHE] state closed: matching
Feb 03 2017 09:53:57 GMT: DETAIL (udf): (src/main/mod_lua.c::1297) apply_stream: END
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::868) Released qtr [base/thr_query.c:2048] 0x7fc9a074d008 1 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::2153) **start 1 end 1 @ 1 pimd found 0**
**Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::2173) All the Data finished moving to next tree 2**
**Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::2516) Loop=7, Selected=0, ret=2**
Feb 03 2017 09:53:57 GMT: DEBUG (query): (thr_query.c::613) Query 0x7fc9a074d008 Done at base/thr_query.c:2536
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::880) Reserved qtr [base/thr_query.c:2017] 0x7fc9a074d008 2 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::1992) Processing Request 1
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::868) Released qtr [base/thr_query.c:2048] 0x7fc9a074d008 1 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::2340) Request is finished
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::1200) Adding fin 0x7fc9a074d008
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::880) Reserved qtr [base/thr_query.c:977] 0x7fc9a074d008 2 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::903) Netio Started_CB 0 1 1 4 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::930) Query Finish Callback io seq 1 with retCode 0
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::477) Pushed 0x7fc990836000 2097152 2097152 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::868) Released qtr [base/thr_query.c:950] 0x7fc9a074d008 1 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::497) Popped 0x7fc990836000
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::865) Released qtr [base/thr_query.c:2553] 0x7fc9a074d008 0 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::769) Total time elapsed 38728 us, 6 of 60 read operations avg latency 6454 us
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::477) Pushed 0x7fc990836000 2097152 2097152 
Feb 03 2017 09:53:57 GMT: DETAIL (query): (thr_query.c::868) Released qtr [base/thr_query.c:2553] 0x7fc9a074d008 0 
Feb 03 2017 09:53:59 GMT: INFO (info): (thr_info.c::4951)  system memory: free 10417136kb ( 63 percent free )
7

Could you explain what you mean by “run using debug” and “run in execution”?

Also, is your cluster in migration (paritition map rebalancing due to node addition/removal)?

Loading/running functions from another module is tricky. Can you put the “matchSecondStep” function directly in “matching.lua” to simplify things?

8

Yes , of course. Pratically, I run client JAVA using Eclipse debugging so using debug in mode step by step and in this case all seem works correctly. But if you run client JAVA and you don’t use debug mode the results are completely different and not deterministic in particular they are only a part of real correct results.

About matchSecondStep I think that it is not real problem because I have tested it and work perfectly. I can try to put all in LUA but I am not sure that this solves my problem.

I hope to give you a good explanation.

9

Besides while I am reading aerospike’s log file, I have found the following message at the end of lua operations:

Feb 06 2017 13:21:19 GMT: WARNING (query): (ai_btree.c::742) Could not find nbtr iterator.. skipping !!

If it is the problem, how can I solve it? What does it mean?

10

That error is probably responsible for your problem. We will investigate. What is your server version? Can you try the latest server to see if this has been fixed?

In the meantime, I will explain some secondary index query limitations.

  1. Records will not be returned in the same order on successive queries. The reason is query requests are sent to multiple nodes in parallel by default. The responses from these nodes are interleaved.

  2. If the cluster is in migration (partitions moving between nodes), the query results may miss data or contain duplicate data. You can tell if the cluster is in migration by issuing this command line info request multiple times.

asinfo -v partition-generation

If the partition-generation changes, then the cluster is in migration. Fortunately, migrations only occur after a node is added or removed from the cluster.

11

The error message means there is a secondary index key with no digest in it.

Run this asinfo command after replacing namespace and indexname (of “passed” bin) and send us the result:

asinfo -v sindex-stat:ns=<namespace>;indexname=<indexname>
12

Brian thank you for your help. About server version I have Aerospike Community Edition build 3.7.5, while for my problem probably I have just solved beacuse I think it was a problem based on management of multithreading in Java client. However I have tried to run your command and the result can be a problem because it is:

FAIL:4:Index Name Not Specified

but at the same time when I run show indexes in aql I find:

aql> show indexes
+---------------+----------+-----------+-----------+-------+-----------+----------+------------+-----------+
| ns            | bin      | indextype | set       | state | indexname | path     | sync_state | type      |
+---------------+----------+-----------+-----------+-------+-----------+----------+------------+-----------+
| "toothpicRAM" | "ar"     | "NONE"    | "polizia" | "RW"  | "arP"     | "ar"     | "synced"   | "NUMERIC" |
| "toothpicSSD" | "ar"     | "NONE"    | "polizia" | "RW"  | "arP"     | "ar"     | "synced"   | "NUMERIC" |
| "toothpicSSD" | "passed" | "NONE"    | "polizia" | "RW"  | "passed"  | "passed" | "synced"   | "NUMERIC" |
+---------------+----------+-----------+-----------+-------+-----------+----------+------------+-----------+
3 rows in set (0.000 secs)
OK

Besides, now I have another problem when I update many records aerospike server reply with the exception com.aerospike.client.AerospikeException: Error Code 18: Device overload. So I have already documented about it and it is a problem due to cache size so I try to expand it until to reach 1024M but I always get the same error. Can you suggest possible solutions?

Thank you.

13

Sorry, the command needs to be run in quotes. Here is the correct command:

asinfo -v 'sindex-stat:ns=<namespace>;indexname=<indexname>'

The “device overload” isn’t a java client question and not my expertise. I recommend asking in the server forum.

14

“Device overload” indicate the underlying device not being able to keep up with the write throughput of the system. Either replace with a higher performing raw device, or have more raw devices installed for the namespace to scale out the write load.