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