1

I observe repeatable, sudden, short-time update queries slowdowns in MongoDB cluster for single database. That slowdowns lasts about 30 seconds and repeats few times a day.

I found that lock % and page faults are peaking at this moments:

lock % peak page faults peak

I ran mongostat to see, what is happening. Here is what I got:

insert  query update delete getmore command flushes mapped  vsize    res faults      locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn     set repl       time
    55   2166   2607     20     972  1408|0       0   440g   895g  26.3g    156       db:18.4%          0      4|0     0|0      1m     3m 10009    rs_1  PRI   20:28:16
    39   2103   2431     12     985  1815|0       0   440g   895g  26.3g    136       db:13.7%          0      6|0     2|1      1m     2m 10009    rs_1  PRI   20:28:17
    84   2097   2646     18     985  1832|0       0   440g   895g  26.3g    140       db:16.5%          0      0|0     1|0      1m     3m 10009    rs_1  PRI   20:28:18
    59   2225   2700     19     989  1854|0       0   440g   895g  26.3g    157       db:18.0%          0     12|0     3|2      1m     3m 10009    rs_1  PRI   20:28:19
    61   2065   2484     20     980  1787|0       0   440g   895g  26.3g    156       db:15.8%          0      9|0     0|0      1m     5m 10009    rs_1  PRI   20:28:20
    86   2134   2660     24     946  1773|0       0   440g   895g  26.4g    393     db_2:118.7%         0     15|0     0|1      1m     3m 10009    rs_1  PRI   20:28:21
    70   2113   2665     21     914  1719|0       0   440g   895g  26.4g    246     db_2:190.9%         0     18|0     0|1      1m     3m 10009    rs_1  PRI   20:28:22
    72   2118   2671     24     920  1745|0       0   440g   895g  26.4g    310     db_2:193.9%         0     27|0     1|1      1m     2m 10009    rs_1  PRI   20:28:23
    63   2127   2529     25     927  1720|0       0   440g   895g  26.4g    326     db_2:191.3%         0     55|0     1|1      1m     4m 10009    rs_1  PRI   20:28:24
    59   2162   2754     22     845  1572|0       0   440g   895g  26.4g    251     db_2:191.4%         0     61|0     1|1      1m     2m 10009    rs_1  PRI   20:28:25
    61   2186   2662     23     910  1676|0       0   440g   895g  26.4g    264     db_2:192.3%         0     87|2     3|3      1m     2m 10009    rs_1  PRI   20:28:26
    79   2231   2642     26     908  1736|0       0   440g   895g  26.3g    227     db_2:190.7%         0     87|0     0|1      1m     2m 10009    rs_1  PRI   20:28:27
    66   2310   2705     24     912  1740|0       0   440g   895g  26.3g    275     db_2:191.4%         0     97|0     0|2      1m     2m 10009    rs_1  PRI   20:28:28
    56   2259   2640     22     920  1758|0       0   440g   895g  26.3g    345     db_2:190.6%         0    126|1     0|1      1m     3m 10009    rs_1  PRI   20:28:29
    78   2513   2745     31     948  1768|0       0   440g   895g  26.3g    267     db_2:189.1%         0    136|0     0|1      1m     3m 10009    rs_1  PRI   20:28:30
  ...
    52   2361   2738     21     926  1753|0       0   440g   895g  26.4g    149     db_2:189.8%         0     14|0     0|1      1m     2m 10009    rs_1  PRI   20:28:57
    45   2321   2570     13     921  1703|0       0   440g   895g  26.4g    161     db_2:190.2%         0      7|0     0|1      1m     3m 10009    rs_1  PRI   20:28:58
    57   2329   2716     21     972  1841|0       0   440g   895g  26.4g    151       db:15.8%          0      1|0     0|4      1m     3m 10009    rs_1  PRI   20:28:59

As you can see, there is no significant difference between workloads during lockdown. Both db and db_2 are constantly queried, db has mixed insert/update/find/delete workloads, while db_2 doing only updates with upsert. I'm trying to profile queries, but the chance to predict next lockdown is too low.

Do you have an idea about the reasons of that kind of troubles?

UPD: I realised that MongoDB frees huge piece of memory right before lags:

MongoDB free memory

After that it maps data back. I find it very strange, keep looking for the reason.

UPD2: checked workingSet and found, that it completely fits into memory by now: 866 721 pages * 4 KB/page ~ 3.3 GB vs. 62 GB of memory available on node.

1

The lock spike coincides with a spike in page faults in MMS, which means that for that period of time (which looks pretty brief), there is data being paged in off disk (that is: not in memory). Since you mention that you are doing updates I would guess that something about the updates during that time frame is hitting a rarely used section of the data that is no longer in memory (the kernel uses LRU to decide what stays in memory). The other possibility is that you are evicting db2 pages right before this because of some other activity and then attempting to use that data again (i.e. classic memory contention).

To get a better picture of this you could do before and after comparisons using something like mongomem but that may not tell you what the usage pattern is that is causing this, unless the data impacted is indicative.

On the usage front, with lock percentage hitting higher values like that you should see the occasional slow operation logged in the log files during that time. If not then perhaps drop your slowms value down a little (to 50ms for example) from the 100ms default and then see if anything gets logged. You can do this without a restart and without using profiling itself by using db.setProfilingLevel() as follows:

db.setProfilingLevel(0, 50)

This has less impact than full profiling and you can leave it on for a longer period to catch the slow operations, though it will cause your log files to be larger, so be careful about disk space for logs if things are tight.

For help filtering and visualizing log files, I highly recommend using mtools, though the usual suspects like grep, awk, sed etc. all work too. As always, beware the false positive - high lock can cause other regularly run operations (like db.serverStatus()) to show up as slow. They are symptoms rather than causes most of the time and they are showing up because they are being run continuously and can be blocked by a busy database or high lock.

  • Thanks for verbose answer, Adam. Unfortunately, I didn't find any unusual queries in slow log. But I found relation between free memory and lags. It would be great if you have any thoughts about the reason of release huge memory pieces. Is it usual pattern for MongoDB? – Vitaly Chirkov Oct 20 '14 at 9:00
  • MongoDB is not actually in control of the freeing of memory, rather the kernel is - so if you are seeing large sections of memory being freed up, then the kernel is doing that for some reason - perhaps another process, or something that needs to be tweaked in the vm settings? Do you have some swap configured? In the end, if you are not seeing slow queries, then it would appear that there is not a lot of impact to your database at present, though it would be nice to know what is causing the impact – Adam C Oct 20 '14 at 11:18
  • I mean there were slow queries, but the same queries performs well on healthy system. Gonna check system config. – Vitaly Chirkov Oct 20 '14 at 11:23
  • Ah, I see, delving into what is evicting memory can be a bit of a dark art. I can suggest making sure you have swap configured, that you have readahead set to a sane (not too high) value. Usually the vm.swappiness and dirty settings have little effect, but that will depend on your system. If you have a system that is not seeing this behavior with the same workload, then finding the difference is key. If it is a VM, don't forget to consider the other guest VMs - a badly behaving neighbor and a struggling hypervisor can cause some weird effects – Adam C Oct 20 '14 at 11:29
1

The reason of the problem was wrong index selection. Somehow Mongo was selecting wrong index and was using it for 20–40 seconds. Not sure, if it was caused by memory flushing or not. There were rare records with large nscanned in slow logs. We hot-fixed it with planCacheSetFilter.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.