dlaczego copy_to_user spędza kilkaset milisekund?

Question

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).

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.

Answer 1

Cóż, rozsądnym wyjaśnieniem jest to, że popełniasz błąd strony. Jednym z możliwych powodów może być to, że serwer rozwidla się/zanika, w zależności od tego, jak zmienia się obciążenie i nowe dziecko musi oszukiwać stronę, ale jako drobna usterka nie powinna zająć dużo czasu, chyba że wystąpi brak pamięci.

Innym jest brak pamięci i faktycznie się wymieniasz.

W każdym razie, ponieważ dotarłeś tak daleko, nie widzę problemu, który idzie dalej. Chcesz umieścić sondę na __do_page_fault i dalej stamtąd.