Почему MongoDB вдруг начала тормозить при вставке данных?

Question

[Павел Купцов]

Добрый день!
Есть скрипт который обрабатывает документы и вставляет результат обработки в MongoDB,
с некоторого момента (причину я так пока и не выяснил), вставка в БД стала жутко тормозить (до 4-5 сек! на операцию). Были приняты превентивные :) меры - удалили все индексы, добавили 1Гб памяти серверу - результат тот же. Для чистоты эксперимента начал писать в новую БД (пустую), пока писал в один поток - скорость вставки была приемлемой (менее 100мс), когда включил в два потока - скорость упала до 130-200мс, а через определенное время снова до 4000мс. При этом скрипт этот работал всегда в 1 поток, но требовалось ускорение обработки документов (которых около 5млн в неделю появляется).
МОнга настроена так:

net:
 bindIp: 127.0.0.1
 port: 27017
storage:
 dbPath: /var/lib/mongodb
 journal:
    enabled: true
 engine: wiredTiger
 wiredTiger:
  engineConfig:
   cacheSizeGB: 4
  collectionConfig:
   blockCompressor: snappy
systemLog:
   destination: file
   path: /var/log/mongodb/mongod.log
   logAppend: true

Я прихожу к выводу что просто железо не справляется, но может и ошибаюсь.
Сервер виртуальный (vmware): 4 Гб памяти (добавлял до 5Гб - но эффекта не дало),
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt11-1+deb8u4

# lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                4
On-line CPU(s) list:   0-3
Thread(s) per core:    1
Core(s) per socket:    2
Socket(s):             2
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 26
Stepping:              5
CPU MHz:               2000.071
BogoMIPS:              4000.14
Hypervisor vendor:     VMware
Virtualization type:   full
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              4096K
NUMA node0 CPU(s):     0-3

Как можно полечить эту проблему?
Спасибо

Answer 1

[lega]

- Покажите какой запрос (на вставку) выполняете
- Какие индексы есть
- Что показывает explain() запроса
- db.stats(), + .stats() на вашей коллекции
- mongostat

когда включил в два потока - скорость упала до 130-200мс

Если условий при вставке нет и размер документа маленький, то скорость на $5 vps с ssd диском достигает 10к/сек, т.е. 0.0001 сек на операцию в среднем. Если у вас подобные запросы - значит монге не дают ресурсов, особенно io.

Comments

[Павел Купцов]

И еще вопрос - лучше инсертить с индексами или без них? Вроде монга тратит доп. ресурсы на создание индекса для новых данных?

Answer 2

[Павел Купцов]

1. Запрос (их несколько но они идентичны по логике)

$col_doc->update(
            { url => $url },
            {
                '$set' => {
                    url      => $url,
                    reg_date => $reg_date
                  }

            },
            { upsert => 1 }
);

и вот в другую коллекцию:

$col_statistic->update(
            { ts => $start_time },
            {
                '$inc' => { $assist => 1 }
            },
            { upsert => 1 }
        );

2. Индексы все удалил - остался только _id_
3. explain без индексов показывает

"winningPlan" : {
                        "stage" : "UPDATE",
                        "inputStage" : {
                                "stage" : "COLLSCAN",
                                "filter" : {
                                        "url" : {
                                                "$eq" : "document.local"
                                        }
                                },
                                "direction" : "forward"
                        }
                },
                "rejectedPlans" : [ ]

с индексом по url:

"winningPlan" : {
                        "stage" : "UPDATE",
                        "inputStage" : {
                                "stage" : "FETCH",
                                "inputStage" : {
                                        "stage" : "IXSCAN",
                                        "keyPattern" : {
                                                "url" : 1
                                        },
                                        "indexName" : "url_1",
                                        "isMultiKey" : false,
                                        "direction" : "forward",
                                        "indexBounds" : {
                                                "url" : [
                                                        "[\"document.local\", \"document.local\"]"
                                                ]
                                        }
                                }
                        }
                },
                "rejectedPlans" : [ ]

4.
На коллекции:

{
        "ns" : "prepared.documents",
        "count" : 422836,
        "size" : 91540732,
        "avgObjSize" : 216,
        "storageSize" : 24944640,
        "capped" : false,
        "wiredTiger" : {
                "metadata" : {
                        "formatVersion" : 1
                },
                "creationString" : "allocation_size=4KB,app_metadata=(formatVersion=1),
-- порезано тут ---
        "nindexes" : 2,
        "totalIndexSize" : 10375168,
        "indexSizes" : {
                "_id_" : 4202496,
                "url_1" : 6172672
        },
        "ok" : 1
}

Это уже когда создал индекс по url
на БД

> db.stats()
{
        "db" : "documents",
        "collections" : 4,
        "objects" : 422843,
        "avgObjSize" : 216.49207625525312,
        "dataSize" : 91542159,
        "storageSize" : 25034752,
        "numExtents" : 0,
        "indexes" : 5,
        "indexSize" : 10444800,
        "ok" : 1
}

Это все данные с полупустой бд - на которой тоже тормоза начинаются при интенсивных инсертах

5. mongostat сейчас выложу.

insert query update delete getmore command % dirty % used flushes  vsize    res qr|qw ar|aw netIn netOut conn     time
    *0    34    732     *0       0     1|0     0.7    4.0       0 408.0M 234.0M   0|0   1|0  195k    95k   17 14:21:43
    *0    *0    260     *0       0     1|0     0.7    4.0       0 408.0M 234.0M   0|0   1|0   88k    34k   17 14:21:44
    *0    *0    230     *0       0     1|0     0.7    4.0       0 408.0M 234.0M   0|0   1|1   79k    31k   17 14:21:45
    *0    *0    332     *0       0     2|0     0.7    4.0       0 408.0M 234.0M   0|0   1|0  113k    39k   16 14:21:46
    *0     1    277     *0       0     3|0     0.8    4.0       0 408.0M 234.0M   0|0   1|0   91k    37k   17 14:21:47
    *0     7    488     *0       0     1|0     0.8    4.0       0 409.0M 235.0M   0|0   1|1  132k    65k   17 14:21:48
    *0    32    693     *0       0     1|0     0.8    4.0       0 409.0M 235.0M   0|0   1|0  183k    92k   17 14:21:49
    *0    14    508     *0       0     1|0     0.8    4.0       0 409.0M 235.0M   0|0   1|0  141k    67k   17 14:21:50
    *0    *0    243     *0       0     1|0     0.8    4.0       0 409.0M 235.0M   0|0   1|0   84k    32k   17 14:21:51
    *0    *0    247     *0       0     2|0     0.8    4.0       0 409.0M 235.0M   0|0   1|1   82k    33k   17 14:21:52
insert query update delete getmore command % dirty % used flushes  vsize    res qr|qw ar|aw netIn netOut conn     time
    *0    *0    187     *0       0     1|0     0.3    4.0       1 409.0M 235.0M   0|0   1|1   63k    28k   17 14:21:53

Comments

[Павел Купцов]

insert query update delete getmore command % dirty % used flushes  vsize    res qr|qw ar|aw netIn netOut conn     time
    *0    *0     76     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   26k    21k    5 13:13:50
    *0    *0    138     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   46k    25k    5 13:13:51
    *0    *0    111     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   38k    23k    5 13:13:52
    *0    *0     81     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   26k    21k    5 13:13:53
    *0    *0     93     *0       0     2|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   31k    22k    5 13:13:54
    *0    *0    173     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   58k    27k    5 13:13:55
    *0    *0    175     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   58k    28k    5 13:13:56
    *0    *0     97     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   32k    22k    5 13:13:57
    *0    *0     61     *0       0     1|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   20k    19k    5 13:13:58
    *0    *0     61     *0       0     2|0     0.0    2.6       0 347.0M 210.0M   0|0   1|0   21k    20k    5 13:13:59

[lega]

Т.к. у вас условия в запросе: { url => $url } и { ts => $start_time }, то вам обязательно нужны индексы по этим полям, иначе монга будет вручную перелопачивать все документы и искать нет ли такого документа с таким url.
Т.е. индексы нужно создать до вставки данных.

col_doc.endureIndex({url: 1})
col_statistic.ensureIndex({ts: 1})
так же можно использовать уникальный индекс, это не даст создать дубль.

Более подробный explan можно сделать так, там есть время выполнения и т.п.: db.user.explain('executionStats').update(...)

Судя по вашему mongostats, монга выполняет 300-400 обновлений в сек (помимо запросов) - а это ~3мс на запрос в среднем.

[lega]

Кроме того можете понаблюдать за io при нагрузке через top или iotop, если оно достигает 100% то это и есть узкое место.

[Павел Купцов]

Спасибо, попробую на новой базе поиграться с вариантами индексов (индексы были - но и на них почему-то тормозило). iotop замерял - максимум который увидел Total DISK WRITE : 60 K/s
Дублей там в принципе быть не может - но стоит попробовать с уникальным индексом в качестве проверки. В любом случае спасибо за подробные ответы - буду активней мониторить работу скрипта и монги.