Go gctrace 引起 runtime 調度阻塞

這是一個奇葩的問題!當你開啓 GODEBUG=gctrace=1,並且日誌是重定向到文件,那麼有概率會造成 runtime 調度阻塞。😅

查找問題

開始業務方說我們的 grpc sidecar 時不時發生高時延抖動,我對比了監控上的性能數據,貌似是磁盤 io 引起的,我迅速調高了日誌級別及修改日誌庫爲異步寫入模式。接口的時延抖動問題確實減少了,但依舊還是出現。

通過項目代碼變更得知,一同事在部署腳本里加入了 gctrace 監控。開始不覺得是這個問題引起的,但近一段時間也就這一個 commit 提交,我就嘗試回滾代碼,問題居然就這麼解決了。

分析 GC gctrace 源碼

我們先來分析下 golang GC gctrace 相關的代碼,我們知道 go 的 stop the world 會發生 mark 的兩個階段,一個是 mark setup 開始階段,另一個就是 mark termination 收尾階段。GC 在進行到 gcMarkTermination 時,會 stop the world,然後判斷是否需要輸出 gctrace 的調試日誌。

簡單說,這個打印輸出的過程是在 stop the world 裏。默認是打印到 pts 僞終端上,這個過程是純內存操作,理論是很快的。

但如果在開啓 gctrace 時進行文件重定向,那麼他的操作就是文件 io 操作了。如果這時候你的服務裏有大量的磁盤 io 的操作,本來寫 page buffer 的操作,會觸發阻塞 flush 磁盤。那麼這時候 go gctrace 打印日誌是在開啓 stop the world 之後操作的,因爲磁盤繁忙,只能是等待磁盤 io 操作完,這裏的 stw 會影響 runtime 對其他協程的調度。

// xiaorui.cc

func gcMarkTermination(nextTriggerRatio float64) {
    // World is stopped  已經開啓了stop the world
    ...
    // Print gctrace before dropping worldsema.

    if debug.gctrace > 0 {
  util := int(memstats.gc_cpu_fraction * 100)

  var sbuf [24]byte
  printlock()
  print("gc ", memstats.numgc,
   " @", string(itoaDiv(sbuf[:], uint64(work.tSweepTerm-runtimeInitTime)/1e6, 3))"s ",
   util, "%: ")
  prev := work.tSweepTerm
  for i, ns := range []int64{work.tMark, work.tMarkTerm, work.tEnd} {
   if i != 0 {
    print("+")
   }
   print(string(fmtNSAsMS(sbuf[:], uint64(ns-prev))))
   prev = ns
  }
  print(" ms clock, ")
  for i, ns := range []int64{sweepTermCpu, gcController.assistTime, gcController.dedicatedMarkTime + gcController.fractionalMarkTime, gcController.idleMarkTime, markTermCpu} {
   if i == 2 || i == 3 {
    // Separate mark time components with /.
    print("/")
   } else if i != 0 {
    print("+")
   }
   print(string(fmtNSAsMS(sbuf[:], uint64(ns))))
  }
  print(" ms cpu, ",
   work.heap0>>20, "->", work.heap1>>20, "->", work.heap2>>20, " MB, ",
   work.heapGoal>>20, " MB goal, ",
   work.maxprocs, " P")
  if work.userForced {
   print(" (forced)")
  }
  print("\n")
  printunlock()
 }

 semrelease(&worldsema)  // 關閉stop the world

    ...
}

解決方法

線上就不應該長期的去監控 gctrace 的日誌。另外需要把較爲頻繁的業務日誌進行採樣輸出。前面有說,我們第一個解決方法就修改日誌的寫入模式,當幾千個協程寫日誌時,不利於磁盤的高效使用和性能,可以藉助 disruptor 做日誌緩存,然後由獨立的協程來寫入日誌。

除此之外,還發現一個問題,開始時整個 golang 進程開了幾百個線程,這是由於過多的寫操作超過磁盤瓶頸,繼而觸發了 disk io 阻塞。這時候 golang runtime sysmon 檢測到 syscall 超時,繼而解綁 mp,接着實例化新的 m 線程綁定 p。記得以前專門寫過文章介紹過 golang 線程爆滿的問題。

後話

我們可以想到如果函數 gcMarkTermination 輸出日誌放在關閉 stop the world 後面,這樣就不會影響 runtime 調度。當然,這個在線上重定向 go gctrace 的問題本來就很奇葩。😅

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/eHEvVzmpPYXAQgcdd_B55w