Dlaczego 2700 rekordów (320KB każdy) powinno zająć 30 sekund na pobranie?

Question

Mam 2700 rekordów w MongoDB. Każdy dokument ma rozmiar około 320 KB. Używany silnik to wiredTiger, a całkowita wielkość kolekcji to około 885 MB.

Moja MongoDB config jest jak poniżej:

systemLog: 
    destination: file 
    path: /usr/local/var/log/mongodb/mongo.log 
    logAppend: true 
storage: 
    dbPath: /usr/local/var/mongodb 
    engine: wiredTiger 
    wiredTiger: 
     engineConfig: 
     cacheSizeGB: 1 
     statisticsLogDelaySecs: 0 
     journalCompressor: snappy 
     collectionConfig: 
     blockCompressor: snappy 
     indexConfig: 
     prefixCompression: false 
net: 
    bindIp: 127.0.0.1 

Moje połączenie jest poprzez socket:

mongo_client = MongoClient('/tmp/mongodb-27017.sock') 

A statystyki kolekcja ujawnić ten wynik:

db.mycol.stats() 
{ 
    "ns" : "bi.mycol", 
    "count" : 2776, 
    "size" : 885388544, 
    "avgObjSize" : 318944, 
    "storageSize" : 972476416, 
    "capped" : false, 
    "wiredTiger" : { 
     "metadata" : { 
      "formatVersion" : 1 
     }, 
     "creationString" : "allocation_size=4KB,app_metadata=(formatVersion=1),block_allocation=best,block_compressor=snappy,cache_resident=0,checkpoint=(WiredTigerCheckpoint.9=(addr=\"01e30275da81e4b9e99f78e30275db81e4c61d1e01e30275dc81e40fab67d5808080e439f6afc0e41e80bfc0\",order=9,time=1444566832,size=511762432,write_gen=13289)),checkpoint_lsn=(24,52054144),checksum=uncompressed,collator=,columns=,dictionary=0,format=btree,huffman_key=,huffman_value=,id=5,internal_item_max=0,internal_key_max=0,internal_key_truncate=,internal_page_max=4KB,key_format=q,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=1MB,memory_page_max=10m,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=0,prefix_compression_min=4,split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,value_format=u,version=(major=1,minor=1)", 
     "type" : "file", 
     "uri" : "statistics:table:collection-0-6630292038312816605", 
     "LSM" : { 
      "bloom filters in the LSM tree" : 0, 
      "bloom filter false positives" : 0, 
      "bloom filter hits" : 0, 
      "bloom filter misses" : 0, 
      "bloom filter pages evicted from cache" : 0, 
      "bloom filter pages read into cache" : 0, 
      "total size of bloom filters" : 0, 
      "sleep for LSM checkpoint throttle" : 0, 
      "chunks in the LSM tree" : 0, 
      "highest merge generation in the LSM tree" : 0, 
      "queries that could have benefited from a Bloom filter that did not exist" : 0, 
      "sleep for LSM merge throttle" : 0 
     }, 
     "block-manager" : { 
      "file allocation unit size" : 4096, 
      "blocks allocated" : 0, 
      "checkpoint size" : 511762432, 
      "allocations requiring file extension" : 0, 
      "blocks freed" : 0, 
      "file magic number" : 120897, 
      "file major version number" : 1, 
      "minor version number" : 0, 
      "file bytes available for reuse" : 460734464, 
      "file size in bytes" : 972476416 
     }, 
     "btree" : { 
      "column-store variable-size deleted values" : 0, 
      "column-store fixed-size leaf pages" : 0, 
      "column-store internal pages" : 0, 
      "column-store variable-size leaf pages" : 0, 
      "pages rewritten by compaction" : 0, 
      "number of key/value pairs" : 0, 
      "fixed-record size" : 0, 
      "maximum tree depth" : 4, 
      "maximum internal page key size" : 368, 
      "maximum internal page size" : 4096, 
      "maximum leaf page key size" : 3276, 
      "maximum leaf page size" : 32768, 
      "maximum leaf page value size" : 1048576, 
      "overflow pages" : 0, 
      "row-store internal pages" : 0, 
      "row-store leaf pages" : 0 
     }, 
     "cache" : { 
      "bytes read into cache" : 3351066029, 
      "bytes written from cache" : 0, 
      "checkpoint blocked page eviction" : 0, 
      "unmodified pages evicted" : 8039, 
      "page split during eviction deepened the tree" : 0, 
      "modified pages evicted" : 0, 
      "data source pages selected for eviction unable to be evicted" : 1, 
      "hazard pointer blocked page eviction" : 1, 
      "internal pages evicted" : 0, 
      "pages split during eviction" : 0, 
      "in-memory page splits" : 0, 
      "overflow values cached in memory" : 0, 
      "pages read into cache" : 10519, 
      "overflow pages read into cache" : 0, 
      "pages written from cache" : 0 
     }, 
     "compression" : { 
      "raw compression call failed, no additional data available" : 0, 
      "raw compression call failed, additional data available" : 0, 
      "raw compression call succeeded" : 0, 
      "compressed pages read" : 10505, 
      "compressed pages written" : 0, 
      "page written failed to compress" : 0, 
      "page written was too small to compress" : 0 
     }, 
     "cursor" : { 
      "create calls" : 7, 
      "insert calls" : 0, 
      "bulk-loaded cursor-insert calls" : 0, 
      "cursor-insert key and value bytes inserted" : 0, 
      "next calls" : 0, 
      "prev calls" : 2777, 
      "remove calls" : 0, 
      "cursor-remove key bytes removed" : 0, 
      "reset calls" : 16657, 
      "search calls" : 16656, 
      "search near calls" : 0, 
      "update calls" : 0, 
      "cursor-update value bytes updated" : 0 
     }, 
     "reconciliation" : { 
      "dictionary matches" : 0, 
      "internal page multi-block writes" : 0, 
      "leaf page multi-block writes" : 0, 
      "maximum blocks required for a page" : 0, 
      "internal-page overflow keys" : 0, 
      "leaf-page overflow keys" : 0, 
      "overflow values written" : 0, 
      "pages deleted" : 0, 
      "page checksum matches" : 0, 
      "page reconciliation calls" : 0, 
      "page reconciliation calls for eviction" : 0, 
      "leaf page key bytes discarded using prefix compression" : 0, 
      "internal page key bytes discarded using suffix compression" : 0 
     }, 
     "session" : { 
      "object compaction" : 0, 
      "open cursor count" : 7 
     }, 
     "transaction" : { 
      "update conflicts" : 0 
     } 
    }, 
    "nindexes" : 2, 
    "totalIndexSize" : 208896, 
    "indexSizes" : { 
     "_id_" : 143360, 
     "date_1" : 65536 
    }, 
    "ok" : 1 
} 

Jak mogę zrozumieć, że MongoDB używa swap? Jak wywnioskować, gdzie dokładnie jest wąskie gardło?

---

Edycja:

Sposób I pobrania danych pytona jest:

for doc in mycol.find({'date': {"$lte": '2016-12-12', '$gte': '2012-09-09'}}, {'_id': False}): 
     doc['uids'] = set(doc['uids']) 
     records.append(doc) 

date pole jest indeksowany.

EDIT 2: Jest to wynik podczas pobierania danych:

CPU core1: ~65% 
CPU core2: ~65% 
CPU core3: ~65% 
CPU core4: ~65% 
RAM: 7190/8190MB 
swap: 1140/2048MB 

---

EDIT 3:
MongoDB dziennika jest:

2015-10-11T17:25:08.317+0330 I NETWORK [initandlisten] connection accepted from anonymous unix socket #18 (2 connections now open) 
2015-10-11T17:25:08.321+0330 I NETWORK [initandlisten] connection accepted from anonymous unix socket #19 (3 connections now open) 
2015-10-11T17:25:36.501+0330 I QUERY [conn19] getmore bi.mycol cursorid:10267473126 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:3 nreturned:14 reslen:4464998 locks:{} 199ms 
2015-10-11T17:25:37.665+0330 I QUERY [conn19] getmore bi.mycol cursorid:10267473126 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:5 nreturned:14 reslen:4464998 locks:{} 281ms 
2015-10-11T17:25:50.331+0330 I NETWORK [conn19] end connection anonymous unix socket (2 connections now open) 
2015-10-11T17:25:50.363+0330 I NETWORK [conn18] end connection anonymous unix socket (1 connection now open) 

---

EDIT 4:
Dane Próbka jest:

{"date": "2012-09-12", "uids": [1,2,3,4,...,30000]} 

NB: Mam 30k UID wewnątrz od uids dziedzinie.

---

EDIT 5:

Wyjaśniając Query że wykorzystuje IXSCAN etap:

$ db.mycol.find({'date': {"$lte": '2018-11-27', '$gte': '2011-04-23'}}, {'_id': 0}).explain("executionStats") 
{ 
    "queryPlanner" : { 
     "plannerVersion" : 1, 
     "namespace" : "bi.mycol", 
     "indexFilterSet" : false, 
     "parsedQuery" : { 
      "$and" : [ 
       { 
        "date" : { 
         "$lte" : "2018-11-27" 
        } 
       }, 
       { 
        "date" : { 
         "$gte" : "2011-04-23" 
        } 
       } 
      ] 
     }, 
     "winningPlan" : { 
      "stage" : "PROJECTION", 
      "transformBy" : { 
       "_id" : 0 
      }, 
      "inputStage" : { 
       "stage" : "FETCH", 
       "inputStage" : { 
        "stage" : "IXSCAN", 
        "keyPattern" : { 
         "date" : 1 
        }, 
        "indexName" : "date_1", 
        "isMultiKey" : false, 
        "direction" : "forward", 
        "indexBounds" : { 
         "date" : [ 
          "[\"2011-04-23\", \"2018-11-27\"]" 
         ] 
        } 
       } 
      } 
     }, 
     "rejectedPlans" : [ ] 
    }, 
    "executionStats" : { 
     "executionSuccess" : true, 
     "nReturned" : 2776, 
     "executionTimeMillis" : 2312, 
     "totalKeysExamined" : 2776, 
     "totalDocsExamined" : 2776, 
     "executionStages" : { 
      "stage" : "PROJECTION", 
      "nReturned" : 2776, 
      "executionTimeMillisEstimate" : 540, 
      "works" : 2777, 
      "advanced" : 2776, 
      "needTime" : 0, 
      "needFetch" : 0, 
      "saveState" : 31, 
      "restoreState" : 31, 
      "isEOF" : 1, 
      "invalidates" : 0, 
      "transformBy" : { 
       "_id" : 0 
      }, 
      "inputStage" : { 
       "stage" : "FETCH", 
       "nReturned" : 2776, 
       "executionTimeMillisEstimate" : 470, 
       "works" : 2777, 
       "advanced" : 2776, 
       "needTime" : 0, 
       "needFetch" : 0, 
       "saveState" : 31, 
       "restoreState" : 31, 
       "isEOF" : 1, 
       "invalidates" : 0, 
       "docsExamined" : 2776, 
       "alreadyHasObj" : 0, 
       "inputStage" : { 
        "stage" : "IXSCAN", 
        "nReturned" : 2776, 
        "executionTimeMillisEstimate" : 0, 
        "works" : 2776, 
        "advanced" : 2776, 
        "needTime" : 0, 
        "needFetch" : 0, 
        "saveState" : 31, 
        "restoreState" : 31, 
        "isEOF" : 1, 
        "invalidates" : 0, 
        "keyPattern" : { 
         "date" : 1 
        }, 
        "indexName" : "date_1", 
        "isMultiKey" : false, 
        "direction" : "forward", 
        "indexBounds" : { 
         "date" : [ 
          "[\"2011-04-23\", \"2018-11-27\"]" 
         ] 
        }, 
        "keysExamined" : 2776, 
        "dupsTested" : 0, 
        "dupsDropped" : 0, 
        "seenInvalidated" : 0, 
        "matchTested" : 0 
       } 
      } 
     } 
    }, 
    "serverInfo" : { 
     "host" : "MySys.local", 
     "port" : 27017, 
     "version" : "3.0.0", 
     "gitVersion" : "nogitversion" 
    }, 
    "ok" : 1 
} 

---

EDIT 6:

OS: Mac osX Yosemite 
MongoDB version: 3.0.0 
Total RAM: 8G 
Filesystem: Mac OS Extended (Journaled) 

Answer 1

Metody I na poprawę wydajności:

1. Przede wszystkim, zamiast stosowania pętli przechodzić zapytania i pobranie danych daję kursor Pandas zamiast tworzenia dużych listę obiektów w pytona:

   cursor = mycol.find({'date': {"$lte": end_date, '$gte': start_date}}, {'_id': False}) 
   df = pandas.DataFrame(list(cursor)) 
   

   Wydajność znacznie się poprawiła, teraz zajmuje to najwyżej 10 sekund, a nie 30 sekund.

2. Zamiast używać doc['uids'] = set(doc['uids']), które trwają około 6 sekund, nie zmieniłem listy domyślnej, aby ustawić i obsługiwać duplikaty z samą ramką danych.

Answer 2

masz dwa problemy tutaj:

1. Używaj isodate zamiast daty ciąg dla szybszych wyszukiwań indeksu, jako daty strunowe zrobić lexographic porównania ciąg, natomiast isodates robi jedną cyfrą. Ponieważ całkowita liczba rekordów jest niska, typ indeksu nie powinien stanowić dużego problemu, problemem może być rozmiar dokumentów i ich transfer w sieci oraz deserializacja.

2. Spróbuj zapytać o nie wybraniu pola uid tj

   for doc in mycol.find({'date': {"$lte": '2016-12-12', '$gte': '2012-09-09'}}, {'_id': False,'uid':False}): 
   

Twój czas zapytań poprawi przez ogromną margin.You będzie wtedy trzeba zbadać razy transferowych między aplikacji i serwerów MongoDB , a także test porównawczy do pobierania pojedynczego dokumentu z wykorzystaniem find_one(), aby zobaczyć, ile czasu zajmuje przekształcanie w czasie.