Architektura serwerów – wydajność przetwarzania zapytań cz.2

Kontynuujemy nasze zmagania z przetwarzaniem zapytań. W pierwszej części zdefiniowaliśmy problem i podjęliśmy pierwsze próby implementacji rozwiązania. Szybko jednak okazało się, że istnieją lepsze metody. Dzisiaj będziemy eksperymentować z wielowątkowością. Oczywiście nie obejdzie się bez problemów…

Kod źródłowy eksperymentów można znaleźć tutaj.

Przejdźmy do rzeczy – ostanie wyniki pokazały, że nasz procesor się nudzi. Zapytania są niezależne więc wielowątkowość wydaje się być naturalnym remedium. Zróbmy więc tak jak robi wiele serwerów – każde zapytanie będzie obsługiwane przez osobny wątek.

Nasza (naiwna) implementacja będzie wyglądać mniej więcej tak:

for_each request in 100k_requests:
    create_thread(RequestProcessor::Process(request))

Uruchamiamy więc nasz program:

$ ./processing_pipeline 2
Running Experiment_2_thread_per_req
Experiment interrupted - exception thrown: Resource temporarily unavailable
Only 32747 threads created
Waited 3951.76 ms, avg 25305.2 trans/sec

Hmm… Program przerwał działanie. Widzimy, że udało się stworzyć 32 747 wątków. Prawdopodobnie nie powiodło się stworzenie kolejnego wątku. Sprawdźmy tą hipotezę:

$ gdb ./processing_pipeline
...
(gdb) catch throw
(gdb) run 2
...
(gdb) bt
#0  0x00007ffff78c58bd in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#1  0x00007ffff78ee7fe in std::__throw_system_error(int) () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#2  0x00007ffff78f0e73 in std::thread::_M_start_thread(...)
#3  0x000000000040eabe in std::thread::thread<...>(...)...
<...>
#7  0x0000000000404705 in Experiment_2_thread_per_req () at main.cpp:92
#8  0x00000000004058ce in main (argc=2, argv=0x7fffffffdcb8) at main.cpp:294

Tak, próba stworzenia nowego obiektu std::thread nie powiodła się. Zapewne przekroczyliśmy jakiś limit. Pytanie tylko o jaki limit chodzi? Bo nie ma czegoś takiego jak limit wątków… W systemie Linux mamy kilka limitów które mogą ograniczać bezpośrednio lub pośrednio liczbę wątków i/lub procesów:

  • Globalny limit procesów (wątek też liczony jako proces) zdefiniowany w /proc/sys/kernel/threads-max. U mnie ustawiony jest na:
$ cat /proc/sys/kernel/threads-max
513640
  • Górny limit wartości jaki może przyjąć deskryptor (pid) procesu (i wątku) zdefiniowany w /proc/sys/kernel/pid_max, wartość jest obliczana przez kernel na podstawie prostej formuły: 1024 * liczba_rdzeni * liczba_wątków_per_rdzeń.
$ cat /proc/sys/kernel/pid_max
32768
  • Maksymalna liczba zmapowanych obszarów pamięci w procesie (więcej tego typu limitów tutaj). Limit ten można odczytać w /proc/sys/vm/max_map_count:
$ cat /proc/sys/vm/max_map_count
65530

A co to oznacza w praktyce? Zajrzyjmy w dokumentację:

max_map_count:

This file contains the maximum number of memory map areas a process
may have. Memory map areas are used as a side-effect of calling
malloc, directly by mmap, mprotect, and madvise, and also when loading
shared libraries.

While most applications need less than a thousand maps, certain
programs, particularly malloc debuggers, may consume lots of them,
e.g., up to one or two maps per allocation.

The default value is 65536.

W skrócie można powiedzieć, że licznik zmapowanych obszarów pamięci powiększa się kiedy np. ładujemy bibliotekę so, kiedy alokator pamięci dostaje nowy blok z kernela, bezpośrednie wywołania mmap, mprotect, madvise, i co dla nas najważniejsze – tworzenie wątku.

  • RLIMIT_AS, RLIMIT_DATA – limit wielkości wirtualnej przestrzeni i limit segmentu danych dla procesu (zmienne zainicjowane, niezainicjowane, sterta (heap). Limity te mogą być zmieniane jednaj wartości domyślne łatwo odczytać (podobnie jak ulimit -a ale mamy więcej detali):
$ cat /proc/self/limits
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        0                    unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             256820               256820               processes 
Max open files            1024                 1048576              files     
Max locked memory         65536                65536                bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       256820               256820               signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us 
  • Limit wynikający z braku wirtualnej pamięci dla nowych wątków. Każdy nowy wątek dostaje stos dla którego system operacyjny przydziela pewien obszar pamięci w wirtualnej przestrzeni. Obecnie dla systemów 64 bitowych stosowany jest model kanoniczny, czyli wykorzystujemy tylko 48 bitów do adresacji. Więc cała przestrzeń to 2^64. Przestrzeń użytkownika to połowa z tego – 128 TB. Szczegóły tutaj. Z drugiej strony stos zajmuje:
$ ulimit -s
8192

Co oznacza 8192 kB * 1024 = 8388608M = 8 MB. Teoretycznie mamy miejsce w wirtualnej pamięci na 128 TB / 8 MB = 16 777 216 wątków.

  • Inne limity zdefiniowane dla użytkownika jak np. max user processes.
$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 256820
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 256820
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

Ok, uzbrojeni w pewną wiedzę teoretyczną kontynuujmy nasze śledztwo. Jak zwykle warto zobaczyć jakie funkcje systemowe zostały wywołane, ile i z jakim skutkiem:

$ strace -c ./processing_pipeline 2
Running Experiment_2_thread_per_req
Experiment interrupted - exception thrown: Resource temporarily unavailable
Only 32747 threads created
Waited 2993.39 ms, avg 33406.9 trans/sec
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 28.10    0.000558           0     32747           clone
 26.13    0.000519           0     32759         1 mprotect
 24.07    0.000478           0     32748           munmap
 19.18    0.000381           0     32770           mmap
  1.81    0.000036           0      3806           brk
  0.70    0.000014           0       291        18 futex
  0.00    0.000000           0         6           read
  0.00    0.000000           0         8           write
  0.00    0.000000           0         7           open
  0.00    0.000000           0         7           close
  0.00    0.000000           0         7           fstat
  0.00    0.000000           0         3           lseek
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         7         7 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.001986                135174        26 total

Widzimy, że wywołanie funkcji futex dało negatywne rezultaty aż 18 razy. Jednak sama funkcja została wywołana tylko 291 razy co nie odpowiada ilości stworzonych wątków. Za to ciekawy trop daje nam funkcja systemowa mprotect – wywołana została 32 759 razy czyli prawie tyle co liczba naszych wątków (32 747). Ale najciekawsze jest to, że tylko jeden raz zwróciła błąd. Sprawdźmy co to za błąd:

$ strace -e trace=mprotect ./processing_pipeline 2 2>&amp;1| grep "= -1"                                                                      
mprotect(0x7fa762ba1000, 4096, PROT_NONE) = -1 ENOMEM (Cannot allocate memory)

Dokumentacja lakonicznie stwierdza:

ENOMEM Internal kernel structures could not be allocated.

Ale możemy zrobić dwie rzeczy – rzucić okiem w kod źródłowy kernela albo zaryzykować hipotezę, że limit mapowania obszarów pamięci został przekroczony (mprotect jest wymieniana jako funkcja mogąca naruszyć ten limit). Jednak aby mieć podstawy do uznania hipotezy za prawdopodobną trzeba wykazać, że ograniczenie 65530 zostało naruszone. Więc policzmy liczbę wywołań: 32759 − 1 (mprotect) + 32770 (mmap) = 65528. Różnica może wynikać z dodatkowych czynności jak ładowanie bibliotek so. Przegląd kodu kernela nie daje jednoznacznej odpowiedzi ponieważ istnieje wiele ścieżek prowadzących do ENOMEM. Najciekawsze funkcje pomocnicze to may_expand_vm, __vm_enough_memory i find_vma które sprawdzają różne limity więc trudno wskazać jednoznacznie przyczynę bez głębszej analizy.

Ale jedną rzecz łatwo zrobić – mamy już hipotezę o przekroczonym limicie mapowania pamięci, liczby potwierdzają nasze przypuszczenia – pozostał więc eksperyment do wykonania – zwiększmy ten limit i zobaczmy co się stanie:

# echo 100000 > /proc/sys/vm/max_map_count
--------------------------------------------------
$ strace -c ./processing_pipeline 2
Running Experiment_2_thread_per_req
Experiment interrupted - exception thrown: Resource temporarily unavailable
Only 49983 threads created
Waited 3990.99 ms, avg 25056.4 trans/sec
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.91    0.000887           0     50007           mmap
 30.07    0.000863           0     49995         1 mprotect
 19.06    0.000547           0     49983           clone
 17.21    0.000494           0     49985           munmap
  2.75    0.000079           0      5799           brk
  0.00    0.000000           0         6           read
  0.00    0.000000           0         8           write
  0.00    0.000000           0         7           open
  0.00    0.000000           0         7           close
  0.00    0.000000           0         7           fstat
  0.00    0.000000           0         3           lseek
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         7         7 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0       348        18 futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.002870                206170        26 total

Wyników chyba nie muszę komentować. Mamy przyczynę niepowodzenia. Jako ciekawostkę podam stos wywołań, który prowadzi do funkcji mprotect:

(gdb) bt
#0  0x00007ffff7050777 in mprotect () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007ffff7bc24fa in allocate_stack (...) at allocatestack.c:649
#2  __pthread_create_2_1 (...) at pthread_create.c:539
#3  0x00007ffff78f0dc3 in std::thread::_M_start_thread(...) from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x000000000040eabe in std::thread::thread(...)... 
...
#8  0x0000000000404705 in Experiment_2_thread_per_req () at main.cpp:92
#9  0x00000000004058ce in main (argc=2, argv=0x7fffffffdcb8) at main.cpp:294

Więc co teraz? Możemy manipulować limitami ale jest to bardzo zła droga w tym przypadku. Nadmierna liczba wątków negatywnie wpływa na wydajność. Trzeba to jakoś ograniczyć programowo. Najprostsze podejście może wyglądać tak:

max_thread_limit = 100
while not done:
    thread_num = 0
    while thread_num < max_thread_limit:
        request = 100k_requests.get_next()
        create_thread(RequestProcessor::Process(request))
        thread_num++
    wait_for_all_threads()

Odpalmy więc nasz program i zobaczmy jakie korzyści daje nam wielowątkowość:

./processing_pipeline 3
Running Experiment_3_thread_per_req_with_throttle for 100 threads
Control result: 6.49994e+10
Total sleep: 18920 ms, # yield: 49800, # requests: 100000
Waited 25767.7 ms, avg 3880.83 trans/sec

WTF??? Wynik gorszy niż w przypadku przetwarzania sekwencyjnego opisanego w poprzednim artykule! Dla przypomnienia:

$ ./processing_pipeline 1
Running Experiment_1_single_threaded
Control result: 6.49994e+10
Total sleep: 18920 ms, # yield: 49800, # requests: 100000
Waited 23612.7 ms, avg 4235 trans/sec

Czyli teraz mamy ponad 25 sekund! Co z tą wielowątkowością?

Otóż powyższy przykład pokazuje jak nieumiejętne korzystanie z tego narzędzia przynosi więcej szkód niż pożytku. Celowo pokazałem jakie problemy z limitami możemy napotkać. Niestety często podczas testów możemy tych problemów nie zauważyć gdyż same limity są dość wysoko ustawione a analiza takich zdarzeń może być trudna. Jak zwykle poinformuje nas o problemach niespecjalnie szczęśliwy klient. Druga sprawa to ślepa wiara w sprawczą moc wielowątkowości. Nasze zrównoleglenie nie pomogło, a przynajmniej nie to naiwne podejście. W kolejnej części zobaczymy co poszło nie tak i gdzie jest problem. Zobaczymy też jak można usprawnić nasz algorytm aby wielowątkowość okazała się skuteczna.

Dodaj komentarz

Twój adres email nie zostanie opublikowany. Pola, których wypełnienie jest wymagane, są oznaczone symbolem *