<optgroup id="6y7f6"><small id="6y7f6"></small></optgroup>

<code id="6y7f6"></code>

  • <p id="6y7f6"><tbody id="6y7f6"><ins id="6y7f6"></ins></tbody></p>
    <code id="6y7f6"><form id="6y7f6"></form></code>

      Loading

      記一次使用gdb診斷gc問題全過程

      原創:扣釘日記(微信公眾號ID:codelogs),歡迎分享,轉載請保留出處。

      簡介

      上次解決了GC長耗時問題后,系統果然平穩了許多,這是之前的文章《GC耗時高,原因竟是服務流量???》
      然而,過了一段時間,我檢查GC日志時,又發現了一個GC問題,如下:
      image_2023-02-04_20230204143644
      從這個圖中可以發現,我們GC有一些尖峰,有時會突然有大量的內存分配。

      查看GC日志,發現有大對象分配的記錄,如下:

      $ grep 'concurrent humongous allocation' gc.log | awk 'match($0,/allocation request: (\w+) bytes/,a){print a[1]}' |sort -nr
      1941835784
      1889656848
      

      image_2023-02-04_20230204143322
      可以看到,一次大對象分配,分配大小竟然有1.9G,這誰能抗得住??!

      async-profiler定位大對象分配

      上面提到的文章介紹過,使用async-profiler可以很容易的定位大對象分配的調用棧,方法如下:

      ./profiler.sh start --all-user -e G1CollectedHeap::humongous_obj_allocate -f ./humongous.jfr jps
      

      然后使用jmc打開humongous.jfr文件,調用棧如下:
      image_2023-02-04_20230204180005

      這是在做thrift反序列化操作,調用了TCompactProtocol.readDouble方法,方法代碼如下:
      image_2023-02-04_20230204144842
      可是,這里只創建了8字節的數組,怎么也不可能需要分配1.9G內存吧,真是奇了怪了!

      經過一番了解,這是因為async-profiler是通過AsyncGetCallTrace來獲取調用棧的,而AsyncGetCallTrace獲取的棧有時是不準的,Java社區有反饋過這個問題,至今未解決。
      image_2023-02-04_20230204171551
      問題鏈接:https://bugs.openjdk.org/browse/JDK-8178287

      尋找其它tracer

      linux上有很多內核態的tracer,如perf、bcc、systemtap,但它們都需要root權限,而我是不可能申請到這個權限的??

      在用戶態上,基于ptrace系統調用實現的有strace、ltrace,我試了一下它們,并無法直接跟蹤G1中的大對象分配函數G1CollectedHeap::humongous_obj_allocate。

      我也在網上搜索了好幾天,希望找到一個有用的純用戶態tracer,但可惜幾天都沒找到,最后,我只能將目標放在c/c++的調試工具gdb上,我想gdb既然是一個調試工具,那它必然能夠查看指定函數的調用參數與調用棧,只要找到相應用法即可!

      編寫gdb腳本

      經過一番學習與探索(PS:其實花了我快2周??),我終于編寫出了實際可用的gdb腳本,如下:

      handle all nostop noprint pass
      handle SIGINT stop print nopass
      
      break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)
      while 1
          continue
          # 如果是Ctrl+c,則退出
          if $_siginfo
              if $_siginfo.si_signo == 2
                  detach
                  quit
              end
          end
          printf "word_size is %d\n",$rsi
          if $rsi > 100*1024*1024/8
              # 打印當前時間
              shell date +%FT%T   
              # 打印當前線程
              thread              
              # 打印當前調用棧
              bt                  
              python import subprocess
              # 向jvm發送kill -3信號,即SIGQUIT信號
              python proc = subprocess.Popen(['kill','-3',str(gdb.selected_inferior().pid)], stdout=subprocess.PIPE, stderr=subprocess.PIPE, bufsize=1, universal_newlines=True)
              python stdout, stderr = proc.communicate()
              python print(stdout)
              python print(stderr)
              detach
              quit
          end
      end
      

      沒學過gdb的同學可能看不明白,沒關系,我們慢慢來。

      handle all nostop noprint pass
      handle SIGINT stop print nopass
      

      這2句handle是處理Linux信號用的,由于我們并不需要調試信號問題,所以讓gdb都不處理信號,保留SIGINT是為了按Ctrl+c時能退出gdb腳本。

      break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)
      

      這個break是給G1中的大對象分配函數G1CollectedHeap::humongous_obj_allocate設置斷點,方法源碼如下:
      image_2023-02-04_20230204152845
      word_size參數表示分配多少字的內存,而在64位機器上,1字等于8字節,所以如果能追蹤到這個參數值,就能知道每次分配大對象的大小了。

      由于JVM是使用C++寫的,而C++編譯會做函數名改寫(mangle)以兼容C的ABI,所以編譯后的函數名就變成了奇奇怪怪的_ZN15G1CollectedHeap22humongous_obj_allocateEmh,通過nm查詢二進制文件的符號表,可以獲取這個名稱。

      $ which java
      /usr/local/jdk/jdk1.8.0_202/bin/java
      
      # jvm相關實現,都在libjvm.so動態庫中
      $ find /usr/local/jdk/jdk1.8.0_202 | grep libjvm.so
      /usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so
      
      $ nm /usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so |grep humongous_obj_allocate
      000000000058c060 t _ZN15G1CollectedHeap22humongous_obj_allocateEmh
      000000000058b1a0 t _ZN15G1CollectedHeap41humongous_obj_allocate_initialize_regionsEjjmh
      

      再看回之前設置斷點的腳本代碼:

      break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)
      

      + 0x58c06f - 0x58c060這個是在做地址偏移操作,了解過匯編的同學應該清楚,調用函數后,函數開頭的一些匯編指令,一般是參數寄存器的相關操作,x86參數寄存器如下:

      rdi 表示第一個參數
      rsi 表示第二個參數
      rdx 表示第三個參數
      rcx 表示第四個參數
      r8 表示第五個參數
      r9 表示第六個參數
      

      可以使用objdump反匯編libjvm.so,看看匯編代碼,以確定斷點該偏移到哪一行指令上,看官們堅持住,匯編相關內容就下面一點??

      $ objdump -d /usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so |less -S
      

      然后在less里面搜索_ZN15G1CollectedHeap22humongous_obj_allocateEmh函數,如下:
      image_2023-02-04_20230204153959
      之所以要加偏移量,是因為在 + 0x58c06f - 0x58c060這個位置后,rsi寄存器(第二個參數)才會有值,之所以獲取每二個參數的值,是因為C++對象編程中,第一個參數是this。

      然后后面的邏輯就好理解了,如下:
      image_2023-02-04_20230204155401
      首先是循環,然后continue表示讓程序運行起來,當程序命中斷點后,continue才會執行完。
      中間是信號處理,主要是為了能Ctrl+c退出循環。
      最后通過print將rsi的值打印出來,這樣就追蹤到了word_size參數的值。

      再然后是打印線程與調用棧信息,如下:
      image_2023-02-04_20230204155915
      當分配內存大于100M時,打印當前時間、當前線程與當前調用棧。

      但gdb的bt命令打印的調用棧是這樣子的,如下:
      image_2023-02-04_20230204160314
      因為Java是解釋執行的,java部分的調用棧bt是獲取不到的。
      image_2023-02-04_20230204174258

      沒有java調用棧,這個追蹤腳本就瘸了呀,我在這里卡了好久,也嘗試了許多種方法??

      對java比較熟悉的同學應該知道,jvm有一個隱藏的診斷功能,如果給jvm進程發SIGQUIT信號,jvm會在標準輸出中打印線程棧信息,而SIGQUIT信號可以通過kill -3發送,因此就有了下面的代碼:
      image_2023-02-04_20230204161023
      gdb真是強大,內嵌了python擴展,而通過python的subprocess包,就可以執行kill -3命令了。

      后面的detachquit,用于退出gdb的,不用深究。

      運行gdb腳本追蹤大對象

      把上面的gdb腳本命名為trace.gdb,然后就可以使用gdb命令運行它了,如下:

      $ gdb -q --batch -x trace.gdb -p `pgrep java`
      

      其中pgrep java用于獲取java進程的進程號。

      注:gdb本質上是基于ptrace系統調用的調試器,斷點命中時對進程有不小切換開銷,所以這種方式只能追蹤調用頻次不高的函數。

      運行后,追蹤到的參數與線程信息如下:
      image_2023-02-04_20230204162114
      其中LWP后面的166就是線程號,轉成十六進制就是0xa6。
      然后到java進程的標準輸出日志中,去找這個線程的Java調用棧,如下:
      image_2023-02-04_20230204163200

      大對象分配由readBinary函數發起,調試下這個函數,如下:
      image_2023-02-04_20230204163605
      媽呀,它創建了一個超大的byte數組,難怪會出現1.9G的大對象分配呢!

      而readBinary的調用,由這個代碼觸發:

      TProtocolFactory factory = new TCompactProtocol.Factory();
      TDeserializer deserializer = new TDeserializer(factory);
      deserializer.deserialize(deserializeObj, sourceBytes);
      

      這是在做thrift反序列化,將sourceBytes字節數組反序列化到deserializeObj對象中。

      當sourceBytes是由deserializeObj對象序列化出來時,反序列化就沒有任何問題。

      而當sourceBytes不是由deserializeObj對象序列化出來時,反序列化代碼從sourceBytes中解析出字段長度時(length),可能是任意值,進而導致可能創建超大的字節數組。

      但我們寫這個代碼,就是為了檢測sourceBytes是否由deserializeObj序列化而來,所以sourceBytes確實有可能不是由deserializeObj序列化而來!

      簡單查看了一會thrift代碼,發現可以限制字段的最大長度,如下:
      image_2023-02-04_20230204165113
      想一想,反序列的某個字段的長度,肯定不會有整個反序列化的數據長呀,因此使用sourceBytes.length來限制即可。

      TProtocolFactory factory = new TCompactProtocol.Factory(sourceBytes.length, sourceBytes.length);
      TDeserializer deserializer = new TDeserializer(factory);
      deserializer.deserialize(deserializeObj, sourceBytes);
      

      限制了后,若字段超長了會拋異常,所以若反序列化異常了,說明當前sourceBytes不是由deserializeObj序列化出來。

      總結

      編寫這個gdb腳本,確實花費了我相當多的時間,因為事前我也不知道gdb是否能夠做到這個事情,且我不是C/C++程序員,對匯編相關知識并不熟悉,中途有好幾次想放棄??

      好在最后成功了,并讓我又Get到了一種新的問題解決路徑,還是非常值得的??

      posted @ 2023-02-04 18:48  扣釘日記  閱讀(2080)  評論(6編輯  收藏  舉報
      欧洲黄色网页链接入口,免费A级毛片无码无遮挡久久影院,a免费黄色网址,国产一级黄色的网站
      <optgroup id="6y7f6"><small id="6y7f6"></small></optgroup>

      <code id="6y7f6"></code>

    1. <p id="6y7f6"><tbody id="6y7f6"><ins id="6y7f6"></ins></tbody></p>
      <code id="6y7f6"><form id="6y7f6"></form></code>