[SERVER-13216] potential v2.6.0-rc1-pre- $in count() performance - MongoDB Jira

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Critical - P2
Resolution: Duplicate
Affects Version/s: 2.6.0-rc1
Fix Version/s: None
Component/s: Performance, Querying
Labels:
- query

Operating System:
ALL

Description

Given a sample data set (attached dump file) of 1M documents we've (me and sharon.elkayam@10gen.com ) run into severe performance issues while executing the following query:

var b = [];

for( var c = 0; c < 200000; c+=2 ) {

	b.push(c)

db.testp.find({_id:{$in: b}}).count()

over version:

2014-03-14T20:36:04.669+0100 [initandlisten] db version v2.6.0-rc1-pre-

2014-03-14T20:36:04.669+0100 [initandlisten] git version: aa02cde1baf6bdb7840ac007f0a5603026409b9e

2014-03-14T20:36:04.669+0100 [initandlisten] OpenSSL version: OpenSSL 0.9.8y 5 Feb 2013

2014-03-14T20:36:04.669+0100 [initandlisten] build info: Darwin nair.local 13.1.0 Darwin Kernel Version 13.1.0: Thu Jan 16 19:40:37 PST 2014; root:xnu-2422.90.20~2/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49

we get extermely bad performance -> 498812ms

log messsage:

...

2014-03-14T20:59:17.398+0100 [initandlisten] connection accepted from 127.0.0.1:60379 #11 (3 connections now open)

2014-03-14T21:01:44.782+0100 [conn9] command test.$cmd command: { $msg: "query not recording (too large)" } keyUpdates:0 numYields:1 locks(micros) r:499305215 reslen:48 498812ms

2014-03-14T21:01:44.782+0100 [conn11] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after cursors: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after indexCounters: 0, after locks: 0, after network: 0, after opcounters: 0, after opcountersRepl: 0, after recordStats: 138920, at end: 138920 }

2014-03-14T21:01:44.782+0100 [conn11] command admin.$cmd command: { serverStatus: 1.0 } keyUpdates:0 numYields:0 locks(micros) r:29 reslen:3461 147376ms

2014-03-14T21:01:44.782+0100 [conn4] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after cursors: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after indexCounters: 0, after locks: 0, after network: 0, after opcounters: 0, after opcountersRepl: 0, after recordStats: 468441, at end: 468441 }

2014-03-14T21:01:44.782+0100 [conn4] command admin.$cmd command: { serverStatus: 1 } ntoreturn:1 keyUpdates:0 numYields:0 locks(micros) r:42 reslen:3461 496934ms

...

blocking all other operations (not yielding)

while running version 2.5.3-pre the same query executes in 550ms

2014-03-14T21:11:17.365+0100 [initandlisten] ** NOTE: This is a development version (2.5.3-pre-) of MongoDB.

2014-03-14T21:11:17.365+0100 [initandlisten] **       Not recommended for production.

2014-03-14T21:11:17.365+0100 [initandlisten]

2014-03-14T21:11:17.365+0100 [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000

2014-03-14T21:11:17.365+0100 [initandlisten]

2014-03-14T21:11:17.365+0100 [initandlisten] db version v2.5.3-pre-

2014-03-14T21:11:17.365+0100 [initandlisten] git version: abc6784faa11658b485d9b69f483ee0279c0c1f3

2014-03-14T21:11:17.365+0100 [initandlisten] build info: Darwin nair.local 12.5.0 Darwin Kernel Version 12.5.0: Mon Jul 29 16:33:49 PDT 2013; root:xnu-2050.48.11~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49

2014-03-14T21:11:17.365+0100 [initandlisten] allocator: tcmalloc

2014-03-14T21:11:17.365+0100 [initandlisten] options: { dbpath: "/Users/norberto/sandbox/2.6_slowcount/db" }

2014-03-14T21:11:17.366+0100 [initandlisten] journal dir=/Users/norberto/sandbox/2.6_slowcount/db/journal

2014-03-14T21:11:17.366+0100 [initandlisten] recover : no journal files present, no recovery needed

2014-03-14T21:11:17.485+0100 [initandlisten] have free list for local.$freelist

2014-03-14T21:11:17.510+0100 [initandlisten] have free list for test.$freelist

2014-03-14T21:11:17.518+0100 [initandlisten] waiting for connections on port 27017

2014-03-14T21:11:27.249+0100 [initandlisten] connection accepted from 127.0.0.1:60599 #1 (1 connection now open)

2014-03-14T21:12:08.734+0100 [conn1] warning: log line attempted (922k) over max size (10k), printing beginning and end ... command test.$cmd command: { count: "testp", query: { _id: { $in: [ 0.0, 2.0, 4.0, 6.0, 8.0, 10.0, 12.0, 14.0, 16.0, 18.0, 20.0, 22.0, 24.0, 26.0, 28.0, 30.0, 32.0, 34.0, 36.0, 38.0, 40.0, 42.0, 44.0, 46.0, 48.0, 50.0, 52.0, 54.0, 56.0, 58.0, 60.0, 62.0, 64.0, 66.0, 68.0, 70.0, 72.0, 74.0, 76.0, 78.0, 80.0, 82.0, 84.0, 86.0, 88.0, 90.0, 92.0, 94.0, 96.0, 98.0, 100.0, 102.0, 104.0, 106.0, 108.0, 110.0, 112.0, 114.0, 116.0, 118.0, 120.0, 122.0, 124.0, 126.0, 128.0, 130.0, 132.0, 134.0, 136.0, 138.0, 140.0, 142.0, 144.0, 146.0, 148.0, 150.0, 152.0, 154.0, 156.0, 158.0, 160.0, 162.0, 164.0, 166.0, 168.0, 170.0, 172.0, 174.0, 176.0, 178.0, 180.0, 182.0, 184.0, 186.0, 188.0, 190.0, 192.0, 194.0, 196.0, 198.0, 200.0, 202.0, 204.0, 206.0, 208.0, 210.0, 212.0, 214.0, 216.0, 218.0, 220.0, 222.0, 224.0, 226.0, 228.0, 230.0, 232.0, 234.0, 236.0, 238.0, 240.0, 242.0, 244.0, 246.0, 248.0, 250.0, 252.0, 254.0, 256.0, 258.0, 260.0, 262.0, 264.0, 266.0, 268.0, 270.0, 272.0, 274.0, 276.0, 278.0, 280.0, 282.0, 284.0, 286.0, 288.0, 290.0, 292.0, 294.0, 296.0, 298.0, 300.0, 302.0, 304.0, 306.0, 308.0, 310.0, 312.0, 314.0, 316.0, 318.0, 320.0, 322.0, 324.0, 326.0, 328.0, 330.0, 332.0, 334.0, 336.0, 338.0, 340.0, 342.0, 344.0, 346.0, 348.0, 350.0, 352.0, 354.0, 356.0, 358.0, 360.0, 362.0, 364.0, 366.0, 368.0, 370.0, 372.0, 374.0, 376.0, 378.0, 380.0, 382.0, 384.0, 386.0, 388.0, 390.0, 392.0, 394.0, 396.0, 398.0, 400.0, 402.0, 404.0, 406.0, 408.0, 410.0, 412.0, 414.0, 416.0, 418.0, 420.0, 422.0, 424.0, 426.0, 428.0, 430.0, 432.0, 434.0, 436.0, 438.0, 440.0, 442.0, 444.0, 446.0, 448.0, 450.0, 452.0, 454.0, 456.0, 458.0, 460.0, 462.0, 464.0, 466.0, 468.0, 470.0, 472.0, 474.0, 476.0, 478.0, 480.0, 482.0, 484.0, 486.0, 488.0, 490.0, 492.0, 494.0, 496.0, 498.0, 500.0, 502.0, 504.0, 506.0, 508.0, 510.0, 512.0, 514.0, 516.0, 518.0, 520.0, 522.0, 524.0, 526.0, 528.0, 530.0, 532.0, 534.0, 536.0, 538.0, 540.0, 542.0, 544.0, 546.0, 548.0, 550.0, 552.0, 554.0, 556.0, 558.0, 560.0, 562.0, 564.0, 566.0, 568.0, 570.0, 572.0, 574.0, 576.0, 578.0, 580.0, 582.0, 584.0, 586.0, 588.0, 590.0, 592.0, 594.0, 596.0, 598.0, 600.0, 602.0, 604.0, 606.0, 608.0, 610.0, 612.0, 614.0, 616.0, 618.0, 620.0, 622.0, 624.0, 626.0, 628.0, 630.0, 632.0, 634.0, 636.0, 638.0, 640.0, 642.0, 644.0, 646.0, 648.0, 650.0, 652.0, 654.0, 656.0, 658.0, 660.0, 662.0, 664.0, 666.0, 668.0, 670.0, 672.0, 674.0, 676.0, 678.0, 680.0, 682.0, 684.0, 686.0, 688.0, 690.0, 692.0, 694.0, 696.0, 698.0, 700.0, 702.0, 704.0, 706.0, 708.0, 710.0, 712.0, 714.0, 716.0, 718.0, 720.0, 722.0, 724.0, 726.0, 728.0, 730.0, 732.0, 734.0, 736.0, 738.0, 740.0, 742.0, 744.0, 746.0, 748.0, 750.0, 752.0, 754.0, 756.0, 758.0, 760.0, 762.0, 764.0, 766.0, 768.0, 770.0, 772.0, 774.0, 776.0, 778.0, 780.0, 782.0, 784.0, 786.0, 788.0, 790.0, 792.0, 794.0, 796.0, 798.0, 800.0, 802.0, 804.0, 806.0, 808.0, 810.0, 812.0, 814.0, 816.0, 818.0, 820.0, 822.0, 824.0, 826.0, 828.0, 830.0, 832.0, 834.0, 836.0, 838.0, 840.0, 842.0, 844.0, 846.0, 848.0, 850.0, 852.0, 854.0, 856.0, 858.0, 860.0, 862.0, 864.0, 866.0, 868.0, 870.0, 872.0, 874.0, 876.0, 878.0, 880.0, 882.0, 884.0, 886.0, 888.0, 890.0, 892.0, 894.0, 896.0, 898.0, 900.0, 902.0, 904.0, 906.0, 908.0, 910.0, 912.0, 914.0, 916.0, 918.0, 920.0, 922.0, 924.0, 926.0, 928.0, 930.0, 932.0, 934.0, 936.0, 938.0, 940.0, 942.0, 944.0, 946.0, 948.0, 950.0, 952.0, 954.0, 956.0, 958.0, 960.0, 962.0, 964.0, 966.0, 968.0, 970.0 .......... 199334.0, 199336.0, 199338.0, 199340.0, 199342.0, 199344.0, 199346.0, 199348.0, 199350.0, 199352.0, 199354.0, 199356.0, 199358.0, 199360.0, 199362.0, 199364.0, 199366.0, 199368.0, 199370.0, 199372.0, 199374.0, 199376.0, 199378.0, 199380.0, 199382.0, 199384.0, 199386.0, 199388.0, 199390.0, 199392.0, 199394.0, 199396.0, 199398.0, 199400.0, 199402.0, 199404.0, 199406.0, 199408.0, 199410.0, 199412.0, 199414.0, 199416.0, 199418.0, 199420.0, 199422.0, 199424.0, 199426.0, 199428.0, 199430.0, 199432.0, 199434.0, 199436.0, 199438.0, 199440.0, 199442.0, 199444.0, 199446.0, 199448.0, 199450.0, 199452.0, 199454.0, 199456.0, 199458.0, 199460.0, 199462.0, 199464.0, 199466.0, 199468.0, 199470.0, 199472.0, 199474.0, 199476.0, 199478.0, 199480.0, 199482.0, 199484.0, 199486.0, 199488.0, 199490.0, 199492.0, 199494.0, 199496.0, 199498.0, 199500.0, 199502.0, 199504.0, 199506.0, 199508.0, 199510.0, 199512.0, 199514.0, 199516.0, 199518.0, 199520.0, 199522.0, 199524.0, 199526.0, 199528.0, 199530.0, 199532.0, 199534.0, 199536.0, 199538.0, 199540.0, 199542.0, 199544.0, 199546.0, 199548.0, 199550.0, 199552.0, 199554.0, 199556.0, 199558.0, 199560.0, 199562.0, 199564.0, 199566.0, 199568.0, 199570.0, 199572.0, 199574.0, 199576.0, 199578.0, 199580.0, 199582.0, 199584.0, 199586.0, 199588.0, 199590.0, 199592.0, 199594.0, 199596.0, 199598.0, 199600.0, 199602.0, 199604.0, 199606.0, 199608.0, 199610.0, 199612.0, 199614.0, 199616.0, 199618.0, 199620.0, 199622.0, 199624.0, 199626.0, 199628.0, 199630.0, 199632.0, 199634.0, 199636.0, 199638.0, 199640.0, 199642.0, 199644.0, 199646.0, 199648.0, 199650.0, 199652.0, 199654.0, 199656.0, 199658.0, 199660.0, 199662.0, 199664.0, 199666.0, 199668.0, 199670.0, 199672.0, 199674.0, 199676.0, 199678.0, 199680.0, 199682.0, 199684.0, 199686.0, 199688.0, 199690.0, 199692.0, 199694.0, 199696.0, 199698.0, 199700.0, 199702.0, 199704.0, 199706.0, 199708.0, 199710.0, 199712.0, 199714.0, 199716.0, 199718.0, 199720.0, 199722.0, 199724.0, 199726.0, 199728.0, 199730.0, 199732.0, 199734.0, 199736.0, 199738.0, 199740.0, 199742.0, 199744.0, 199746.0, 199748.0, 199750.0, 199752.0, 199754.0, 199756.0, 199758.0, 199760.0, 199762.0, 199764.0, 199766.0, 199768.0, 199770.0, 199772.0, 199774.0, 199776.0, 199778.0, 199780.0, 199782.0, 199784.0, 199786.0, 199788.0, 199790.0, 199792.0, 199794.0, 199796.0, 199798.0, 199800.0, 199802.0, 199804.0, 199806.0, 199808.0, 199810.0, 199812.0, 199814.0, 199816.0, 199818.0, 199820.0, 199822.0, 199824.0, 199826.0, 199828.0, 199830.0, 199832.0, 199834.0, 199836.0, 199838.0, 199840.0, 199842.0, 199844.0, 199846.0, 199848.0, 199850.0, 199852.0, 199854.0, 199856.0, 199858.0, 199860.0, 199862.0, 199864.0, 199866.0, 199868.0, 199870.0, 199872.0, 199874.0, 199876.0, 199878.0, 199880.0, 199882.0, 199884.0, 199886.0, 199888.0, 199890.0, 199892.0, 199894.0, 199896.0, 199898.0, 199900.0, 199902.0, 199904.0, 199906.0, 199908.0, 199910.0, 199912.0, 199914.0, 199916.0, 199918.0, 199920.0, 199922.0, 199924.0, 199926.0, 199928.0, 199930.0, 199932.0, 199934.0, 199936.0, 199938.0, 199940.0, 199942.0, 199944.0, 199946.0, 199948.0, 199950.0, 199952.0, 199954.0, 199956.0, 199958.0, 199960.0, 199962.0, 199964.0, 199966.0, 199968.0, 199970.0, 199972.0, 199974.0, 199976.0, 199978.0, 199980.0, 199982.0, 199984.0, 199986.0, 199988.0, 199990.0, 199992.0, 199994.0, 199996.0, 199998.0 ] } }, fields: {} } ntoreturn:1 keyUpdates:0 locks(micros) r:550306 reslen:48 550ms

2014-03-14T21:12:17.530+0100 [clientcursormon] mem (MB) res:75 virt:3104

2014-03-14T21:12:17.530+0100 [clientcursormon]  mapped (incl journal view):576

2014-03-14T21:12:17.530+0100 [clientcursormon]  connections:1

running again 2.6.0-rc1 with extended verbosity I got this:

norberto:2.6_slowcount/ $ mongod --dbpath db -vvvvvv                                                                                                                                             [21:16:19]

2014-03-14T21:16:28.651+0100 [DataFileSync] BackgroundJob starting: DataFileSync

2014-03-14T21:16:28.651+0100 shardObjTest passed

2014-03-14T21:16:28.651+0100 isInRangeTest passed

2014-03-14T21:16:28.651+0100 shardKeyTest passed

2014-03-14T21:16:28.651+0100 [initandlisten] MongoDB starting : pid=66958 port=27017 dbpath=db 64-bit host=nair.local

2014-03-14T21:16:28.651+0100 [initandlisten]

2014-03-14T21:16:28.651+0100 [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000

2014-03-14T21:16:28.651+0100 [initandlisten] db version v2.6.0-rc1-pre-

2014-03-14T21:16:28.651+0100 [initandlisten] git version: aa02cde1baf6bdb7840ac007f0a5603026409b9e

2014-03-14T21:16:28.652+0100 [initandlisten] OpenSSL version: OpenSSL 0.9.8y 5 Feb 2013

2014-03-14T21:16:28.652+0100 [initandlisten] build info: Darwin nair.local 13.1.0 Darwin Kernel Version 13.1.0: Thu Jan 16 19:40:37 PST 2014; root:xnu-2422.90.20~2/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49

2014-03-14T21:16:28.652+0100 [initandlisten] allocator: tcmalloc

2014-03-14T21:16:28.652+0100 [initandlisten] options: { storage: { dbPath: "db" }, vvvvvv: true }

2014-03-14T21:16:28.652+0100 [initandlisten] journal dir=db/journal

2014-03-14T21:16:28.652+0100 [initandlisten] recover begin

2014-03-14T21:16:28.652+0100 [initandlisten] info no lsn file in journal/ directory

2014-03-14T21:16:28.652+0100 [initandlisten] recover lsn: 0

2014-03-14T21:16:28.652+0100 [initandlisten] recover db/journal/j._0

2014-03-14T21:16:28.652+0100 [initandlisten] mmf open db/local.ns

2014-03-14T21:16:28.652+0100 [initandlisten] mmf finishOpening 0x105000000 /Users/norberto/sandbox/2.6_slowcount/db/local.ns len:16777216

2014-03-14T21:16:28.654+0100 [initandlisten] mmf open db/test.ns

2014-03-14T21:16:28.654+0100 [initandlisten] mmf finishOpening 0x107000000 /Users/norberto/sandbox/2.6_slowcount/db/test.ns len:16777216

2014-03-14T21:16:28.655+0100 [initandlisten] mmf open db/local.0

2014-03-14T21:16:28.655+0100 [initandlisten] mmf finishOpening 0x109000000 /Users/norberto/sandbox/2.6_slowcount/db/local.0 len:67108864

2014-03-14T21:16:28.659+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/local.ns

2014-03-14T21:16:28.659+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.659+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.659+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:28.659+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.659+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.ns

2014-03-14T21:16:28.659+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.659+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.659+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms

2014-03-14T21:16:28.659+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.659+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/local.0

2014-03-14T21:16:28.663+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.663+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.663+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 1 n:1 0ms

2014-03-14T21:16:28.663+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.663+0100 [initandlisten] recover cleaning up

2014-03-14T21:16:28.663+0100 [initandlisten] removeJournalFiles

2014-03-14T21:16:28.664+0100 [initandlisten] removeJournalFiles end

2014-03-14T21:16:28.664+0100 [initandlisten] recover done

2014-03-14T21:16:28.677+0100 [initandlisten] opening db:  local

2014-03-14T21:16:28.677+0100 [initandlisten] mmf open db/local.ns

2014-03-14T21:16:28.677+0100 [initandlisten] mmf finishOpening 0x105000000 /Users/norberto/sandbox/2.6_slowcount/db/local.ns len:16777216

2014-03-14T21:16:28.679+0100 [initandlisten] mmf open db/local.0

2014-03-14T21:16:28.679+0100 [initandlisten] mmf finishOpening 0x107000000 /Users/norberto/sandbox/2.6_slowcount/db/local.0 len:67108864

2014-03-14T21:16:28.679+0100 [initandlisten] enter repairDatabases (to check pdfile version #)

2014-03-14T21:16:28.679+0100 [initandlisten] 	local

2014-03-14T21:16:28.679+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/local.0

2014-03-14T21:16:28.679+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.680+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.680+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms

2014-03-14T21:16:28.680+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.680+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/local.ns

2014-03-14T21:16:28.680+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.680+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.680+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 1 n:1 0ms

2014-03-14T21:16:28.680+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.680+0100 [initandlisten] 	test

2014-03-14T21:16:28.680+0100 [initandlisten] opening db:  test

2014-03-14T21:16:28.680+0100 [initandlisten] mmf open db/test.ns

2014-03-14T21:16:28.680+0100 [initandlisten] mmf finishOpening 0x105000000 /Users/norberto/sandbox/2.6_slowcount/db/test.ns len:16777216

2014-03-14T21:16:28.681+0100 [initandlisten] mmf open db/test.0

2014-03-14T21:16:28.681+0100 [initandlisten] mmf finishOpening 0x107000000 /Users/norberto/sandbox/2.6_slowcount/db/test.0 len:67108864

2014-03-14T21:16:28.685+0100 [initandlisten] mmf open db/test.1

2014-03-14T21:16:28.685+0100 [initandlisten] mmf finishOpening 0x10f000000 /Users/norberto/sandbox/2.6_slowcount/db/test.1 len:134217728

2014-03-14T21:16:28.693+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.0

2014-03-14T21:16:28.693+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.693+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.693+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms

2014-03-14T21:16:28.693+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.693+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.1

2014-03-14T21:16:28.693+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.693+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.693+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 1 n:1 0ms

2014-03-14T21:16:28.693+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.693+0100 [initandlisten] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.ns

2014-03-14T21:16:28.693+0100 [initandlisten] _groupCommit

2014-03-14T21:16:28.693+0100 [initandlisten] journal REMAPPRIVATEVIEW

2014-03-14T21:16:28.693+0100 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms

2014-03-14T21:16:28.693+0100 [initandlisten] groupCommit end

2014-03-14T21:16:28.693+0100 [initandlisten] done repairDatabases

2014-03-14T21:16:28.693+0100 [initandlisten] opening db:  admin

2014-03-14T21:16:28.693+0100 [initandlisten] query admin.system.roles planSummary: EOF ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) W:72 r:44 nreturned:0 reslen:20 0ms

2014-03-14T21:16:28.693+0100 [snapshot] BackgroundJob starting: snapshot

2014-03-14T21:16:28.693+0100 [ClientCursorMonitor] BackgroundJob starting: ClientCursorMonitor

2014-03-14T21:16:28.693+0100 [PeriodicTaskRunner] BackgroundJob starting: PeriodicTaskRunner

2014-03-14T21:16:28.694+0100 [TTLMonitor] BackgroundJob starting: TTLMonitor

2014-03-14T21:16:28.694+0100 [IndexRebuilder] BackgroundJob starting: IndexRebuilder

2014-03-14T21:16:28.694+0100 [initandlisten] fd limit hard:9223372036854775807 soft:256 max conn: 204

2014-03-14T21:16:28.694+0100 [IndexRebuilder] opening db:  local

2014-03-14T21:16:28.694+0100 [IndexRebuilder] mmf open db/local.ns

2014-03-14T21:16:28.694+0100 [IndexRebuilder] mmf finishOpening 0x105189000 /Users/norberto/sandbox/2.6_slowcount/db/local.ns len:16777216

2014-03-14T21:16:28.695+0100 [IndexRebuilder] mmf open db/local.0

2014-03-14T21:16:28.695+0100 [IndexRebuilder] mmf finishOpening 0x107189000 /Users/norberto/sandbox/2.6_slowcount/db/local.0 len:67108864

2014-03-14T21:16:28.696+0100 [initandlisten] run command local.$cmd { create: "startup_log", size: 10485760, capped: true }

2014-03-14T21:16:28.696+0100 [initandlisten] create collection local.startup_log { size: 10485760, capped: true }

2014-03-14T21:16:28.696+0100 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0 numYields:0  reslen:75 0ms

2014-03-14T21:16:28.696+0100 [initandlisten] info PageFaultRetryableSection will not yield, already locked upon reaching

2014-03-14T21:16:28.696+0100 [initandlisten] insert local.startup_log ninserted:1 keyUpdates:0 numYields:0  0ms

2014-03-14T21:16:28.697+0100 [initandlisten] waiting for connections on port 27017

2014-03-14T21:16:28.703+0100 [IndexRebuilder] opening db:  test

2014-03-14T21:16:28.703+0100 [IndexRebuilder] mmf open db/test.ns

2014-03-14T21:16:28.704+0100 [IndexRebuilder] mmf finishOpening 0x10f189000 /Users/norberto/sandbox/2.6_slowcount/db/test.ns len:16777216

2014-03-14T21:16:28.705+0100 [IndexRebuilder] mmf open db/test.0

2014-03-14T21:16:28.705+0100 [IndexRebuilder] mmf finishOpening 0x111189000 /Users/norberto/sandbox/2.6_slowcount/db/test.0 len:67108864

2014-03-14T21:16:28.709+0100 [IndexRebuilder] mmf open db/test.1

2014-03-14T21:16:28.709+0100 [IndexRebuilder] mmf finishOpening 0x119189000 /Users/norberto/sandbox/2.6_slowcount/db/test.1 len:134217728

2014-03-14T21:16:28.724+0100 [IndexRebuilder] IndexRebuilder::checkNS: local.startup_log

2014-03-14T21:16:28.724+0100 [IndexRebuilder] IndexRebuilder::checkNS: local.system.indexes

2014-03-14T21:16:28.724+0100 [IndexRebuilder] IndexRebuilder::checkNS: local.system.namespaces

2014-03-14T21:16:28.724+0100 [IndexRebuilder] IndexRebuilder::checkNS: test.testp

2014-03-14T21:16:28.725+0100 [IndexRebuilder] IndexRebuilder::checkNS: test.system.indexes

2014-03-14T21:16:28.725+0100 [IndexRebuilder] IndexRebuilder::checkNS: test.system.namespaces

2014-03-14T21:16:28.725+0100 [IndexRebuilder] checking complete

2014-03-14T21:16:28.783+0100 [journal] lsn set 0

2014-03-14T21:16:28.783+0100 [journal] journal WRITETODATAFILES 1

2014-03-14T21:16:28.783+0100 [journal] journal WRITETODATAFILES 2

2014-03-14T21:16:28.783+0100 [journal] journal WRITETODATAFILES 0.197ms

2014-03-14T21:16:29.729+0100 [journal] _groupCommit

2014-03-14T21:16:29.729+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:29.729+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:29.732+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 2ms

2014-03-14T21:16:29.732+0100 [journal] groupCommit end

2014-03-14T21:16:30.782+0100 [journal] _groupCommit

2014-03-14T21:16:30.782+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:30.782+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:30.782+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:30.782+0100 [journal] groupCommit end

2014-03-14T21:16:31.830+0100 [journal] _groupCommit

2014-03-14T21:16:31.830+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:31.830+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:31.830+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:31.830+0100 [journal] groupCommit end

2014-03-14T21:16:32.880+0100 [journal] _groupCommit

2014-03-14T21:16:32.880+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:32.880+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:32.880+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:32.880+0100 [journal] groupCommit end

2014-03-14T21:16:33.929+0100 [journal] _groupCommit

2014-03-14T21:16:33.929+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:33.929+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:33.929+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:33.930+0100 [journal] groupCommit end

2014-03-14T21:16:34.974+0100 [journal] _groupCommit

2014-03-14T21:16:34.975+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:34.975+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:34.975+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:34.975+0100 [journal] groupCommit end

2014-03-14T21:16:36.023+0100 [journal] _groupCommit

2014-03-14T21:16:36.023+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:36.023+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:36.023+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:36.023+0100 [journal] groupCommit end

2014-03-14T21:16:36.722+0100 [initandlisten] connection accepted from 127.0.0.1:60695 #1 (1 connection now open)

2014-03-14T21:16:36.722+0100 [conn1] run command admin.$cmd { whatsmyuri: 1 }

2014-03-14T21:16:36.722+0100 [conn1] command admin.$cmd command: { whatsmyuri: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:62 0ms

2014-03-14T21:16:36.725+0100 [conn1] run command admin.$cmd { buildinfo: 1.0 }

2014-03-14T21:16:36.725+0100 [conn1] command admin.$cmd command: { buildinfo: 1.0 } keyUpdates:0 numYields:0  reslen:871 0ms

2014-03-14T21:16:36.728+0100 [conn1] run command admin.$cmd { getLog: "startupWarnings" }

2014-03-14T21:16:36.728+0100 [conn1] command: { getLog: "startupWarnings" }

2014-03-14T21:16:36.728+0100 [conn1] command admin.$cmd command: { getLog: "startupWarnings" } keyUpdates:0 numYields:0  reslen:257 0ms

2014-03-14T21:16:36.728+0100 [conn1] run command admin.$cmd { serverStatus: 1.0 }

2014-03-14T21:16:36.729+0100 [conn1] command admin.$cmd command: { serverStatus: 1.0 } keyUpdates:0 numYields:0 locks(micros) r:11 reslen:3137 0ms

2014-03-14T21:16:36.729+0100 [conn1] run command admin.$cmd { buildinfo: 1.0 }

2014-03-14T21:16:36.729+0100 [conn1] command admin.$cmd command: { buildinfo: 1.0 } keyUpdates:0 numYields:0  reslen:871 0ms

2014-03-14T21:16:36.729+0100 [conn1] run command admin.$cmd { replSetGetStatus: 1.0 }

2014-03-14T21:16:36.729+0100 [conn1] command: { replSetGetStatus: 1.0 }

2014-03-14T21:16:36.729+0100 [conn1] command admin.$cmd command: { replSetGetStatus: 1.0 } keyUpdates:0 numYields:0  reslen:76 0ms

2014-03-14T21:16:36.729+0100 [conn1] run command test.$cmd { isMaster: 1.0 }

2014-03-14T21:16:36.730+0100 [conn1] command test.$cmd command: { isMaster: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms

2014-03-14T21:16:37.073+0100 [journal] _groupCommit

2014-03-14T21:16:37.073+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:37.073+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:37.073+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:37.073+0100 [journal] groupCommit end

2014-03-14T21:16:38.124+0100 [journal] _groupCommit

2014-03-14T21:16:38.124+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:38.124+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:38.124+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:38.124+0100 [journal] groupCommit end

2014-03-14T21:16:39.173+0100 [journal] _groupCommit

2014-03-14T21:16:39.173+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:39.173+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:39.173+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:39.173+0100 [journal] groupCommit end

2014-03-14T21:16:40.222+0100 [journal] _groupCommit

2014-03-14T21:16:40.222+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:40.222+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:40.222+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:40.222+0100 [journal] groupCommit end

2014-03-14T21:16:41.274+0100 [journal] _groupCommit

2014-03-14T21:16:41.274+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:41.274+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:41.274+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:41.274+0100 [journal] groupCommit end

2014-03-14T21:16:42.312+0100 [journal] _groupCommit

2014-03-14T21:16:42.312+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:42.312+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:42.312+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:42.312+0100 [journal] groupCommit end

2014-03-14T21:16:43.355+0100 [journal] _groupCommit

2014-03-14T21:16:43.356+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:43.356+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:43.356+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:43.356+0100 [journal] groupCommit end

2014-03-14T21:16:44.396+0100 [journal] _groupCommit

2014-03-14T21:16:44.396+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:44.396+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:44.396+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:44.396+0100 [journal] groupCommit end

2014-03-14T21:16:45.438+0100 [journal] _groupCommit

2014-03-14T21:16:45.438+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:45.438+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:45.438+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:45.439+0100 [journal] groupCommit end

2014-03-14T21:16:46.477+0100 [journal] _groupCommit

2014-03-14T21:16:46.477+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:46.477+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:46.477+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:46.477+0100 [journal] groupCommit end

2014-03-14T21:16:47.521+0100 [journal] _groupCommit

2014-03-14T21:16:47.521+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:47.521+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:47.521+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:47.521+0100 [journal] groupCommit end

2014-03-14T21:16:48.567+0100 [journal] _groupCommit

2014-03-14T21:16:48.568+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:48.568+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:48.568+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:48.568+0100 [journal] groupCommit end

2014-03-14T21:16:49.609+0100 [journal] _groupCommit

2014-03-14T21:16:49.609+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:49.609+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:49.609+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:49.609+0100 [journal] groupCommit end

2014-03-14T21:16:50.126+0100 [conn1] run command admin.$cmd { serverStatus: 1.0 }

2014-03-14T21:16:50.126+0100 [conn1] command admin.$cmd command: { serverStatus: 1.0 } keyUpdates:0 numYields:0 locks(micros) r:20 reslen:3137 0ms

2014-03-14T21:16:50.127+0100 [conn1] run command admin.$cmd { buildinfo: 1.0 }

2014-03-14T21:16:50.127+0100 [conn1] command admin.$cmd command: { buildinfo: 1.0 } keyUpdates:0 numYields:0  reslen:871 0ms

2014-03-14T21:16:50.127+0100 [conn1] run command admin.$cmd { replSetGetStatus: 1.0 }

2014-03-14T21:16:50.128+0100 [conn1] command: { replSetGetStatus: 1.0 }

2014-03-14T21:16:50.128+0100 [conn1] command admin.$cmd command: { replSetGetStatus: 1.0 } keyUpdates:0 numYields:0  reslen:76 0ms

2014-03-14T21:16:50.128+0100 [conn1] run command test.$cmd { isMaster: 1.0 }

2014-03-14T21:16:50.128+0100 [conn1] command test.$cmd command: { isMaster: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms

2014-03-14T21:16:50.132+0100 [conn1] run command admin.$cmd { serverStatus: 1.0 }

2014-03-14T21:16:50.132+0100 [conn1] command admin.$cmd command: { serverStatus: 1.0 } keyUpdates:0 numYields:0 locks(micros) r:10 reslen:3137 0ms

2014-03-14T21:16:50.133+0100 [conn1] run command admin.$cmd { buildinfo: 1.0 }

2014-03-14T21:16:50.133+0100 [conn1] command admin.$cmd command: { buildinfo: 1.0 } keyUpdates:0 numYields:0  reslen:871 0ms

2014-03-14T21:16:50.133+0100 [conn1] run command admin.$cmd { replSetGetStatus: 1.0 }

2014-03-14T21:16:50.133+0100 [conn1] command: { replSetGetStatus: 1.0 }

2014-03-14T21:16:50.133+0100 [conn1] command admin.$cmd command: { replSetGetStatus: 1.0 } keyUpdates:0 numYields:0  reslen:76 0ms

2014-03-14T21:16:50.133+0100 [conn1] run command test.$cmd { isMaster: 1.0 }

2014-03-14T21:16:50.133+0100 [conn1] command test.$cmd command: { isMaster: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms

2014-03-14T21:16:50.657+0100 [journal] _groupCommit

2014-03-14T21:16:50.657+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:50.657+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:50.657+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:50.657+0100 [journal] groupCommit end

2014-03-14T21:16:51.708+0100 [journal] _groupCommit

2014-03-14T21:16:51.708+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:51.708+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:51.708+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:16:51.708+0100 [journal] groupCommit end

2014-03-14T21:16:52.756+0100 [journal] _groupCommit

2014-03-14T21:16:52.756+0100 [journal] _groupCommit upgrade

2014-03-14T21:16:52.756+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:16:52.756+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:16:52.756+0100 [journal] groupCommit end

2014-03-14T21:16:53.099+0100 [conn1] warning: log line attempted (922k) over max size (10k), printing beginning and end ... run command test.$cmd { count: "testp", query: { _id: { $in: [ 0.0, 2.0, 4.0, 6.0, 8.0, 10.0, 12.0, 14.0, 16.0, 18.0, 20.0, 22.0, 24.0, 26.0, 28.0, 30.0, 32.0, 34.0, 36.0, 38.0, 40.0, 42.0, 44.0, 46.0, 48.0, 50.0, 52.0, 54.0, 56.0, 58.0, 60.0, 62.0, 64.0, 66.0, 68.0, 70.0, 72.0, 74.0, 76.0, 78.0, 80.0, 82.0, 84.0, 86.0, 88.0, 90.0, 92.0, 94.0, 96.0, 98.0, 100.0, 102.0, 104.0, 106.0, 108.0, 110.0, 112.0, 114.0, 116.0, 118.0, 120.0, 122.0, 124.0, 126.0, 128.0, 130.0, 132.0, 134.0, 136.0, 138.0, 140.0, 142.0, 144.0, 146.0, 148.0, 150.0, 152.0, 154.0, 156.0, 158.0, 160.0, 162.0, 164.0, 166.0, 168.0, 170.0, 172.0, 174.0, 176.0, 178.0, 180.0, 182.0, 184.0, 186.0, 188.0, 190.0, 192.0, 194.0, 196.0, 198.0, 200.0, 202.0, 204.0, 206.0, 208.0, 210.0, 212.0, 214.0, 216.0, 218.0, 220.0, 222.0, 224.0, 226.0, 228.0, 230.0, 232.0, 234.0, 236.0, 238.0, 240.0, 242.0, 244.0, 246.0, 248.0, 250.0, 252.0, 254.0, 256.0, 258.0, 260.0, 262.0, 264.0, 266.0, 268.0, 270.0, 272.0, 274.0, 276.0, 278.0, 280.0, 282.0, 284.0, 286.0, 288.0, 290.0, 292.0, 294.0, 296.0, 298.0, 300.0, 302.0, 304.0, 306.0, 308.0, 310.0, 312.0, 314.0, 316.0, 318.0, 320.0, 322.0, 324.0, 326.0, 328.0, 330.0, 332.0, 334.0, 336.0, 338.0, 340.0, 342.0, 344.0, 346.0, 348.0, 350.0, 352.0, 354.0, 356.0, 358.0, 360.0, 362.0, 364.0, 366.0, 368.0, 370.0, 372.0, 374.0, 376.0, 378.0, 380.0, 382.0, 384.0, 386.0, 388.0, 390.0, 392.0, 394.0, 396.0, 398.0, 400.0, 402.0, 404.0, 406.0, 408.0, 410.0, 412.0, 414.0, 416.0, 418.0, 420.0, 422.0, 424.0, 426.0, 428.0, 430.0, 432.0, 434.0, 436.0, 438.0, 440.0, 442.0, 444.0, 446.0, 448.0, 450.0, 452.0, 454.0, 456.0, 458.0, 460.0, 462.0, 464.0, 466.0, 468.0, 470.0, 472.0, 474.0, 476.0, 478.0, 480.0, 482.0, 484.0, 486.0, 488.0, 490.0, 492.0, 494.0, 496.0, 498.0, 500.0, 502.0, 504.0, 506.0, 508.0, 510.0, 512.0, 514.0, 516.0, 518.0, 520.0, 522.0, 524.0, 526.0, 528.0, 530.0, 532.0, 534.0, 536.0, 538.0, 540.0, 542.0, 544.0, 546.0, 548.0, 550.0, 552.0, 554.0, 556.0, 558.0, 560.0, 562.0, 564.0, 566.0, 568.0, 570.0, 572.0, 574.0, 576.0, 578.0, 580.0, 582.0, 584.0, 586.0, 588.0, 590.0, 592.0, 594.0, 596.0, 598.0, 600.0, 602.0, 604.0, 606.0, 608.0, 610.0, 612.0, 614.0, 616.0, 618.0, 620.0, 622.0, 624.0, 626.0, 628.0, 630.0, 632.0, 634.0, 636.0, 638.0, 640.0, 642.0, 644.0, 646.0, 648.0, 650.0, 652.0, 654.0, 656.0, 658.0, 660.0, 662.0, 664.0, 666.0, 668.0, 670.0, 672.0, 674.0, 676.0, 678.0, 680.0, 682.0, 684.0, 686.0, 688.0, 690.0, 692.0, 694.0, 696.0, 698.0, 700.0, 702.0, 704.0, 706.0, 708.0, 710.0, 712.0, 714.0, 716.0, 718.0, 720.0, 722.0, 724.0, 726.0, 728.0, 730.0, 732.0, 734.0, 736.0, 738.0, 740.0, 742.0, 744.0, 746.0, 748.0, 750.0, 752.0, 754.0, 756.0, 758.0, 760.0, 762.0, 764.0, 766.0, 768.0, 770.0, 772.0, 774.0, 776.0, 778.0, 780.0, 782.0, 784.0, 786.0, 788.0, 790.0, 792.0, 794.0, 796.0, 798.0, 800.0, 802.0, 804.0, 806.0, 808.0, 810.0, 812.0, 814.0, 816.0, 818.0, 820.0, 822.0, 824.0, 826.0, 828.0, 830.0, 832.0, 834.0, 836.0, 838.0, 840.0, 842.0, 844.0, 846.0, 848.0, 850.0, 852.0, 854.0, 856.0, 858.0, 860.0, 862.0, 864.0, 866.0, 868.0, 870.0, 872.0, 874.0, 876.0, 878.0, 880.0, 882.0, 884.0, 886.0, 888.0, 890.0, 892.0, 894.0, 896.0, 898.0, 900.0, 902.0, 904.0, 906.0, 908.0, 910.0, 912.0, 914.0, 916.0, 918.0, 920.0, 922.0, 924.0, 926.0, 928.0, 930.0, 932.0, 934.0, 936.0, 938.0, 940.0, 942.0, 944.0, 946.0, 948.0, 950.0, 952.0, 954.0, 956.0, 958.0, 960.0, 962.0, 964.0, 966.0, 968.0, 970.0, 972 .......... .0, 199322.0, 199324.0, 199326.0, 199328.0, 199330.0, 199332.0, 199334.0, 199336.0, 199338.0, 199340.0, 199342.0, 199344.0, 199346.0, 199348.0, 199350.0, 199352.0, 199354.0, 199356.0, 199358.0, 199360.0, 199362.0, 199364.0, 199366.0, 199368.0, 199370.0, 199372.0, 199374.0, 199376.0, 199378.0, 199380.0, 199382.0, 199384.0, 199386.0, 199388.0, 199390.0, 199392.0, 199394.0, 199396.0, 199398.0, 199400.0, 199402.0, 199404.0, 199406.0, 199408.0, 199410.0, 199412.0, 199414.0, 199416.0, 199418.0, 199420.0, 199422.0, 199424.0, 199426.0, 199428.0, 199430.0, 199432.0, 199434.0, 199436.0, 199438.0, 199440.0, 199442.0, 199444.0, 199446.0, 199448.0, 199450.0, 199452.0, 199454.0, 199456.0, 199458.0, 199460.0, 199462.0, 199464.0, 199466.0, 199468.0, 199470.0, 199472.0, 199474.0, 199476.0, 199478.0, 199480.0, 199482.0, 199484.0, 199486.0, 199488.0, 199490.0, 199492.0, 199494.0, 199496.0, 199498.0, 199500.0, 199502.0, 199504.0, 199506.0, 199508.0, 199510.0, 199512.0, 199514.0, 199516.0, 199518.0, 199520.0, 199522.0, 199524.0, 199526.0, 199528.0, 199530.0, 199532.0, 199534.0, 199536.0, 199538.0, 199540.0, 199542.0, 199544.0, 199546.0, 199548.0, 199550.0, 199552.0, 199554.0, 199556.0, 199558.0, 199560.0, 199562.0, 199564.0, 199566.0, 199568.0, 199570.0, 199572.0, 199574.0, 199576.0, 199578.0, 199580.0, 199582.0, 199584.0, 199586.0, 199588.0, 199590.0, 199592.0, 199594.0, 199596.0, 199598.0, 199600.0, 199602.0, 199604.0, 199606.0, 199608.0, 199610.0, 199612.0, 199614.0, 199616.0, 199618.0, 199620.0, 199622.0, 199624.0, 199626.0, 199628.0, 199630.0, 199632.0, 199634.0, 199636.0, 199638.0, 199640.0, 199642.0, 199644.0, 199646.0, 199648.0, 199650.0, 199652.0, 199654.0, 199656.0, 199658.0, 199660.0, 199662.0, 199664.0, 199666.0, 199668.0, 199670.0, 199672.0, 199674.0, 199676.0, 199678.0, 199680.0, 199682.0, 199684.0, 199686.0, 199688.0, 199690.0, 199692.0, 199694.0, 199696.0, 199698.0, 199700.0, 199702.0, 199704.0, 199706.0, 199708.0, 199710.0, 199712.0, 199714.0, 199716.0, 199718.0, 199720.0, 199722.0, 199724.0, 199726.0, 199728.0, 199730.0, 199732.0, 199734.0, 199736.0, 199738.0, 199740.0, 199742.0, 199744.0, 199746.0, 199748.0, 199750.0, 199752.0, 199754.0, 199756.0, 199758.0, 199760.0, 199762.0, 199764.0, 199766.0, 199768.0, 199770.0, 199772.0, 199774.0, 199776.0, 199778.0, 199780.0, 199782.0, 199784.0, 199786.0, 199788.0, 199790.0, 199792.0, 199794.0, 199796.0, 199798.0, 199800.0, 199802.0, 199804.0, 199806.0, 199808.0, 199810.0, 199812.0, 199814.0, 199816.0, 199818.0, 199820.0, 199822.0, 199824.0, 199826.0, 199828.0, 199830.0, 199832.0, 199834.0, 199836.0, 199838.0, 199840.0, 199842.0, 199844.0, 199846.0, 199848.0, 199850.0, 199852.0, 199854.0, 199856.0, 199858.0, 199860.0, 199862.0, 199864.0, 199866.0, 199868.0, 199870.0, 199872.0, 199874.0, 199876.0, 199878.0, 199880.0, 199882.0, 199884.0, 199886.0, 199888.0, 199890.0, 199892.0, 199894.0, 199896.0, 199898.0, 199900.0, 199902.0, 199904.0, 199906.0, 199908.0, 199910.0, 199912.0, 199914.0, 199916.0, 199918.0, 199920.0, 199922.0, 199924.0, 199926.0, 199928.0, 199930.0, 199932.0, 199934.0, 199936.0, 199938.0, 199940.0, 199942.0, 199944.0, 199946.0, 199948.0, 199950.0, 199952.0, 199954.0, 199956.0, 199958.0, 199960.0, 199962.0, 199964.0, 199966.0, 199968.0, 199970.0, 199972.0, 199974.0, 199976.0, 199978.0, 199980.0, 199982.0, 199984.0, 199986.0, 199988.0, 199990.0, 199992.0, 199994.0, 199996.0, 199998.0 ] } }, fields: {} }

2014-03-14T21:16:53.810+0100 [journal] _groupCommit

2014-03-14T21:16:53.810+0100 [journal] _groupCommit upgrade

2014-03-14T21:17:28.677+0100 [DataFileSync] flushing mmaps took 23ms  for 6 files

2014-03-14T21:17:28.697+0100 [TTLMonitor] TTLMonitor thread awake

2014-03-14T21:17:28.697+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:17:28.697+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:17:28.697+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:18:28.683+0100 [DataFileSync] flushing mmaps took 25ms  for 6 files

2014-03-14T21:18:28.700+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:18:28.700+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:18:28.700+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:18:37.702+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:18:37.702+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:6 0ms

2014-03-14T21:18:37.702+0100 [journal] groupCommit end

2014-03-14T21:18:37.702+0100 [TTLMonitor] query admin.system.indexes query: { expireAfterSeconds: { $exists: true } } planSummary: EOF ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:202 nreturned:0 reslen:20 0ms

2014-03-14T21:18:37.702+0100 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:81 nreturned:0 reslen:20 0ms

2014-03-14T21:18:37.702+0100 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:38 nreturned:0 reslen:20 0ms

2014-03-14T21:19:28.682+0100 [DataFileSync] flushing mmaps took 21ms  for 6 files

2014-03-14T21:19:28.702+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:19:28.702+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:19:28.702+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:19:37.705+0100 [TTLMonitor] TTLMonitor thread awake

2014-03-14T21:20:28.682+0100 [DataFileSync] flushing mmaps took 18ms  for 6 files

2014-03-14T21:20:28.706+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:20:28.706+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:20:28.706+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:21:28.692+0100 [DataFileSync] flushing mmaps took 24ms  for 6 files

2014-03-14T21:21:28.709+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:21:28.709+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:21:28.709+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:21:57.257+0100 [initandlisten] connection accepted from 127.0.0.1:60792 #2 (2 connections now open)

2014-03-14T21:21:57.257+0100 [conn2] run command admin.$cmd { replSetGetStatus: 1.0, forShell: 1.0 }

2014-03-14T21:21:57.257+0100 [conn2] command: { replSetGetStatus: 1.0, forShell: 1.0 }

2014-03-14T21:21:57.257+0100 [conn2] command admin.$cmd command: { replSetGetStatus: 1.0, forShell: 1.0 } keyUpdates:0 numYields:0  reslen:76 0ms

2014-03-14T21:21:57.257+0100 [conn2] run command test.$cmd { isMaster: 1.0, forShell: 1.0 }

2014-03-14T21:21:57.258+0100 [conn2] command test.$cmd command: { isMaster: 1.0, forShell: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms

2014-03-14T21:22:02.552+0100 [conn2] Socket recv() conn closed? 127.0.0.1:60792

2014-03-14T21:22:02.553+0100 [conn2] SocketException: remote: 127.0.0.1:60792 error: 9001 socket exception [CLOSED] server [127.0.0.1:60792]

2014-03-14T21:22:02.553+0100 [conn2] end connection 127.0.0.1:60792 (1 connection now open)

2014-03-14T21:22:28.692+0100 [DataFileSync] flushing mmaps took 21ms  for 6 files

2014-03-14T21:22:28.712+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:22:28.712+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:22:28.712+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:23:28.698+0100 [DataFileSync] flushing mmaps took 24ms  for 6 files

2014-03-14T21:23:28.715+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:23:28.715+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:23:28.715+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:24:20.186+0100 [journal] _groupCommit

2014-03-14T21:24:20.186+0100 [journal] _groupCommit upgrade

2014-03-14T21:24:28.701+0100 [DataFileSync] flushing mmaps took 24ms  for 6 files

2014-03-14T21:24:28.719+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:24:28.719+0100 [PeriodicTaskRunner] task: WriteBackManager::cleaner took: 0ms

2014-03-14T21:24:28.719+0100 [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 0ms

2014-03-14T21:25:13.413+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:25:13.413+0100 [conn1] command test.$cmd command: { $msg: "query not recording (too large)" } keyUpdates:0 numYields:3 locks(micros) r:947397854 reslen:48 500313ms

2014-03-14T21:25:13.413+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:6 0ms

2014-03-14T21:25:13.414+0100 [journal] groupCommit end

2014-03-14T21:25:13.414+0100 [TTLMonitor] query admin.system.indexes query: { expireAfterSeconds: { $exists: true } } planSummary: EOF ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:37 nreturned:0 reslen:20 0ms

2014-03-14T21:25:13.414+0100 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:49 nreturned:0 reslen:20 0ms

2014-03-14T21:25:13.414+0100 [TTLMonitor] query test.system.indexes query: { expireAfterSeconds: { $exists: true } } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:33 nreturned:0 reslen:20 0ms

2014-03-14T21:25:13.414+0100 [conn1] run command admin.$cmd { serverStatus: 1.0 }

2014-03-14T21:25:13.414+0100 [conn1] command admin.$cmd command: { serverStatus: 1.0 } keyUpdates:0 numYields:0 locks(micros) r:10 reslen:3137 0ms

2014-03-14T21:25:13.415+0100 [conn1] run command admin.$cmd { buildinfo: 1.0 }

2014-03-14T21:25:13.416+0100 [conn1] command admin.$cmd command: { buildinfo: 1.0 } keyUpdates:0 numYields:0  reslen:871 0ms

2014-03-14T21:25:13.416+0100 [conn1] run command admin.$cmd { replSetGetStatus: 1.0 }

2014-03-14T21:25:13.416+0100 [conn1] command: { replSetGetStatus: 1.0 }

2014-03-14T21:25:13.416+0100 [conn1] command admin.$cmd command: { replSetGetStatus: 1.0 } keyUpdates:0 numYields:0  reslen:76 0ms

2014-03-14T21:25:13.416+0100 [conn1] run command test.$cmd { isMaster: 1.0 }

2014-03-14T21:25:13.416+0100 [conn1] command test.$cmd command: { isMaster: 1.0 } keyUpdates:0 numYields:0  reslen:178 0ms

2014-03-14T21:25:14.465+0100 [journal] _groupCommit

2014-03-14T21:25:14.465+0100 [journal] _groupCommit upgrade

2014-03-14T21:25:14.465+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:25:14.465+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:25:14.465+0100 [journal] groupCommit end

2014-03-14T21:25:15.516+0100 [journal] _groupCommit

2014-03-14T21:25:15.516+0100 [journal] _groupCommit upgrade

2014-03-14T21:25:15.516+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:25:15.516+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:25:15.516+0100 [journal] groupCommit end

2014-03-14T21:25:16.561+0100 [journal] _groupCommit

2014-03-14T21:25:16.561+0100 [journal] _groupCommit upgrade

2014-03-14T21:25:16.561+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:25:16.561+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:25:16.561+0100 [journal] groupCommit end

2014-03-14T21:25:17.608+0100 [journal] _groupCommit

2014-03-14T21:25:17.608+0100 [journal] _groupCommit upgrade

2014-03-14T21:25:17.608+0100 [journal] journal REMAPPRIVATEVIEW

2014-03-14T21:25:17.608+0100 [journal] journal REMAPPRIVATEVIEW done startedAt: 0 n:3 0ms

2014-03-14T21:25:17.608+0100 [journal] groupCommit end

^C2014-03-14T21:25:18.642+0100 [signalProcessingThread] got signal 2 (Interrupt: 2), will terminate after current cmd ends

2014-03-14T21:25:18.642+0100 [signalProcessingThread] now exiting

dbexit: 2014-03-14T21:25:18.642+0100 [signalProcessingThread] shutdown: going to close listening sockets...

2014-03-14T21:25:18.642+0100 [signalProcessingThread] closing listening socket: 7

2014-03-14T21:25:18.642+0100 [signalProcessingThread] closing listening socket: 8

2014-03-14T21:25:18.642+0100 [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock

2014-03-14T21:25:18.643+0100 [signalProcessingThread] shutdown: going to flush diaglog...

2014-03-14T21:25:18.643+0100 [signalProcessingThread] shutdown: going to close sockets...

2014-03-14T21:25:18.643+0100 [signalProcessingThread] shutdown: waiting for fs preallocator...

2014-03-14T21:25:18.643+0100 [signalProcessingThread] shutdown: lock for final commit...

2014-03-14T21:25:18.643+0100 [signalProcessingThread] shutdown: final commit...

2014-03-14T21:25:18.643+0100 [signalProcessingThread] _groupCommit

2014-03-14T21:25:18.643+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW

2014-03-14T21:25:18.643+0100 [conn1] Socket recv() errno:9 Bad file descriptor 127.0.0.1:60695

2014-03-14T21:25:18.643+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW done startedAt: 3 n:3 0ms

2014-03-14T21:25:18.643+0100 [signalProcessingThread] groupCommit end

2014-03-14T21:25:18.643+0100 [conn1] SocketException: remote: 127.0.0.1:60695 error: 9001 socket exception [RECV_ERROR] server [127.0.0.1:60695]

2014-03-14T21:25:18.643+0100 [conn1] end connection 127.0.0.1:60695 (0 connections now open)

2014-03-14T21:25:18.663+0100 [signalProcessingThread] shutdown: closing all files...

2014-03-14T21:25:18.663+0100 [signalProcessingThread] mmf close

2014-03-14T21:25:18.663+0100 [signalProcessingThread] mmf close /Users/norberto/sandbox/2.6_slowcount/db/local.ns

2014-03-14T21:25:18.663+0100 [signalProcessingThread] _groupCommit

2014-03-14T21:25:18.663+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW

2014-03-14T21:25:18.663+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms

2014-03-14T21:25:18.663+0100 [signalProcessingThread] groupCommit end

2014-03-14T21:25:18.663+0100 [signalProcessingThread] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.ns

2014-03-14T21:25:18.663+0100 [signalProcessingThread] _groupCommit

2014-03-14T21:25:18.663+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW

2014-03-14T21:25:18.663+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW done startedAt: 1 n:1 0ms

2014-03-14T21:25:18.663+0100 [signalProcessingThread] groupCommit end

2014-03-14T21:25:18.664+0100 [signalProcessingThread] mmf close /Users/norberto/sandbox/2.6_slowcount/db/local.0

2014-03-14T21:25:18.664+0100 [signalProcessingThread] _groupCommit

2014-03-14T21:25:18.664+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW

2014-03-14T21:25:18.664+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW done startedAt: 2 n:1 0ms

2014-03-14T21:25:18.664+0100 [signalProcessingThread] groupCommit end

2014-03-14T21:25:18.664+0100 [signalProcessingThread] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.1

2014-03-14T21:25:18.664+0100 [signalProcessingThread] _groupCommit

2014-03-14T21:25:18.664+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW

2014-03-14T21:25:18.664+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms

2014-03-14T21:25:18.664+0100 [signalProcessingThread] groupCommit end

2014-03-14T21:25:18.665+0100 [signalProcessingThread] mmf close /Users/norberto/sandbox/2.6_slowcount/db/test.0

2014-03-14T21:25:18.665+0100 [signalProcessingThread] _groupCommit

2014-03-14T21:25:18.665+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW

2014-03-14T21:25:18.665+0100 [signalProcessingThread] journal REMAPPRIVATEVIEW done startedAt: 1 n:1 0ms

2014-03-14T21:25:18.665+0100 [signalProcessingThread] groupCommit end

2014-03-14T21:25:18.665+0100 [signalProcessingThread] closeAllFiles() finished

2014-03-14T21:25:18.665+0100 [signalProcessingThread] journalCleanup...

2014-03-14T21:25:18.665+0100 [signalProcessingThread] removeJournalFiles

2014-03-14T21:25:18.665+0100 [signalProcessingThread] removeJournalFiles end

2014-03-14T21:25:18.665+0100 [signalProcessingThread] shutdown: removing fs lock...

2014-03-14T21:25:18.665+0100 [signalProcessingThread] shutdown: groupCommitMutex

dbexit: really exiting now

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

dump.tgz
2.57 MB
Mar 14 2014 10:24:48 PM UTC

Activity

People

Assignee:: Unassigned

Reporter:: Norberto Fernando Rocha Leite (Inactive)

Participants:: Ben Becker, Norberto Fernando Rocha Leite

Votes:: 0 Vote for this issue

Watchers:: 8 Start watching this issue

Dates

Created:: Mar 14 2014 10:24:48 PM UTC

Updated:: Dec 10 2014 11:04:52 PM UTC

Resolved:: Mar 14 2014 10:40:24 PM UTC