[SERVER-20385] $sample stage could not find a non-duplicate document while using a random cursor Created: 11/Sep/15  Updated: 05/Jun/17  Resolved: 03/Jun/17

Status: Closed
Project: Core Server
Component/s: Aggregation Framework, WiredTiger
Affects Version/s: 3.1.7
Fix Version/s: 3.1.9

Type: Bug Priority: Major - P3
Reporter: Matt Kangas Assignee: Keith Bostic (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File SERVER-20385-tmp3.tgz    
Issue Links:
Depends
is depended on by WT-1973 MongoDB changes for WiredTiger 2.7.0 Closed
Duplicate
is duplicated by SERVER-20503 $sample gives persistent error on uni... Closed
Related
related to SERVER-29446 $sample stage could not find a non-du... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

Repro'd on Ubuntu 15.04 with a local build of mongod from source.

Extract tarball to tmp3

./mongod --dbpath tmp3 --port 27009
./mongo --port 27009
> use mongodb
> db.fanclub.aggregate([{$sample: {size: 120}}])

Try the .aggregate query a few times (n < 5)

Sprint: Quint 9 09/18/15
Participants:

 Description   

Running 3.1.8-pre (d03334dfa87386feef4b8331f0e183d80495808c)

> db.fanclub.aggregate([{$sample: {size: 120}}])
assert: command failed: {
        "ok" : 0,
        "errmsg" : "$sample stage could not find a non-duplicate document after 100 while using a random cursor. This is likely a sporadic failure, please try again.",
        "code" : 28799
} : aggregate failed
_getErrorWithCode@src/mongo/shell/utils.js:23:13
doassert@src/mongo/shell/assert.js:13:14
assert.commandWorked@src/mongo/shell/assert.js:259:5
DBCollection.prototype.aggregate@src/mongo/shell/collection.js:1211:5
@(shell):1:1

It is indeed sporadic in my testing. Should the client ever see this message?

I am able to reproduce this with --storageEngine=wiredTiger on a somewhat old set of files:

$ less tmp/WiredTiger
WiredTiger
WiredTiger 2.5.1: (December 24, 2014)

However, when I export/import that database into a new --dbpath, I am unable to repro:

$ less tmp2/WiredTiger
WiredTiger
WiredTiger 2.6.2: (June  4, 2015)



 Comments   
Comment by Charlie Swanson [ 05/Jun/17 ]

Opened SERVER-29446 to investigate

Comment by A. Jesse Jiryu Davis [ 30/May/17 ]

The error message is still missing a word after "100", as Charlie said, it should be "100 attempts".

Comment by A. Jesse Jiryu Davis [ 30/May/17 ]

With MongoDB 3.4.4 on Mac OS X, I can reproduce this. First do "python -m pip install pymongo pytz", then:

from datetime import datetime, timedelta
 
import pytz
from bson import ObjectId
from pymongo import MongoClient
from pymongo.errors import OperationFailure
 
CHUNKS = 20
 
collection = MongoClient().db.test
collection.delete_many({})
 
start = datetime(2000, 1, 1, tzinfo=pytz.UTC)
for hour in range(10000):
    collection.insert(
        {'_id': ObjectId.from_datetime(start + timedelta(hours=hour)), 'x': 1})
 
for _ in range(10):
    try:
        docs = list(collection.aggregate([{
            "$sample": {"size": CHUNKS}
        }, {
            "$sort": {"_id": 1}
        }]))
    except OperationFailure as exc:
        if exc.code == 28799:
            # Work around https://jira.mongodb.org/browse/SERVER-20385
            print("retry")
            continue
 
        raise
 
    for d in docs:
        print(d['_id'].generation_time)
 
    break
else:
    raise OperationFailure("$sample failed")

As often as not, the sample fails ten times in a row with error code 28799 and the message: "$sample stage could not find a non-duplicate document after 100 while using a random cursor. This is likely a sporadic failure, please try again."

Comment by Mor [X] [ 05/Apr/17 ]

I'm able to reproduce this issue on 3.2.12:

Collection contains 1.1B documents, trying to get a $sample of 1M keep returning this error msg (3/3 tries).

The sample size is less then 1% of the collection size, so I don't think it should be hard to get 1M unique documents statistically speaking.

The sample works ok for 1000.

Comment by Matt Kangas [ 18/Sep/15 ]

Confirmed fixed per the repro above. Thanks!

Comment by Githook User [ 16/Sep/15 ]

Author:

{u'username': u'michaelcahill', u'name': u'Michael Cahill', u'email': u'michael.cahill@mongodb.com'}

Message: Merge pull request #2194 from wiredtiger/server-20385

SERVER-20385: WT_CURSOR.next(random) more random
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/7505a02a52bc140acd0fcd81985c0e0ad2a78f7d

Comment by Githook User [ 16/Sep/15 ]

Author:

{u'username': u'keithbostic', u'name': u'Keith Bostic', u'email': u'keith@wiredtiger.com'}

Message: SERVER-20385: the original use case of WT_CURSOR.next(random) was to
return a point in the tree for splitting the tree, and for that reason,
once we found a random page, we always returned the first key on that
page in order to make the split easy.

In MongoDB: first, $sample de-duplicates the keys WiredTiger returns,
that is, it ignores keys it's already returned; second, $sample allows
you to set the sample size. If you specify a sample size greater than
the number of leaf pages in the table, the de-duplication code catches
us because we can't return more unique keys than the number of leaf
pages in the table.

Remove the code that returns the first key of the page, always return
as a random a key as we can.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/ba9fcca4b317965b590ce4e67442f1a68a218bbe

Comment by Keith Bostic (Inactive) [ 15/Sep/15 ]

This is a WiredTiger problem, I've pushed a branch for review & merge. Apologies all around!

Comment by Geert Bosch [ 15/Sep/15 ]

I checked the dataset, and it seems the document count etc is valid.

Comment by Daniel Pasette (Inactive) [ 14/Sep/15 ]

charlie.swanson, I believe the issue that you were asking about was WT-2032. Resolved in 3.1.7. I'm wondering if there is something peculiar with how the data is laid out. Would need keith.bostic to take a look at the data files.

Comment by Matt Kangas [ 14/Sep/15 ]

charlie.swanson, there are 10k documents in the collection being sampled (see attached tarball). Zero writes were taking place at that time; the database was otherwise entirely idle.

Comment by Charlie Swanson [ 14/Sep/15 ]

So I now realize that log message is missing a word. It should be "after 100 attempts".

How many documents are in the collection being sampled? Were there any writes taking place at the time?

This error message indicates that the document returned from WiredTiger's random cursor was identical (in terms of _id), 100 times in a row. There is not a graceful way to recover from this, so we decided to just propagate this up to the user and have them try again.

geert.bosch, I remember you encountered a similar problem when hooking up the random cursor, where WiredTiger always returned the same document. Do you remember what version that was fixed in?

Generated at Thu Feb 08 03:54:03 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.