Dlaczego każda działalność kilka minut na local.oplog.rs blokuje klientom Mongo

Question

problem:

Co jedna lub dwie minuty, klienci Mongo wstrzymać przez około 3 sekundy. Normalny czas działania aktualizacji wynosi około 1 lub 2 milisekundy. Kiedy pojawia się to spowolnienie, mamy kilka aktualizacji trwających od 1 do 3 sekund.

Dziennik powolnych zapytań nie pokazuje niczego związanego z tym. Ani debugowania klienta mongo (mongo-php-client).

Obecna architektura ma jeden wzorzec, 1 element podrzędny i jeden arytmiter w zestawie replik.

Wykonane zapytania są zawsze tego samego sortowania (upsert by _id, insert with new MongoId). Nie ma "co kilka minut uruchamiamy tę super kosztowną aktualizację"

Blokowanie wydaje się być spowodowane przez local.oplog.rs. Przynajmniej tak właśnie pokazuje wynik mongotopu. Nie znalazłem żadnego wskazania, że ​​wtórne powoduje ten problem, ponieważ wyjścia wszystkich poniższych poleceń wydają się być stabilne. Nie znalazłem żadnych informacji wskazujących, że spowolnienie spowodowane jest również przez konkretne zapytanie.

Pomysł przechowywania danych to wstępnie zgrupowane raporty. Mamy wiele aktualizacji (kilkaset na sekundę), ale bardzo niski odsetek zapytań. Indeksy są powiązane z daną datą (z wyjątkiem _id, który jest obliczany na podstawie klucza złożonego na podstawie wszystkich wymiarów zawartych w rekordzie. To wszystko oznacza, że ​​_id nie jest przyrostowy, tak jak w przypadku indeksu ObjectId). Wystarczy dać wyobrażenie, indeksy w największych kolekcji są (w MB):

"indexSizes" : { 
    "_id_" : 1967, 
    "owner_date" : 230, 
    "flow_date" : 231, 
    "date" : 170 
}, 

Większość innych kolekcjach mają indeksy wielkości 100 MB lub mniej. We wszystkich kolekcjach indeks _id jest największy. Warto zauważyć, że te identyfikatory są generowane ręcznie (na podstawie metadanych więc wprowadzenie odbywa się jako upsert i nie są przyrostowe)

obserwacji:

Edit1: Po więcej kopania, wydaje się, że blokowanie jest związane z procesem rsync dziennika, podczas przepłukiwania na dysk. Dziennik jest w tym samym systemie plików niż pliki danych, ale spowolnienie nie jest oczekiwane, ponieważ dyski są urządzeniami szybkiego ssd.

Edycja2: Po kilku testach możliwości zapisu dysków nie stanowią problemu. Zwykle piszemy z szybkością kilku megabajtów na sekundę. Korzystanie z niektórych testów na dysku akceptuje 150MB/s bez problemu

Oczekiwana odpowiedź:

Dlaczego ten przestój dzieje?

• Wskaźniki z możliwych przyczyn, w celu przeprowadzenia dalszych
• Doświadczenie/rozwiązanie oparte na podobnych przypadkach

Objaśnienie Problem:

następujące polecenia uruchomienia w głównym węzłem

Za każdym razem, gdy pojawia się powolność, widzimy w mongostacie (dwa exa): mples)

insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl  time 
    10 *0 141  *0  93 120|0  0.4 80.0  0 11.5G 9.4G 0|1 1|0 110k 71k 274 rs0 PRI 13:15:44 
    12 *0 178  *0  72 105|0  0.2 80.0  1 11.5G 9.4G 0|0 1|0 111k 79k 274 rs0 PRI 13:15:45 
    47 *0  7  *0  0 159|0  0.1 80.0  0 11.5G 9.4G 0|0 2|1 15k 44k 274 rs0 PRI 13:15:49 !!!!HERE 
    14 *0 929  *0  99 170|0  0.2 80.0  0 11.5G 9.4G 0|0 1|0 419k 417k 274 rs0 PRI 13:15:50 
    21 *0 287  *0  124 181|0  0.2 80.0  0 11.5G 9.4G 0|0 1|0 187k 122k 274 rs0 PRI 13:15:51 

insert query update delete getmore command % dirty % used flushes vsize res qr|qw ar|aw netIn netOut conn set repl  time 
    10 *0 145  *0  70 108|0  0.3 79.9  0 11.5G 9.4G 0|0 1|0 98k 71k 274 rs0 PRI 13:16:48 
    11 *0 155  *0  72 111|0  0.2 79.9  1 11.5G 9.4G 0|0 1|0 103k 75k 274 rs0 PRI 13:16:49 
    44 *0  3  *0  0 144|0  0.0 79.9  0 11.5G 9.4G 0|2 1|0 11k 75k 274 rs0 PRI 13:16:53 !!!!HERE 
    11 *0 837  *0  94 134|0  0.2 79.9  0 11.5G 9.4G 0|0 1|0 377k 348k 274 rs0 PRI 13:16:54 
    12 *0 180  *0  86 139|0  0.2 79.9  0 11.5G 9.4G 0|0 1|0 122k 85k 274 rs0 PRI 13:16:55 
    14 *0 195  *0  83 124|0  0.2 79.9  0 11.5G 9.4G 0|0 2|0 125k 89k 274 rs0 PRI 13:16:56 

kolumna aktualizacji zawiera kroplę, a kolejna zawiera znacznie więcej aktualizacji. Zauważ także, że używamy mongostatu z 1 sekundowym opóźnieniem. Kiedy pojawia się powolność, mongostat przestaje odpowiadać przez kilka sekund. Ogranicznik jest obecna tylko w module głównym, a nie w serwera podrzędnego

To wyjście mongotop kiedy to problem występuje (w 2015-07-07T13: 29: 38):

(przykład z nieco więcej kontekstu można znaleźć here)

                     ns total  read write 2015-07-07T13:29:33+02:00 
                  database_name.d_date_flow_owner 555ms 550ms  4ms        
                      local.oplog.rs  61ms  53ms  7ms        
                 database_name.client_context_bbbbbbb  15ms  0ms  15ms        
                 database_name.d_date_landing_owner  15ms  0ms  15ms        
                 database_name.d_date_billing_owner  10ms  0ms  10ms        
database_name.w_bl_carrier_country_date_device_flow_landing_manager_op1_os_owner_prod_site  7ms  0ms  7ms        
       database_name.d_carrier_country_date_device_flow_landing_op1_os_owner_site  5ms  0ms  5ms        
                 database_name.d_country_date_owner  5ms  0ms  5ms        
                 database_name.d_date_device_owner  5ms  0ms  5ms        
                  database_name.d_date_os_owner  5ms  0ms  5ms        

              ns total read write 2015-07-07T13:29:37+02:00 
     database_name.client_context_bbbbbbb  2ms  0ms  2ms        
     database_name.client_context_aaaaaaaaa  1ms  0ms  1ms        
        admin.system.backup_users  0ms  0ms  0ms        
        admin.system.namespaces  0ms  0ms  0ms        
         admin.system.new_users  0ms  0ms  0ms        
         admin.system.profile  0ms  0ms  0ms        
          admin.system.roles  0ms  0ms  0ms        
          admin.system.users  0ms  0ms  0ms        
         admin.system.version  0ms  0ms  0ms        
           database_name  0ms  0ms  0ms        

                     ns  total  read  write 2015-07-07T13:29:38+02:00 
                  local.oplog.rs 8171ms 4470ms 3701ms        
              database_name.d_date_op1_owner  45ms  0ms  45ms        
             database_name.d_date_device_owner  39ms  0ms  39ms        
               database_name.m_date_owner  34ms  0ms  34ms        
               database_name.d_date_owner  32ms  0ms  32ms        
              database_name.d_date_owner_site  31ms  0ms  31ms        
             database_name.d_carrier_date_owner  30ms  0ms  30ms        
              database_name.d_date_flow_owner  30ms  0ms  30ms        
             database_name.d_date_owner_product  28ms  0ms  28ms        
database_name.d_carrier_country_date_device_flow_landing_op1_os_owner_site  27ms  0ms  27ms        

                         ns total  read write 2015-07-07T13:29:39+02:00 
                  database_name.d_date_flow_owner 558ms 552ms  6ms        
                      local.oplog.rs  62ms  61ms  1ms        
                 database_name.d_carrier_date_owner  17ms  0ms  17ms        
                   database_name.d_date_owner  16ms  0ms  16ms        
database_name.w_bl_carrier_country_date_device_flow_landing_manager_op1_os_owner_prod_site  7ms  0ms  7ms        
                 database_name.d_date_billing_owner  6ms  0ms  6ms        
       database_name.d_carrier_country_date_device_flow_landing_op1_os_owner_site  5ms  0ms  5ms        
                 database_name.d_country_date_owner  5ms  0ms  5ms        
                 database_name.d_date_device_owner  5ms  0ms  5ms        
                  database_name.d_date_op1_owner  5ms  0ms  5ms        

Debug klienta php Mongo, który pokazuje problem (dwie ostatnie „PhpMongoClient debug” linie):

(przykład z nieco bardziej kontekst można znaleźć here)

Update duration: 2ms 
Update duration: 1ms 
Update duration: 1ms 
Update duration: 4006ms 
    PhpMongoClient debug: 2015-07-07 10:40:26 - PARSE (INFO): Parsing mongodb://primary_host.lan,secondary_host.lan 
    PhpMongoClient debug: 2015-07-07 10:40:26 - PARSE (INFO): - Found node: primary_host.lan:27017 
    [....] 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): limiting by credentials: done 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): sorting servers by priority and ping time 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): - connection: type: PRIMARY, socket: 42, ping: 0, hash: primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): sorting servers: done 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): selecting near servers 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): selecting near servers: nearest is 0ms 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): - connection: type: PRIMARY, socket: 42, ping: 0, hash: primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (FINE): selecting near server: done 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (INFO): pick server: random element 0 
    PhpMongoClient debug: 2015-07-07 10:40:26 - REPLSET (INFO): - connection: type: PRIMARY, socket: 42, ping: 0, hash: primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751 
    PhpMongoClient debug: 2015-07-07 10:40:26 - CON (FINE): No timeout changes for primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751 
    PhpMongoClient debug: 2015-07-07 10:40:30 - CON (FINE): No timeout changes for primary_host.lan:27017;rs0;database_name/user/5ca571e7db198eeee3abee35857bfd53;30751 
Update duration: 3943ms 
Update duration: 3476ms 
Update duration: 2008ms 
Update duration: 961ms 
Update duration: 956ms 
Update duration: 20ms 
Update duration: 20ms 
Update duration: 3ms 
Update duration: 42ms 
Update duration: 24ms 
Update duration: 25ms 
Update duration: 56ms 
Update duration: 24ms 
Update duration: 11ms 
Update duration: 11ms 
Update duration: 3ms 
Update duration: 2ms 
Update duration: 3ms 
Update duration: 1ms 
Update duration: 1ms 
Update duration: 1ms 
Update duration: 2ms 

Mongo informacje:

• Mongo wersja: 3.0.3
• repliki ustawiony z 1 podrzędnego i 1 arbiter
• opóźnienia replikacji zmienia się między 0 i 4 sekundy
• Silnik : WiredTiger
• System plików: XFS
• Oper System ative: Red Hat Enterprise Linux Server wersja 7.1
• Pamięć: 24 GB. Zgłoszone przez htop jako 40% używane, 60% pamięci podręcznej

Answer 1

Ten problem zniknął. Podjęto dwa działania:

1. Przerobiono system raportów pre-aggregated. Obciążenie pracą mangi zmniejszono o 10 razy.
2. Zaktualizowana wersja Mongo do 3.0.6

Niestety, dwie zmiany zostały wprowadzone w Internecie bez dużo czasu między nimi. Podejrzewam, że zmniejszenie obciążenia spowodowało podstęp (który może, ale nie musi, być powiązany z problemem, który @ steve-brisk wskazał) przynajmniej na razie (zobaczymy, kiedy ponownie uderzymy w poprzednie poziomy obciążenia).Jednak w związku z aktualizacją wersji może się zdarzyć, że nawet przy poprzednich poziomach obciążenia nie będziemy mogli ponownie trafić w ten problem. Nie mam żadnych dowodów wskazujących na jedno z dwóch rozwiązań. Ale po ich obu problem został rozwiązany.