[SERVER-21887] $sample takes disproportionately long time on newly created collection Created: 14/Dec/15  Updated: 23/Nov/16  Resolved: 21/Dec/15

Status: Closed
Project: Core Server
Component/s: Aggregation Framework, WiredTiger
Affects Version/s: 3.2.0
Fix Version/s: 3.2.3, 3.3.0

Type: Bug Priority: Major - P3
Reporter: Asya Kamsky Assignee: Keith Bostic (Inactive)
Resolution: Done Votes: 0
Labels: code-only
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screenshot 2015-12-14 10.07.31.png     File metrics.2015-12-14T16-20-52Z-00000     PNG File perf-sample.png     File repro.js    
Issue Links:
Depends
Duplicate
is duplicated by SERVER-24710 Optimize $sample+$project Closed
Related
related to WT-2291 Random cursor walk inefficient in ski... Closed
is related to SERVER-23661 $sample takes disproportionately long... Closed
Backwards Compatibility: Fully Compatible
Operating System: Linux
Backport Completed:
Steps To Reproduce:
  1. Download the attached repro.js
  2. Run test with wiredTiger storage engine ($sample takes about 5200 milliseconds for me)

    python buildscripts/resmoke.py repro.js
    

  3. For a baseline of some sort, compare to timing on mmapv1 (about 550 milliseconds)

    python buildscripts/resmoke.py --storageEngine=mmapv1 repro.js
    

Participants:

 Description   

Even though SERVER-19182 and SERVER-19183 exist, I have a collection of one million documents on which $sample takes very long time. This shows even on collections with only 10K documents.

This only happens to collection that was just created. Restarting mongod process "fixes" this symptom.



 Comments   
Comment by Githook User [ 29/Jan/16 ]

Author:

{u'name': u'Ramon Fernandez', u'email': u'ramon@mongodb.com'}

Message: Import wiredtiger-wiredtiger-2.7.0-559-g07966a4.tar.gz from wiredtiger branch mongodb-3.2

ref: 3c2ad56..07966a4

WT-1517 schema format edge cases
WT-1801 Add a directory sync after rollback of a WT_SESSION::rename operation
WT-2060 Simplify aggregation of statistics
WT-2073 metadata cleanups
WT-2099 Seeing memory underflow messages
WT-2113 truncate01 sometimes fails
WT-2142 Connection cleanup in Python tests
WT-2177 Add an optional per-thread seed to random number generator
WT-2198 bulk load and column store appends
WT-2216 simplify row-store search loop slightly
WT-2225 New split code performance impact
WT-2231 pinned page cursor searches could check parent keys
WT-2235 wt printlog option without unicode
WT-2242 WiredTiger treats dead trees the same as other trees in eviction
WT-2244 Trigger in-memory splits sooner
WT-2245 WTPERF Truncate has no ability to catch up when it falls behind
WT-2246 column-store append searches the leaf page; the maximum record number fails CRUD operations
WT-2247 variable-length column-store in-memory page splits
WT-2256 WTPERFs throttle option fires in bursts
WT-2257 wtperf doesn't handle overriding workload config
WT-2258 WiredTiger preloads pages even when direct-IO is configured.
WT-2259 __wt_evict_file_exclusive_on() should clear WT_BTREE_NO_EVICTION on error
WT-2260 Workloads evict internal pages unexpectedly
WT-2262 Random sampling is skewed by tree shape
WT-2265 Wiredtiger related change in ppc64le specific code block in gcc.h
WT-2266 Add wtperf config to set if perf thresholds are fatal
WT-2267 Improve wtperf throttling implementation to provide steady load
WT-2269 wtperf should dump its config everytime it runs
WT-2272 Stress test assertion in the sweep server
WT-2275 broken DB after application crash
WT-2276 tool to decode checkpoint addr
WT-2277 Remove WT check against big-endian systems
WT-2279 Define WT_PAUSE(), WT_FULL_BARRIER(), etc when s390x is defined
WT-2281 wtperf smoke.sh fails on ppc64le
WT-2282 error in wt_txn_update_oldest verbose message test
WT-2283 retry in txn_update_oldest results in a hang
WT-2284 Repeated macro definition
WT-2285 configure should set BUFFER_ALIGNMENT_DEFAULT to 4kb on linux
WT-2287 WT_SESSION.rebalance
WT-2289 failure in fast key check
WT-2290 WT_SESSION.compact could be more effective.
WT-2291 Random cursor walk inefficient in skip list only trees
WT-2295 WT_SESSION.create does a full-scan of the main table
WT-2296 New log algorithm needs improving for sync/flush settings
WT-2297 Fix off-by-one error in Huffman config file parsing
WT-2299 upper-level WiredTiger code is reaching into the block manager
WT-2301 Add reading a range to wtperf
WT-2303 Build warning in wtperf
WT-2304 wtperf crash dumping config
WT-2305 Fix coverity scan issues on 23/12/2015
WT-2307 Internal page splits can corrupt cursor iteration
WT-2308 custom extractor for ref_cursors in join cursor
WT-2311 Support Sparc
WT-2312 re-creating a deleted column-store page can corrupt the in-memory tree
WT-2313 sweep-server: conn_dhandle.c, 610: dhandle != conn->cache->evict_file_next
WT-2314 page-swap error handling is inconsistent
WT-2316 stress test failure: WT_CURSOR.prev out-of-order returns
WT-2320 Only check copyright when cutting releases
WT-2321 WT-2321: race between eviction and worker threads on the eviction queue
WT-2326 Change WTPERF to use new memory allocation functions instead of the standard
WT-2328 schema drop does direct unlink, it should use a block manager interface.
WT-2331 Checking of search() result for reference cursors before join()
WT-2332 Bug in logging write-no-sync mode
WT-2333 Add a flag so drop doesn't block
WT-2335 NULL pointer crash in config_check_search with invalid configuration string
WT-2338 Disable using pre-allocated log files when backup cursor is open
WT-2339 format post-rebalance verify failure (stress run #11586)
WT-2340 Add logging guarantee assertions, whitespace
WT-2342 Enhance wtperf to support background create and drop operations
WT-2344 OS X compiler warning
WT-2347 Java: schema format edge cases
WT-2348 xargs -P isn't portable
WT-2355 Fix minor scratch buffer usage in logging
SERVER-21833 Compact does not release space to the system with WiredTiger
SERVER-21887 $sample takes disproportionately long time on newly created collection
SERVER-22064 Coverity analysis defect 77699: Unchecked return value
SERVER-21944 WiredTiger changes for 3.2.2
Branch: v3.2
https://github.com/mongodb/mongo/commit/5d6532f3d5227ff76f62c4810c98a4ef4d0c8c56

Comment by Keith Bostic (Inactive) [ 21/Dec/15 ]

The issues in the randomness of searches in skip-list only trees are resolved by WT-2291.

Comment by Keith Bostic (Inactive) [ 18/Dec/15 ]

The search itself is now fast enough, but there are still issues in the randomness of searches in skip-list only trees.

Comment by Githook User [ 16/Dec/15 ]

Author:

{u'username': u'agorrod', u'name': u'Alex Gorrod', u'email': u'alexander.gorrod@mongodb.com'}

Message: Merge pull request #2394 from wiredtiger/SERVER-21887-sample

WT-2291: fix for sampling in newly created trees.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/be6a40a5e88cd09b407e0a8eed34594bc5450dfd

Comment by Githook User [ 16/Dec/15 ]

Author:

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

Message: SERVER-21887: fix for sampling in newly created trees. Don't walk the
skiplist level 0, instead, randomly descend the skiplist from the first
level where we have at least two entries.
Branch: develop
https://github.com/wiredtiger/wiredtiger/commit/1bc6d34130a8903dd17d52567dabd08810e46b33

Comment by Alexander Gorrod [ 15/Dec/15 ]

Thanks asya That does indeed look like the likely cause. I have talked to keith.bostic about the likely cause, and we have a plan of attack. Thanks for the reproducer and detailed information.

Comment by Alexander Gorrod [ 14/Dec/15 ]

cc wiredtiger-escalation We need to get to the bottom of this one.

Comment by Lucas Hrabovsky (Inactive) [ 14/Dec/15 ]

Any way to detect that a collection is a "new collection"? If so, it would be trivial to make compass use client-side reservoir on the fly by just patching in 1 place and including in weekly patch release: https://github.com/mongodb-js/collection-sample

cc compass-escalation in case this pops up in CS tickets

Comment by Asya Kamsky [ 14/Dec/15 ]

I've confirmed that this happens to newly created (inserted into) large collections only - restarting mongod always "clears" the problem.

Comment by Charlie Swanson [ 14/Dec/15 ]

I've attached a reproduction script, and assigned to michael.cahill. Let me know if there's anything else I can help with!

Comment by Charlie Swanson [ 14/Dec/15 ]

Attached a nice graph of where the time is going. It seems like we're stuck in __wt_row_random. This confirms it's internal to WiredTiger. I'll get a nice reproduction and pass the information along to the WiredTiger folks.

Comment by Asya Kamsky [ 14/Dec/15 ]

Testing whether only newly created collection displays this symptom (will restart server then to see if that resolves it again).

Comment by Asya Kamsky [ 14/Dec/15 ]

3.2.0

Comment by Charlie Swanson [ 14/Dec/15 ]

What version of mongod is this?

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