왜 copy_to_user는 수백 밀리 초를 소비합니까?

Question

아파치 트래 픽 서버를 실행하는 리눅스 서버가 있는데 약 1/20의 요청이 예상보다 오래 걸리는 몇 밀리 초가 걸린다는 사실을 발견했습니다 (1-2ms가되어야 함).

systemtap으로 추적 한 후 linux kernel copy_to_user() 호출에 시간이 소비되었음을 알았습니다. (가 용납> inet_csk_accept-> move_addr_to_user-> copy_to_user라는)

서버 부하가 낮은 종료됩니다 (< 100qps)와 copy_to_user라는()는 단지 16 바이트의 데이터 (구조체 SOCKADDR)를 복사 할 수 있지만 밀리 초 수백을 보낸다.

systemtap 및 커널 추적 기술에 익숙하지 않으므로 추가 이유를 조사 할 수 없습니다. 나는 CPU 사용량을 확인하고, 스왑 사용을

어떤 조언 주셔서 감사합니다.

하드웨어 :

• CPU : 인텔 (R) 제온 (R) CPU의 E5-2640 v3의의 @의 2.60GHz
• 메모리 : 64G
• 디스크 : 11 * 6T 하드 디스크

소프트웨어 :

• centos6 2.6.32-696.el6.x86_64 # 1 SMP Tue Mar 21 19:29:05 UTC 2017 x86_64에의 x86_64에의 x86_64의 GNU/리눅스
• 아파치 trafficserver 5.3.2 구성 10G 램

• 의 nginx 1.10.2, 프록시 사용자 요청은 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 
  

---

업데이트 :

당신이 __do_page_fault에 대한 몇 가지 조사를 추가 한 후 조언을 주셔서 감사합니다 @employee, 시간이 __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가 조언 해 주신 데 대해 감사드립니다. 아파치 트래픽 관리 서버는 별도의 스레드에서 hdd를 읽고 쓰고 trafficserver는 읽기/쓰기 (캐시 내용) 차단을 위해 연결을 허용하는 1 개의 스레드, 88 (hdd 당 8 개의 스레드) 스레드를 보유하고 있지만 다른 스레드에서 읽기/쓰기 차단이 왜 __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 

---

는 업데이트 :

문제 해결! 근원은 trafficserver가 주기적으로 우리가 작성한 고대 플러그인의 파일을 백업하는 system()입니다.

Answer 1

글쎄, 적절한 설명은 페이지 폴트를 취하는 것입니다. 한 가지 가능한 이유는로드가 어떻게 변경되고 새 하위가 페이지를 폴트해야하는지에 따라 서버가 포크/종료한다는 것입니다. 그러나 사소한 오류로 인해 메모리 부족이 발생하지 않는 한 오래 걸리지 않아야합니다.

또 다른 한 가지는 메모리 부족이며 실제로 교환하는 것입니다.

어느 쪽이든 지금까지이 문제가 발생했다면 문제가 더 진행되는 것을 볼 수 없습니다. 프로브를 __do_page_fault에 놓고 계속 진행하고 싶습니다.