{"id":53590,"date":"2019-12-05T00:00:00","date_gmt":"2019-12-04T21:00:00","guid":{"rendered":"https:\/\/prohoster.info\/blog\/blog_prohoster\/kak-my-v-tsian-ukroshhali-terabajty-logov"},"modified":"2020-02-18T14:01:30","modified_gmt":"2020-02-18T11:01:30","slug":"kak-my-v-tsian-ukroshhali-terabajty-logov","status":"publish","type":"post","link":"https:\/\/prohoster.info\/pl\/blog\/administrirovanie\/kak-my-v-tsian-ukroshhali-terabajty-logov","title":{"rendered":"Jak w CIAN okie\u0142znali\u015bmy terabajty log\u00f3w","gt_translate_keys":[{"key":"rendered","format":"text"}]},"content":{"rendered":"

\"Jak
\n
\nCze\u015b\u0107 wszystkim, nazywam si\u0119 Aleksander, pracuj\u0119 w CIAN jako in\u017cynier i zajmuj\u0119 si\u0119 zarz\u0105dzaniem systemami oraz automatyzacj\u0105 proces\u00f3w infrastrukturalnych. W komentarzach do jednego z wcze\u015bniejszych artyku\u0142\u00f3w poproszono nas o opowiedzenie, sk\u0105d bierzemy 4 TB log\u00f3w dziennie i co z nimi robimy. Tak, mamy du\u017co log\u00f3w, a do ich przetwarzania stworzyli\u015bmy osobny klaster infrastrukturalny, kt\u00f3ry pozwala nam szybko rozwi\u0105zywa\u0107 problemy. W tym artykule opowiem, jak przez rok dostosowali\u015bmy go do pracy z ci\u0105gle rosn\u0105cym strumieniem danych.
\n<\/a><\/noindex><\/p>\n

Od czego zaczynali\u015bmy<\/h3>\n

\n\"Jak
\n
\nW ci\u0105gu ostatnich kilku lat obci\u0105\u017cenie na cian.ru ros\u0142o bardzo szybko, a w trzecim kwartale 2018 roku odwiedzalno\u015b\u0107 zasobu osi\u0105gn\u0119\u0142a 11,2 mln unikalnych u\u017cytkownik\u00f3w miesi\u0119cznie. W krytycznych momentach tracili\u015bmy do 40% log\u00f3w, przez co nie mogli\u015bmy szybko zajmowa\u0107 si\u0119 incydentami i tracili\u015bmy bardzo du\u017co czasu i energii na ich rozwi\u0105zanie. Cz\u0119sto te\u017c nie mogli\u015bmy znale\u017a\u0107 przyczyny problemu, a on powtarza\u0142 si\u0119 po pewnym czasie. To by\u0142 koszmar, z kt\u00f3rym trzeba by\u0142o co\u015b zrobi\u0107.<\/p>\n

W tym czasie do przechowywania log\u00f3w u\u017cywali\u015bmy klastra z\u0142o\u017conego z 10 w\u0119z\u0142\u00f3w danych z ElasticSearch w wersji 5.5.2 z typowymi ustawieniami indeks\u00f3w. Zosta\u0142 on wprowadzony ponad rok temu jako popularne i dost\u0119pne rozwi\u0105zanie: wtedy strumie\u0144 log\u00f3w nie by\u0142 tak du\u017cy, wi\u0119c nie by\u0142o sensu wymy\u015bla\u0107 niestandardowych konfiguracji.\u00a0<\/p>\n

Przetwarzanie nadchodz\u0105cych log\u00f3w zapewnia\u0142 Logstash na r\u00f3\u017cnych portach na pi\u0119ciu koordynatorach ElasticSearch. Jeden indeks, niezale\u017cnie od rozmiaru, sk\u0142ada\u0142 si\u0119 z pi\u0119ciu shard\u00f3w. By\u0142a zorganizowana godzinowa i dzienna rotacja, w wyniku czego co godzin\u0119 w klastrze pojawia\u0142o si\u0119 oko\u0142o 100 nowych shard\u00f3w. Dop\u00f3ki log\u00f3w by\u0142o niewiele, klaster sobie radzi\u0142 i nikt nie zwraca\u0142 uwagi na jego ustawienia.\u00a0<\/p>\n

Problemy z szybkim wzrostem<\/h3>\n

\nWielko\u015b\u0107 generowanych log\u00f3w ros\u0142a bardzo szybko, poniewa\u017c na siebie nak\u0142ada\u0142y si\u0119 dwa procesy. Z jednej strony u\u017cytkownik\u00f3w serwisu przybywa\u0142o coraz wi\u0119cej. Z drugiej strony zacz\u0119li\u015bmy aktywnie przechodzi\u0107 na architektur\u0119 mikrous\u0142ug, dziel\u0105c nasze stare monolity na C# i Pythona. Kilkadziesi\u0105t nowych mikrous\u0142ug, zast\u0119puj\u0105cych cz\u0119\u015bci monolitu, generowa\u0142o znacznie wi\u0119cej log\u00f3w dla infrastrukturalnego klastra.\u00a0<\/p>\n

To w\u0142a\u015bnie skalowanie doprowadzi\u0142o do tego, \u017ce klaster sta\u0142 si\u0119 praktycznie niezarz\u0105dzalny. Kiedy logi zacz\u0119\u0142y przychodzi\u0107 z pr\u0119dko\u015bci\u0105 20 tysi\u0119cy komunikat\u00f3w na sekund\u0119, cz\u0119sta bezu\u017cyteczna rotacja zwi\u0119kszy\u0142a liczb\u0119 shard\u00f3w do 6 tysi\u0119cy, a na jeden w\u0119ze\u0142 przypada\u0142o ponad 600 shard\u00f3w.\u00a0<\/p>\n

Prowadzi\u0142o to do problem\u00f3w z przydzielaniem pami\u0119ci operacyjnej, a przy awarii w\u0119z\u0142a rozpoczyna\u0142a si\u0119 r\u00f3wnoczesna migracja wszystkich shard\u00f3w, co zwi\u0119ksza\u0142o ruch i obci\u0105\u017ca\u0142o pozosta\u0142e w\u0119z\u0142y, co praktycznie uniemo\u017cliwia\u0142o zapis danych w klastrze. W tym czasie pozostawali\u015bmy bez log\u00f3w. A przy problemie z serwerem<\/a> tracili\u015bmy 1\/10 klastra. Dodatkowo, du\u017ca liczba indeks\u00f3w ma\u0142ych rozmiar\u00f3w wprowadza\u0142a dodatkowe trudno\u015bci.<\/p>\n

Bez log\u00f3w nie rozumieli\u015bmy przyczyn incydent\u00f3w i mogli\u015bmy pr\u0119dzej czy p\u00f3\u017aniej natkn\u0105\u0107 si\u0119 na te same problemy ponownie, a w ideologii naszego zespo\u0142u by\u0142o to niedopuszczalne, poniewa\u017c wszystkie mechanizmy naszej pracy s\u0105 nastawione na to, aby nigdy nie powtarza\u0107 tych samych problem\u00f3w. Potrzebowali\u015bmy pe\u0142nego zestawu log\u00f3w i ich dostarczania praktycznie w czasie rzeczywistym, poniewa\u017c zesp\u00f3\u0142 in\u017cynier\u00f3w dy\u017curnych monitorowa\u0142 alerty nie tylko z metryk, ale r\u00f3wnie\u017c z log\u00f3w. Dla zrozumienia skali problemu \u2014 w tym czasie ca\u0142kowita ilo\u015b\u0107 log\u00f3w wynosi\u0142a oko\u0142o 2 TB dziennie.\u00a0<\/p>\n

Postawili\u015bmy sobie zadanie \u2014 ca\u0142kowicie wyeliminowa\u0107 utrat\u0119 log\u00f3w i skr\u00f3ci\u0107 czas ich dostarczania do klastra ELK maksymalnie do 15 minut w przypadku sytuacji awaryjnych (na t\u0119 liczb\u0119 w dalszej cz\u0119\u015bci opierali\u015bmy si\u0119 jako na wewn\u0119trznym KPI).<\/p>\n

Nowy mechanizm rotacji i hot-warm w\u0119z\u0142y<\/h3>\n

\n\"Jak
\n
\nTransformacj\u0119 klastra rozpocz\u0119li\u015bmy od aktualizacji wersji ElasticSearch z 5.5.2 do 6.4.3. Nasz klaster wersji 5 kolejny raz si\u0119 zawiesi\u0142, wi\u0119c zdecydowali\u015bmy si\u0119 go wy\u0142\u0105czy\u0107 i ca\u0142kowicie zaktualizowa\u0107 \u2014 log\u00f3w i tak nie by\u0142o. Tak wi\u0119c t\u0119 migracj\u0119 przeprowadzili\u015bmy w zaledwie kilka godzin.<\/p>\n

Najwi\u0119ksz\u0105 zmian\u0105 na tym etapie by\u0142o wprowadzenie na trzech w\u0119z\u0142ach z koordynatorem jako bufor po\u015bredni Apache Kafka. Broker wiadomo\u015bci uwolni\u0142 nas od utraty log\u00f3w podczas problem\u00f3w z ElasticSearch. Jednocze\u015bnie dodali\u015bmy do klastra 2 w\u0119z\u0142y i przeszli\u015bmy na architektur\u0119 hot-warm z trzema \u201egor\u0105cymi\u201d w\u0119z\u0142ami, umiejscowionymi w r\u00f3\u017cnych szafach w centrum danych. Na nich kierowali\u015bmy logi, kt\u00f3rych nie mo\u017cna by\u0142o straci\u0107 w \u017cadnym wypadku \u2014 nginx oraz logi b\u0142\u0119d\u00f3w aplikacji. Na pozosta\u0142e w\u0119z\u0142y przesy\u0142ane by\u0142y logi mniejsze \u2014 debug, warning itp., a tak\u017ce po 24 godzinach przenoszone by\u0142y \u201ewa\u017cne\u201d logi z \u201egor\u0105cych\u201d w\u0119z\u0142\u00f3w.<\/p>\n

Aby nie zwi\u0119ksza\u0107 liczby ma\u0142ych indeks\u00f3w, przeszli\u015bmy z rotacji czasowej na mechanizm rollover. Na forach by\u0142o wiele informacji na temat tego, \u017ce rotacja wed\u0142ug rozmiaru indeksu jest bardzo niewiarygodna, dlatego postanowili\u015bmy u\u017cy\u0107 rotacji wed\u0142ug liczby dokument\u00f3w w indeksie. Przeanalizowali\u015bmy ka\u017cdy indeks i ustalili\u015bmy liczb\u0119 dokument\u00f3w, po kt\u00f3rej powinno nast\u0105pi\u0107 rotacja. W ten spos\u00f3b osi\u0105gn\u0119li\u015bmy optymalny rozmiar sharda \u2014 nie wi\u0119cej ni\u017c 50 GB.\u00a0<\/p>\n

Optymalizacja klastra<\/h3>\n

\n\"Jak
\n
\nJednak ca\u0142kowicie nie pozbyli\u015bmy si\u0119 problem\u00f3w. Niestety, nadal pojawia\u0142y si\u0119 ma\u0142e indeksy: nie osi\u0105ga\u0142y one okre\u015blonej wielko\u015bci, nie rotowa\u0142y si\u0119 i by\u0142y usuwane podczas globalnego czyszczenia indeks\u00f3w starszych ni\u017c trzy dni, poniewa\u017c zrezygnowali\u015bmy z rotacji wed\u0142ug daty. Prowadzi\u0142o to do utraty danych, poniewa\u017c indeks znika\u0142 ca\u0142kowicie z klastra, a pr\u00f3ba zapisu do nieistniej\u0105cego indeksu \u0142ama\u0142a logik\u0119 curatora, kt\u00f3rego u\u017cywali\u015bmy do zarz\u0105dzania. Alias do zapisu przekszta\u0142ca\u0142 si\u0119 w indeks i \u0142ama\u0142 logik\u0119 rollovera, powoduj\u0105c niekontrolowany wzrost niekt\u00f3rych indeks\u00f3w do 600 GB.\u00a0<\/p>\n

Na przyk\u0142ad dla konfiguracji rotacji:<\/p>\n

curator-elk-rollover.yaml\n\n---\nactions:\n 1:\n action: rollover\n options:\n name: \"nginx_write\"\n conditions:\n max_docs: 100000000\n 2:\n action: rollover\n options:\n name: \"python_error_write\"\n conditions:\n max_docs: 10000000\n<\/code><\/pre>\n
W przypadku braku rollover alias wyst\u0119powa\u0142 b\u0142\u0105d:<\/p>\n
ERROR     alias \"nginx_write\" not found.\nERROR     Failed to complete action: rollover.  : Unable to perform index rollover with alias \"nginx_write\".\n<\/code><\/pre>\n
Rozwi\u0105zanie tego problemu zostawili\u015bmy na nast\u0119pn\u0105 iteracj\u0119 i zaj\u0119li\u015bmy si\u0119 inn\u0105 kwesti\u0105: przeszli\u015bmy na logik\u0119 pull w pracy Logstasha, zajmuj\u0105cego si\u0119 przetwarzaniem przychodz\u0105cych log\u00f3w (usuwaniem zb\u0119dnych informacji i wzbogacaniem ich). Umie\u015bcili\u015bmy go w dockera, kt\u00f3ry uruchamiamy przez docker-compose, tam r\u00f3wnie\u017c umie\u015bcili\u015bmy logstash-exportera, kt\u00f3ry przekazuje metryki do Prometheusa do bie\u017c\u0105cego monitorowania przep\u0142ywu log\u00f3w. Dzi\u0119ki temu umo\u017cliwili\u015bmy sobie p\u0142ynne zmienianie liczby instancji logstasha odpowiedzialnych za przetwarzanie ka\u017cdego typu log\u00f3w.<\/p>\n
Podczas gdy doskonalili\u015bmy klaster, frekwencja na cian.ru wzros\u0142a do 12,8 mln unikalnych u\u017cytkownik\u00f3w miesi\u0119cznie. W rezultacie nasze przekszta\u0142cenia nie nad\u0105\u017ca\u0142y nieco za zmianami na produkcji, i napotkali\u015bmy problem, \u017ce \u201eciep\u0142e\u201d w\u0119z\u0142y nie radzi\u0142y sobie z obci\u0105\u017ceniem i spowalnia\u0142y ca\u0142y przep\u0142yw log\u00f3w. Dane \u201egor\u0105ce\u201d otrzymywali\u015bmy bez zak\u0142\u00f3ce\u0144, ale w dostaw\u0119 pozosta\u0142ych musieli\u015bmy ingerowa\u0107 i przeprowadza\u0107 r\u0119czn\u0105 rotacj\u0119, aby r\u00f3wnomiernie rozdzieli\u0107 indeksy.\u00a0<\/p>\n
Przy tym skalowanie i zmiana ustawie\u0144 instancji logstasha w klastrze komplikowa\u0142y si\u0119 tym, \u017ce by\u0142 to lokalny docker-compose, a wszystkie dzia\u0142ania by\u0142y wykonywane r\u0119cznie (aby doda\u0107 nowe ko\u0144c\u00f3wki, nale\u017ca\u0142o r\u0119cznie przej\u015b\u0107 przez wszystkie serwery i wsz\u0119dzie wykona\u0107 docker-compose up -d).<\/p>\n
Przegrupowanie log\u00f3w<\/h3>\n
\nW wrze\u015bniu tego roku nadal kontynuowali\u015bmy rozdzielanie monolitu, obci\u0105\u017cenie klastra wzrasta\u0142o, a przep\u0142yw log\u00f3w zbli\u017ca\u0142 si\u0119 do 30 tysi\u0119cy wiadomo\u015bci na sekund\u0119.\u00a0<\/p>\n
\"Jak
\n
\nNast\u0119pn\u0105 iteracj\u0119 rozpocz\u0119li\u015bmy od aktualizacji sprz\u0119tu. Z pi\u0119ciu koordynator\u00f3w przeszli\u015bmy na trzech, wymienili\u015bmy w\u0119z\u0142y danych i zyskali\u015bmy pod wzgl\u0119dem koszt\u00f3w i pojemno\u015bci magazynu. Dla w\u0119z\u0142\u00f3w u\u017cywamy dw\u00f3ch konfiguracji:\u00a0<\/p>\n