为什么copy_to_user花费几百毫秒?

我有一些运行 apache 流量服务器的 linux 服务器，发现大约 1/20 的请求需要几毫秒，这比预期的要长得多(应该是 1-2 毫秒)。

通过 systemtap 跟踪后，我发现时间花在 linux 内核 copy_to_user() 调用上。(接受->inet_csk_accept->move_addr_to_user->copy_to_user)

服务器负载很低(<100qps)，copy_to_user()只复制16字节的数据(struct sockaddr)，但花费数百毫秒。

由于我不熟悉 systemtap 和内核跟踪技术，因此无法调查进一步的原因。我已经检查了 cpu 使用情况，交换使用情况

感谢您的任何建议。

硬件：

• 中央处理器： 英特尔® 至强® CPU E5-2640 v3 @ 2.60GHz
• 内存：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
• 阿帕奇流量服务器 5.3.2 配置 10G 内存

• nginx 1.10.2，代理用户对流量服务器的请求

  // 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 %dn", 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 %dn", 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
  

更新：

本月@employee感谢您的建议，在__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 流量服务器在单独的线程中读/写到 HDD。流量服务器有 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

更新：

问题解决了！ 根本原因是流量服务器定期调用system()来备份我们编写的古老插件中的文件。