Quick sequential access to collection randomly gives no results

[AngryLoki]

Collecting all documents by setting pagesize=1000 and incrementing page gives empty result set randomly.

Example code:

// Get all items
function dbFindAll(items, page) {
  if (!items) items = 0;
  if (!page) page = 1;

  $.get('http://localhost:8080/wd/demo?pagesize=1000&page=' + page, function(data) {
    if (data._embedded) items += data._embedded['rh:doc'].length;
    else console.log("Encountered first empty set at page:", page, data);
    if (data._embedded && data._embedded['rh:doc'].length === 1000) return dbFindAll(items, page + 1);
    console.log("Collection size via iteration:", items);
  });
}

// Generate some data for collection
var postdata = [];
for (var i = 0; i < 10000; i++) {
  postdata.push({ qid: i });
}

// Post generated data, check collection size via `count` and via iteration
$.ajax('http://localhost:8080/wd/demo', {
  data: JSON.stringify(postdata),
  contentType: 'application/json',
  type: 'POST',
  success: function(resp) {
    console.log("Posted", resp._embedded['rh:result'][0].inserted, "docs");
    $.get('http://localhost:8080/wd/demo?count&pagesize=0', function(data) {
      console.log("Now actual collection size is", data._size);
      dbFindAll();
    })
  }
});

First empty page is different each time. However accessing the same page few seconds later gives normal results (i. e. 1000 results). Example output:

Posted 10000 docs
Now actual collection size is 280000
Encountered first empty set at page: 13 Object {_id: "demo", _created_on: "2016-03-04T07:31:55Z", _etag: Object, _collection-props-cached: true, _returned: 0}
Collection size via iteration: 12000

Tested with eager-cursor-allocation-pool-size: 100. Setting eager-cursor-allocation-pool-size to 0 removes this problem.

Checked on:

• Windows/MongoDB 2.6/RESTHeart v. 2.0.0-beta-1.
• Ubuntu/MongoDB 3.2/RESTHeart v. 2.0.0-beta-1.

[ujibang]

fixed

you can get the 2.0.0-beta2-snapshot from sonatype.org

please try it and confirm.

thanks for reporting this one!

[AngryLoki]

Well, now it gives correct results, but now with eager-cursor-allocation-pool-size: 100 it is as slow as with eager-cursor-allocation-pool-size: 0. For example, earlier each page took 20ms (but it was buggy), now it takes 350ms.

[ujibang]

I just committed some cursor pool optimization that should improve your use case.

please try it with the latest snapshot

A basic test follows. I issued the same GET request on a far page (1616400 documents to skip) three times. The first time (with no cursor in pool) took 1.393 sec, the others times (that benefited from preallocated cursors) took 0,602 sec and 0,377 sec

10:44:02.360 [XNIO-1 task-1] DEBUG org.restheart.db.DBCursorPool - no cursor in pool.
10:44:03.619 [XNIO-1 task-1] INFO  o.r.handlers.RequestLoggerHandler - GET http://127.0.0.1:8080/test/huge?pagesize=100&page=16165&eager=linear from /127.0.0.1:51597 => status=200 elapsed=1393ms contentLength=1255 username=a roles=[admins]
10:44:04.750 [cursor-pool-populator-0] DEBUG org.restheart.db.DBCursorPool - new cursor in pool: { collection: test.huge, filter: null, sort: null, skipped: 1615900, cursorId: 13858924232152}
10:44:07.163 [XNIO-1 task-2] DEBUG org.restheart.db.DBCursorPool - found cursor in pool. id 13858924232152, saving 1616400 skips
10:44:07.164 [XNIO-1 task-2] DEBUG org.restheart.db.CollectionDAO - got cursor from pool with skips 1615900. need to reach 1616400 skips.
10:44:07.716 [XNIO-1 task-2] DEBUG org.restheart.db.CollectionDAO - skipping 500 times took 552 msecs
10:44:07.725 [XNIO-1 task-2] INFO  o.r.handlers.RequestLoggerHandler - GET http://127.0.0.1:8080/test/huge?pagesize=100&page=16165&eager=linear from /127.0.0.1:51598 => status=200 elapsed=602ms contentLength=1255 username=a roles=[admins]
10:44:08.943 [cursor-pool-populator-0] DEBUG org.restheart.db.DBCursorPool - new cursor in pool: { collection: test.huge, filter: null, sort: null, skipped: 1615900, cursorId: 13863116884389}
10:44:20.584 [XNIO-1 task-3] DEBUG org.restheart.db.DBCursorPool - found cursor in pool. id 13863116884389, saving 1616400 skips
10:44:20.585 [XNIO-1 task-3] DEBUG org.restheart.db.CollectionDAO - got cursor from pool with skips 1615900. need to reach 1616400 skips.
10:44:20.949 [XNIO-1 task-3] DEBUG org.restheart.db.CollectionDAO - skipping 500 times took 364 msecs
10:44:20.957 [XNIO-1 task-3] INFO  o.r.handlers.RequestLoggerHandler - GET http://127.0.0.1:8080/test/huge?pagesize=100&page=16165&eager=linear from /127.0.0.1:51600 => status=200 elapsed=377ms contentLength=1255 username=a roles=[admins]
10:44:22.141 [cursor-pool-populator-0] DEBUG org.restheart.db.DBCursorPool - new cursor in pool: { collection: test.huge, filter: null, sort: null, skipped: 1615900, cursorId: 13876314840614}

However your test case is more challenging, since it keeps issuing GET requests very quickly (of course this is especially true when the client and restheart are on the same machine, with no network latency). In some cases the populator thread (in charge of preallocating the cursors) happens to work in parallel with the request handlers. In this cases, mongodb is challenged with one heavy query from the populator thread and one query from the request handler. If the mongodb server has limited resources, the latter can be slowed down.

[AngryLoki]

Looks better now (back to 20-100 ms for my collection), thanks!

[ujibang]

Great!

@AngryLoki, Thank you again for helping solving this bug.