-
Type:
Bug
-
Resolution: Duplicate
-
Priority:
Critical - P2
-
None
-
Affects Version/s: 2.6.0-rc1
-
Component/s: Performance, Querying
-
ALL
-
None
-
0
-
None
-
None
-
None
-
None
-
None
-
None
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