なぜcopy_to_userは数百ミリ秒かかるのですか？

Question

私はいくつかのLinuxサーバーにApacheのトラフィックサーバーを実行しており、約1/20の要求が数ミリ秒かかることがわかりました。

systemtapでトレースした後、Linuxカーネルのcopy_to_user（）コールで時間が費やされています。 （なAccept-> inet_csk_accept-> move_addr_to_user-> copy_to_user）

サーバーの負荷が低い終了している（< 100qps）とcopy_to_userは（）だけで16バイトのデータ（sockaddr構造体）をコピーしますが、ミリ秒の数百を過ごします。

私はsystemtapとカーネルトレースのテクニックを初めて使いこなしているので、それ以上の理由は調べることができません。私はCPU使用量をチェックして、使用量を交換します

ありがとうございます。

ハードウェア：

• CPU：インテル（R）Xeonプロセッサ（R）CPU E5-2640 V3
2.60GHz @メモリ：64G
• ディスク：* 6TのHDD 11

ソフトウェア：

• 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/Linuxの
• Apacheのtrafficserver 5.3.2のconfigure 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あなたのアドバイスに感謝します。 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 

---

更新：解決

問題！ 私たちが書いた古代のプラグインのファイルをバックアップするためにtrafficserverが定期的にsystem（）を呼び出しています。

Answer 1

まあ、合理的な説明は、あなたがページフォールトを取っているということです。考えられる理由の1つは、負荷がどのように変化し、新しい子がページにフォールトを発生させるかによってサーバーがフォーク/終了することですが、マイナーフォールトではメモリ不足がなければ長時間かかるべきではありません。

もう1つはメモリ不足で、実際には交換しています。

これまでのところ、あなたがこれまで来てくれたとしても、私は問題がさらに進んでいくのを見ません。プローブを__do_page_faultに置き、そこから続行する必要があります。