почему copy_to_user тратит несколько сотен миллисекунд?

У меня есть несколько серверов Linux, на которых работает apache trafficserver, и я обнаружил, что около 1/20 запросов занимают несколько миллисекунд, что намного дольше, чем ожидалось (должно быть 1-2 мс).

После отслеживания с помощью systemtap я обнаружил, что время тратится на вызов copy_to_user() ядра Linux. (accept->inet_csk_accept->move_addr_to_user->copy_to_user)

Нагрузка на сервер довольно низкая (‹100 запросов в секунду), а функция copy_to_user() просто копирует 16 байт данных (структура sockaddr), но тратит сотни миллисекунд.

Поскольку я новичок в технике systemtap и трассировки ядра, я не могу исследовать дальнейшие причины. Я проверил использование процессора, использование подкачки

Спасибо за любой совет.

Аппаратное обеспечение:

• ЦП: ЦП Intel(R) Xeon(R) E5-2640 v3 @ 2,60 ГГц
• память: 64G
• диск: жесткий диск 11 * 6T

Программное обеспечение:

• centos6 2.6.32-696.el6.x86_64 #1 SMP Вт 21 марта 19:29:05 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
• Apache 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 я обнаружил, что время было потрачено на __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, спасибо за совет. Apache trafficserver читает/записывает на жесткий диск в отдельных потоках. trafficserver имеет 1 поток для приема соединений, 88 (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

Обновлять:

Проблема решена! Основная причина заключается в том, что трафик-сервер периодически вызывает system() для резервного копирования файла в древнем плагине, который мы написали.