preflist_exhausted message when running out of JS VMs [JIRA: RIAK-2399]

[jonmeredith]

If all JS VMs are busy, MapReduce can return a preflist_exhausted message.

{"phase":0,"error":"[preflist_exhausted]","input":"..."}

accompanied with a message in console.log

16:40:50.037 [notice] JS call failed: All VMs are busy.

If pipe is out of a resource it would be helpful if it let the client know.

The scripts below reproduce. First seed with some data (needs recent b_b)

{mode, max}.
{duration, 1}.
{concurrent, 3}.
{driver, basho_bench_driver_http_raw}.
{key_generator, {int_to_str, {partitioned_sequential_int, 0, 100000}}}.
{value_generator, {fixed_bin, 1000, $X}}.
{http_raw_port, 8098}.
{operations, [{put, 1}]}.
{source_dir, "foo"}.
{http_raw_ips, ["pe1950-1.local","pe1950-2.local","dl360g5-1.local"]}.
{http_raw_path, "/riak/bucket"}.

Then run the following MR query

jons-macpro:ml-pl-ex jmeredith$ cat QUERY 
echo -n "Starting $$: "
## Add this helps {"timeout":300000,
time curl -X POST -H "content-type: application/json" \
    http://${1:-pe1950-1.local:8098}/mapred --data @-<<\EOF
{"timeout":10000,"inputs":"bucket"
,"query":[{"map":{"language":"javascript","source":"
function(v) {
  return [1]
}
"}},{"reduce":{"language":"javascript","source":"
function(v) {
  return [v.reduce(function(t, val) { return t + val; }, 0)]
}
"}}]}
EOF

with 10 in parallel in a loop

jons-macpro:ml-pl-ex jmeredith$ cat QUERY 
echo -n "Starting $$: "
## Add this helps {"timeout":300000,
time curl -X POST -H "content-type: application/json" \
    http://${1:-pe1950-1.local:8098}/mapred --data @-<<\EOF
{"timeout":10000,"inputs":"bucket"
,"query":[{"map":{"language":"javascript","source":"
function(v) {
  return [1]
}
"}},{"reduce":{"language":"javascript","source":"
function(v) {
  return [v.reduce(function(t, val) { return t + val; }, 0)]
}
"}}]}
EOF
jons-macpro:ml-pl-ex jmeredith$ cat PARALLEL 
while true
do
    echo === $(date) ===
    for i in 1 2 3 4 5 6 7 8 9 10 
    do
      ./QUERY &
    done
    wait
done

Adding some debug to riak_pipe_vnode:queue_work_erracc/6 at the point where it returns perflist_exhausted shows that the call came from riak_pipe_vnode_worker:process_input/3 as the result of riak_kv_mrc_map returning forward_preflist, which it only does when map_js gets {error, no_vms} from riak_kv_js_manager:blocking_dispatch

Here is the telling backtrace.

16:40:50.037 [info] Preflist exhausted: Input: {ok,{r_object,<<98,117,99,107,101,116>>,<<55,52,48,54,49>>,[{r_content,{dict,6,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[[<<76,105,110,107,115>>]],[],[],[],[],[],[],[],[[<<99,111,110,116,101,110,116,45,116,121,112,101>>,97,112,112,108,105,99,97,116,105,111,110,47,111,99,116,101,116,45,115,116,114,101,97,109],[<<88,45,82,105,97,107,45,86,84,97,103>>,52,87,51,51,108,101,70,103,57,55,108,50,78,102,65,86,101,49,51,111,66,68]],[[<<105,110,100,101,120>>]],[],[[<<88,45,82,105,97,107,45,76,97,115,116,45,77,111,100,105,102,105,101,100>>|{1333,122926,806801}]],[],[[<<88,45,82,105,97,107,45,77,101,116,97>>]]}}},<<88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,88,...>>}],...},...}  NVal: 1 UsedPrefList: [{45671926166590716193865151022383844364247891968,'riak@dl360g5-1.local'}] ErrAcc: []
16:40:50.039 [info] BT: 
Program counter: 0x00007f68f7761758 (unknown function)
CP: 0x00007f68ed648590 (riak_pipe_vnode:queue_work_erracc/6 + 1544)

0x00007f68e980c538 Return addr 0x00007f68ec6862d8 (riak_pipe_vnode_worker:forward_preflist/3 + 248)
y(0)     [{45671926166590716193865151022383844364247891968,'riak@dl360g5-1.local'}]
y(1)     []
y(2)     []
y(3)     "<0.1399.0>"
y(4)     <0.1399.0>

0x00007f68e980c568 Return addr 0x00007f68ec685460 (riak_pipe_vnode_worker:process_input/3 + 1256)
y(0)     {state,45671926166590716193865151022383844364247891968,{fitting_details,{fitting,<7226.1384.0>,#Ref<7226.0.2.171556>,follow,1},{xform_map,0},riak_kv_mrc_map,{{jsanon,<<26 bytes>>},none},{fitting,<7226.1383.0>,#Ref<7226.0.2.171556>,<<20 bytes>>,1},[{sink,{fitting,<7226.957.0>,#Ref<7226.0.2.171556>,sink,undefined}},{log,sink},{trace,{set,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[error],[],[],[],[],[],[],[],[],[],[],[],[],[]}}}}],64},<0.246.0>,{state,45671926166590716193865151022383844364247891968,{fitting_details,{fitting,<7226.1384.0>,#Ref<7226.0.2.171556>,follow,1},{xform_map,0},riak_kv_mrc_map,{{jsanon,<<26 bytes>>},none},{fitting,<7226.1383.0>,#Ref<7226.0.2.171556>,<<20 bytes>>,1},[{sink,{fitting,<7226.957.0>,#Ref<7226.0.2.171556>,sink,undefined}},{log,sink},{trace,{set,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[error],[],[],[],[],[],[],[],[],[],[],[],[],[]}}}}],64},{jsanon,<<26 bytes>>},none}}
y(1)     {ok,{r_object,<<6 bytes>>,<<5 bytes>>,[{r_content,{dict,6,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[[<<5 bytes>>]],[],[],[],[],[],[],[],[[<<12 bytes>>,97,112,112,108,105,99,97,116,105,111,110,47,111,99,116,101,116,45,115,116,114,101,97,109],[<<11 bytes>>,52,87,51,51,108,101,70,103,57,55,108,50,78,102,65,86,101,49,51,111,66,68]],[[<<5 bytes>>]],[],[[<<20 bytes>>|{1333,122926,806801}]],[],[[<<11 bytes>>]]}}},<<1000 bytes>>}],[{<<8 bytes>>,{1,63500342126}}],{dict,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[[clean|true]],[]}}},undefined},undefined}
y(2)     {state,45671926166590716193865151022383844364247891968,{fitting_details,{fitting,<7226.1384.0>,#Ref<7226.0.2.171556>,follow,1},{xform_map,0},riak_kv_mrc_map,{{jsanon,<<26 bytes>>},none},{fitting,<7226.1383.0>,#Ref<7226.0.2.171556>,<<20 bytes>>,1},[{sink,{fitting,<7226.957.0>,#Ref<7226.0.2.171556>,sink,undefined}},{log,sink},{trace,{set,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[error],[],[],[],[],[],[],[],[],[],[],[],[],[]}}}}],64},{jsanon,<<26 bytes>>},none}
y(3)     {fitting_details,{fitting,<7226.1384.0>,#Ref<7226.0.2.171556>,follow,1},{xform_map,0},riak_kv_mrc_map,{{jsanon,<<26 bytes>>},none},{fitting,<7226.1383.0>,#Ref<7226.0.2.171556>,<<20 bytes>>,1},[{sink,{fitting,<7226.957.0>,#Ref<7226.0.2.171556>,sink,undefined}},{log,sink},{trace,{set,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[error],[],[],[],[],[],[],[],[],[],[],[],[],[]}}}}],64}

0x00007f68e980c590 Return addr 0x00007f68ec6849b0 (riak_pipe_vnode_worker:wait_for_input/2 + 264)
y(0)     {state,45671926166590716193865151022383844364247891968,{fitting_details,{fitting,<7226.1384.0>,#Ref<7226.0.2.171556>,follow,1},{xform_map,0},riak_kv_mrc_map,{{jsanon,<<26 bytes>>},none},{fitting,<7226.1383.0>,#Ref<7226.0.2.171556>,<<20 bytes>>,1},[{sink,{fitting,<7226.957.0>,#Ref<7226.0.2.171556>,sink,undefined}},{log,sink},{trace,{set,1,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[error],[],[],[],[],[],[],[],[],[],[],[],[],[]}}}}],64},{jsanon,<<26 bytes>>},none}
y(1)     Catch 0x00007f68ec6854c0 (riak_pipe_vnode_worker:process_input/3 + 1352)
y(2)     {state,45671926166590716193865151022383844364247891968,{fitting_details,{fitting,<7226.1384.0>,#Ref<7226.0.2.171556>,follow,1},{xform_map,0},riak_kv_mrc_map,{{jsanon,<<26 bytes>>},none},{fitting,<7226.1383.0>,#Ref<7226.0.2.171556>,<<20 bytes>>,1},[{sink,{fitting,<7226.957.0>,#Ref<7226.0.2.171556>,sink,undefined}},{log,sink},{trace,{set,1,16,1...

[jonmeredith]

If you are seeing the log message, the number of VMs allocated for map and reduce tasks can be configured in the app.config - defaults are 8 for map and 6 for reduce, increasing them will use more memory but should reduce the incidence of the error message.

{riak_kv, [
             ...
            {map_js_vm_count, 24 },
            {reduce_js_vm_count, 18 },
            ...]

[bashopatricia]

Will not fix. JS deprecated.