Mam kilka serwerów linuksowych z uruchomionym serwerem ruchu apache i znalazłem około 1/20 żądań, które trwają kilka milisekund, co jest znacznie dłuższe niż oczekiwano (powinno być 1-2ms).dlaczego copy_to_user spędza kilkaset milisekund?
Po śledzeniu przez systemtap, znalazłem czas spędzony na wywoływaniu jądra Linux copy_to_user(). (accept-> inet_csk_accept-> move_addr_to_user-> copy_to_user)
Obciążenie serwera jest rzucić niska (< 100qps) i copy_to_user() po prostu skopiować dane 16 bajtów (struct sockaddr), ale wydawać setki milisekundy.
Jako że jestem nowy w technikach śledzenia systemtap i jądra, nie mogę zbadać dalszego powodu. Sprawdziłem użycie procesora, zamieniam użycie
Dziękuję za radę.
Sprzęt:
- CPU Intel (R) Xeon (R) E5-2640 procesora V3 @ 2.60GHz
- pamięci: 64G
- dysku: 11 * 6T dysku
Software:
- centos6 2.6.32-696.el6.x86_64 # 1 SMP czw 21 marca 2017 19:29:05 UTC x86_64 x86_64 x86_64 GNU/Linux
- apache trafficserver 5.3.2 Konfiguracja 10G RAM
nginx 1.10.2, pełnomocnik żądanie użytkownika do trafficserver
// systemtap probe kernel.function("move_addr_to_user") { ts["move_addr_to_user", pid()] = gettimeofday_ms() } probe kernel.function("move_addr_to_user").return { printf("[%d]move_addr_to_user done:%d %s %d\n", gettimeofday_ms(), pid(), execname(), gettimeofday_ms()-ts["move_addr_to_user", pid()]) } probe kernel.function("copy_to_user") { ts["copy_to_user", pid()] = gettimeofday_ms() } probe kernel.function("copy_to_user").return { printf("[%d]copy_to_user done:%d %s %d %d\n", gettimeofday_ms(), pid(), execname(), gettimeofday_ms()-ts["copy_to_user", pid()], gettimeofday_ms()-ts["__copy_to_user", pid()]) } // output: [1495630190767] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 0 [1495630191164]copy_to_user done:24145 [ACCEPT 0:8080] 0 [1495630191164] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 0 [1495630192172]copy_to_user done:24145 [ACCEPT 0:8080] 861 [1495630192172] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 861 [1495630192173]copy_to_user done:24145 [ACCEPT 0:8080] 0 [1495630192173] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 0 [1495630192173]copy_to_user done:24145 [ACCEPT 0:8080] 0 [1495630192173] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 0 [1495630192173]copy_to_user done:24145 [ACCEPT 0:8080] 0 free -g total used free shared buffers cached Mem: 62 55 6 0 0 32 -/+ buffers/cache: 23 39 Swap: 15 0 15 top - 20:57:39 up 24 days, 19:26, 2 users, load average: 7.70, 9.43, 9.62 Tasks: 643 total, 1 running, 642 sleeping, 0 stopped, 0 zombie Cpu(s): 0.1%us, 1.0%sy, 0.0%ni, 97.5%id, 1.1%wa, 0.0%hi, 0.3%si, 0.0%st Mem: 65560992k total, 58525192k used, 7035800k free, 365084k buffers Swap: 16777212k total, 0k used, 16777212k free, 33957572k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 24145 traffics 20 0 21.7g 12g 6212 S 24.7 19.3 212:42.85 [ET_NET 0] 22173 root 20 0 677m 325m 1180 S 3.6 0.5 0:41.10 nginx 22161 root 20 0 677m 325m 1184 S 2.6 0.5 0:47.50 nginx 22168 root 20 0 677m 326m 2076 S 2.6 0.5 0:28.31 nginx 22150 root 20 0 677m 325m 1208 S 1.6 0.5 0:42.75 nginx 22165 root 20 0 677m 325m 1200 S 1.6 0.5 0:31.77 nginx
Aktualizacja:
@pracownik miesiąca dziękuję za poradę, po dodaniu sondowania do __do_page_fault, znalazłem czas spędzony na __do_page_fault -> down_read (& mm-> mmap_sem);
[1495677639202]copy_to_user done:24145 [ACCEPT 0:8080] 1
[1495677639202] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 1
[1495677639314]copy_to_user done:24145 [ACCEPT 0:8080] 0
[1495677639314] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 0
[1495677641329]do page fault done:24145 [ACCEPT 0:8080] 622
[1495677641329]copy_to_user done:24145 [ACCEPT 0:8080] 622
[1495677641329] 16 16 move_addr_to_user done:24145 [ACCEPT 0:8080] 622
@Ricardo Biehl Pasquali dzięki za radę. Serwer plików Apache odczytuje/zapisuje na hdd w oddzielnych wątkach. trafficserver ma 1 wątek do akceptowania połączeń, wątki 88 (8 wątków na hdd) do blokowania odczytu/zapisu (zawartość pamięci podręcznej), ale nie rozumiem, dlaczego blokowanie odczytu/zapisu w innych wątkach może prowadzić do wysokiej latencji __do_page_fault() .
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 16.00 0.00 4.00 0.00 160.00 40.00 0.05 13.50 0.00 13.50 7.75 3.10
sdi 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sde 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdj 0.00 0.00 6.00 0.00 4326.00 0.00 721.00 0.06 10.50 10.50 0.00 6.83 4.10
sdc 0.00 0.00 2.00 0.00 1472.00 0.00 736.00 0.04 18.50 18.50 0.00 9.50 1.90
sdh 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdg 0.00 0.00 14.00 0.00 10464.00 0.00 747.43 0.04 2.71 2.71 0.00 1.79 2.50
Aktualizacja:
Problem rozwiązany! Główną przyczyną jest okresowy system wywoławczy trafficserver() do pliku kopii zapasowej w starożytnej wtyczce, którą napisaliśmy.
Być może różnica czasu wynika z wielu przełączników kontekstu - lub z dużej przepustowości z blokowaniem odczytów i zapisów. 'copy_to_user()' jest superszybkie, domyślam się, że ukończenie zajmuje mniej niż mikrosekundę. Nie wiem, czy masz do czynienia z błędem. W każdym razie, powinieneś aktualizować swoje jądro Linux. –