記一次 .NET 某市附屬醫院 Web程序 偶發性CPU爆高分析

2022-01-12 dotNET跨平臺
一：背景 1. 講故事

這個月初，一位朋友加微信求助他的程序出現了 CPU 偶發性爆高，希望能有償解決一下。

從描述看，這個問題應該困擾了很久，還是醫院的朋友給力，開門就是 100塊 紅包 🤣🤣🤣，那既然是偶發性爆高，人工不行，還得用 procdump 自動抓，用 procdump -ma -s 5 -n 2 -c 70 w3wp 埋伏好，幾天後如願生成了兩個dump，太妙了，接下來就用 windbg 分析吧。

二：Windbg 分析 1. 真的是cpu爆高嗎

一切只相信數據，這裡用 !tp 看一下此時 machine 的cpu值。


0:062:x86> !tp
CPU utilization: 83%
Worker Thread: Total: 37 Running: 6 Idle: 31 MaxLimit: 8191 MinLimit: 4
Work Request in Queue: 0
---
Number of Timers: 2
---
Completion Port Thread:Total: 1 Free: 1 MaxFree: 8 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 4

從數據看，此時 CPU utilization: 83%, 沒毛病。
2. 查看線程耗時
既然是偶發性的bug，而且也說了可能是醫生操作了什麼觸發了什麼條件才導致的，剛好這裡也有 2 個dump，那就比一下各個線程的耗時吧，這裡只提取 top5 。

0:062:x86> .time
Debug session time: Thu Dec 16 14:31:45.000 2021 (UTC + 8:00)
System Uptime: not available
Process Uptime: 0 days 1:20:48.000
  Kernel time: 0 days 0:08:43.000
  User time: 0 days 1:08:19.000

0:062:x86> !runaway
 User Mode Time
  Thread       Time
   62:7188     0 days 0:18:05.343
   44:6c90     0 days 0:16:16.687
   39:86e8     0 days 0:14:57.734
   32:1d8c     0 days 0:01:02.546
   35:23a4     0 days 0:00:58.250

0:062:x86> .time
Debug session time: Thu Dec 16 14:32:00.000 2021 (UTC + 8:00)
System Uptime: not available
Process Uptime: 0 days 1:21:03.000
  Kernel time: 0 days 0:08:45.000
  User time: 0 days 1:08:41.000

0:062:x86> !runaway
 User Mode Time
  Thread       Time
   62:7188     0 days 0:18:11.875
   44:6c90     0 days 0:16:23.156
   39:86e8     0 days 0:15:04.156
   32:1d8c     0 days 0:01:02.546
   35:23a4     0 days 0:00:58.250

從信息看，間隔15s的dump，相對來說 62,44,39 這三個線程耗時最多，所以這三個線程值得繼續挖一挖。
3. 查看線程棧
接下來用 ~62s; !clrstack;~44s; !clrstack;~39s; !clrstack 切到這三個線程看下棧情況，如下圖所示：
從棧中看，並沒有用戶代碼，這就很尷尬了，我一度懷疑是不是 webform 的同步上下文導致的，但好歹我還是有一些經驗，既然 !clrstack 看不到，那就用 !dumpstack 。

0:062:x86> !dumpstack
OS Thread Id: 0x7188 (62)
TEB information is not available so a stack size of 0xFFFF is assumed
Current frame: (MethodDesc 6b0e1b58 +0x1c System.Collections.Generic.ObjectEqualityComparer`1[[System.__Canon, mscorlib]].Equals(System.__Canon, System.__Canon))
ChildEBP RetAddr  Caller, Callee
3867ebfc 6b440484 (MethodDesc 6b0db558 +0x54 System.Collections.Generic.List`1[[System.__Canon, mscorlib]].Contains(System.__Canon))
3867ec18 24bbc3c5 (MethodDesc 25e2ba88 +0x845 xxx.bl_baseInfo.getBljl(System.String, System.String)), calling 2f23072e
3867ec84 6b466d0b (MethodDesc 6b0dcb5c +0x7b System.String.TrimHelper(Int32)), calling (MethodDesc 6b0d1cf4 +0 System.Globalization.CharUnicodeInfo.IsWhiteSpace(Char))
3867ec98 24bbba00 (MethodDesc 2a6eca54 +0x1b8 xxx_blcx.Button1_Click(System.Object, System.EventArgs)), calling (MethodDesc 25e2ba88 +0  xxx.getBljl(System.String, System.String))
3867ecb8 05b5d487 05b5d487
3867ecec 6092da13 (MethodDesc 5fdff5c0 System.Web.UI.WebControls.Button.OnClick(System.EventArgs))
3867ed04 5ffdd1cd (MethodDesc 5fdff5e8 +0xcd System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String))
3867ed1c 5ffdd0fd (MethodDesc 5fdff5e0 +0xd System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String))
...

真是太奇怪了，用戶代碼 xxx.bl_baseInfo.getBljl 怎麼跑到非託管棧 ? 這真是第一次遇到，從棧上看，程序在 xxx.bl_baseInfo.getBljl() 方法中遇到了問題，接下來用 !dso 把堆對象都導出來。

0:062:x86> !dso
Error requesting heap segment b4fe0000
Failed to retrieve segments for gc heap
Unable to determine bounds of gc heap

我去，這個 dump 的棧被破壞了，可能是 cpu 爆高導致的，也有可能是抓的不好，這下太折磨了，得，只能用 kb 到非託管棧上找方法參數。

0:062:x86> kb
 # ChildEBP RetAddr      Args to Child              
00 3867ebfc 6b440484     cd0a25a8 124e2c7c 0efb330c mscorlib_ni!System.Collections.Generic.ObjectEqualityComparer`1[System.__Canon].Equals(System.__Canon, System.__Canon)$##6003913+0x1c
01 3867ec18 24bbc3c5     cd0a25a8 132b35e4 132b35cc mscorlib_ni!System.Collections.Generic.List`1[System.__Canon].Contains(System.__Canon)$##600398F+0x54
WARNING: Frame IP not in any known module. Following frames may be wrong.
02 3867ec98 24bbba00     0e3aead8 8412256c 3867ecc0 0x24bbc3c5
03 3867ecb8 05b5d487     0a3d6f00 3867f170 5381fbca 0x24bbba00
04 3867ecec 6092da13     0a3d6e48 00000000 132a20c0 0x5b5d487
05 3867ed04 5ffdd1cd     124ca1a8 80208dfc 80208dfc System_Web_ni![COLD] System.Web.UI.WebControls.Button.OnClick(System.EventArgs)$##60029E3+0xb
...

接下來我們 !do 一下 132b35cc 地址，看看是什麼 list。

0:062:x86> !do 132b35cc
Name:        System.Collections.Generic.List`1[[xxx.Model.me_zyblbr, xxx]]
MethodTable: 29f36c8c
EEClass:     6b0aedc4
Size:        24(0x18) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
6b4aea10  4001871        4     System.__Canon[]  0 instance 8e8054e0 _items
6b513c04  4001872        c         System.Int32  1 instance   233139 _size
6b513c04  4001873       10         System.Int32  1 instance   233139 _version
6b512104  4001874        8        System.Object  0 instance 00000000 _syncRoot
6b4aea10  4001875        4     System.__Canon[]  0   static  <no information>

用輸出中可以看到，這個 list=23w 條記錄，它正在 list.Contains 處，有了這些信息，接下來就可以把源碼導出來，簡化後的代碼如下：

  public IList<xxx> getBljl(string as_search, string as_ztbz)
  {
   IList<me_zyblbr> list = new List<me_zyblbr>();
   using (CDataBase cDataBase = new CDataBase("xxx"))
   {
                var text = "select xxxx  from xxx";
    OracleDataReader oracleDataReader = cDataBase.SetReader(text);
    while (oracleDataReader.Read())
    {
     if (!list.Contains(me_zyblbr))
     {
      list.Insert(0, me_zyblbr);
     }
    }
    oracleDataReader.Close();
    return list;
   }
   return list;
  }

眼尖的朋友肯定能注意到，在數據量大的情況下，這裡的 list.Insert(0, me_zyblbr); 有大問題，畢竟 list.Insert 的複雜度是 O(N)，針對 23w 來說總的時間複雜度就是：
n(n-1)/2 = 23w(23w-1)/2 = 26,450,000,000 = 264億 。
然後就是 3個這樣的線程就一起把cpu給抬起來了。
4. 到底是什麼sql語句導致
雖然問題根已找到，但朋友最關心的是這位醫生到底輸入了什麼導致 sql 查詢了如此大的數據, 不知道醫生要扣錢還是他們要向上面有個交代😂😂😂， 由於堆，棧都 被損壞了，找起來還是很麻煩的，我用了 sos 中的 !lno, !dumpheap 都是報錯,徹底趴窩了，最後想了下 sosex 中也有一個 !mdso 命令，終於一路坎坷的找到了重要的 OracleParameter 參數。

0:062:x86> !mdso
Thread 62:
Location          Object            Type

EDI:      132b35cc  System.Collections.Generic.List`1[[xxx.me_zyblbr, xxx]]
3867ec08  124e2c7c  System.Collections.Generic.ObjectEqualityComparer`1[[xxx.me_zyblbr, xxx]]
3867ec44  132b3a5c  Oracle.DataAccess.Client.OracleParameter

0:062:x86> !mdt 132b3a5c
132b3a5c (Oracle.DataAccess.Client.OracleParameter)
    __identity:NULL (System.Object)
    m_pOpoPrmValCtx:4e691200 (System.UIntPtr)
    m_paramName:125fe6f0 (System.String) Length=5, String=":xxx"
    m_sourceColumn:NULL (System.String)
    m_sourceVersion:0x200 (System.Data.DataRowVersion)
    m_dbType:0x0 (System.Data.DbType)
    m_oraDbType:0x77 (NVarchar2) (Oracle.DataAccess.Client.OracleDbType)
    m_bOracleDbTypeExSet:false (System.Boolean)
    m_maxSize:0xffffffff (System.Int32)
    m_maxArrayBindSize:NULL (System.Int32[])
    m_nullable:false (System.Boolean)
    m_value:132b3af8 (System.String) Length=6, String="%高血壓病%"

原來是醫生模糊查詢了一個 高血壓病 導致的。。。
不過這裡主要是想告訴大家的是,當由於內存遭到一定程度的破壞導致 sos 徹底趴窩也不要怕，可能還有其他的插件可以救我們於水火之中，多一個插件多一條路哈。
三：總結 
總的來說，這次偶發的CPU爆高事故，犯的相對比較低級，對 List.Insert 的複雜度可能也不是很了解，也有可能是為了趕業務所欠的債吧，改發也相對簡單，先用 add 送到 list，最後再統一按規則做一下重整排序。

相關焦點

  • 記一次 .NET遊戲站程序的 CPU 爆高分析
    一、講故事上個月有個老朋友找到我，說他的站點晚高峰 CPU 會突然爆高，發了兩份 dump 文件過來，如下圖：又是經典的 CPU 爆高問題，到目前為止，對這種我還是有一些經驗可循的。第二個：有時候你抓的dump剛好線程都處理完了，cpu 還未真實回落，所以分析這種dump意義不大，我是吃了不少虧。現在的碼農都精怪精怪的，基本不會傻傻的寫出個死循環，絕大部分都是遇到某種 資源密集型 或 計算密集型 場景下導致非託管的 GC 出了問題。
  • 如何在.NET應用程式中分析CPU使用率過高的問題
    原文來自：https://www.toptal.com/dot-net/hunting-high-cpu-usage-in-dot-net軟體開發可能是一個非常複雜的過程。作為開發人員，我們需要考慮很多不同的變量。有些不在我們的控制之下，有些在實際代碼執行時對我們來說是未知的，有些則由我們直接控制。 .NET開發人員[1]也毫不例外。
  • Go語言 CPU 性能、內存分析調試方法大匯總:你要的都在這
    直觀上來說，這個程序在test()函數執行完後，切片contaner的內存應該被釋放，不應該佔用830M那麼大。下面讓我們使用GODEBUG來分析程序的內存使用情況。執行snippet_mem程序之前添加環境變量GODEBUG='gctrace=1'來跟蹤列印垃圾回收器信息$ GODEBUG='gctrace=1' .
  • 如何使用pprof分析應用
    inuse_objects終端查看web查看3、程序啟動到現在的內存使用 alloc_space終端查看web 查看4、從啟動到現在的總分配對象 alloc_objects1、PProf2、支持什麼使用模式3、可以做什麼4、 測試demo5、 訪問web6、指標解析1、runtime.futex2、 runtime.gopark--協程指標gopark函數做的主要事情分為兩點：調用過程3、runtime.ready
  • 記一次 .NET 程序的性能優化實戰(2)—— 使用 perfview 找出 Regex 慢的根本原因
    前言 我在上一篇文章《記一次 .NET 程序的性能優化實戰（1）—— 使用 process explorer 快速定位問題代碼》中用 process explorer 定位到了導致程序運行緩慢的原因——使用了 .NET 中的正則表達式。.NET 中的正則表達式真這麼慢嗎？帶著疑問，開始了本次的探索之旅。
  • golang 調試分析的高階技巧
    golang 作為一門現代化語音，出生的時候就自帶完整的 debug 手段：golang tools 是直接集成在語言工具裡，支持內存分析，cpu分析，阻塞鎖分析等；delve，gdb 作為最常用的 debug 工具，讓你能夠更深入的進入程序調試；delve 當前是最友好的 golang 調試程序，ide 調試其實也是調用 dlv 而已，比如 goland；單元測試的設計深入到語言設計級別
  • Golang 調試分析的高階技巧
    golang 作為一門現代化語音，出生的時候就自帶完整的 debug 手段：golang tools 是直接集成在語言工具裡，支持內存分析，cpu分析，阻塞鎖分析等；delve，gdb 作為最常用的 debug 工具，讓你能夠更深入的進入程序調試；delve 當前是最友好的 golang 調試程序，ide 調試其實也是調用 dlv 而已，比如 goland；單元測試的設計深入到語言設計級別
  • Go 性能分析工具 pprof 入門
    在實際項目中對高並發場景下的服務上線前必須經過pprof驗證，本文介紹了pprof的用法。一. pprof 數據採樣pprof 採樣數據主要有三種獲取方式:runtime/pprof: 手動調用runtime.StartCPUProfile或者runtime.StopCPUProfile等 API來生成和寫入採樣文件，靈活性高net/http/pprof: 通過 http 服務獲取Profile採樣文件，簡單易用，適用於對應用程式的整體監控
  • Go 調試分析的高階技巧
    golang 作為一門現代化語音，出生的時候就自帶完整的 debug 手段：golang tools 是直接集成在語言工具裡，支持內存分析，cpu分析，阻塞鎖分析等；delve，gdb 作為最常用的 debug 工具，讓你能夠更深入的進入程序調試；delve 當前是最友好的 golang 調試程序，ide 調試其實也是調用 dlv 而已，比如 goland；單元測試的設計深入到語言設計級別，
  • Golang 性能分析工具簡要介紹
    pprof 可以對我們所寫的算法甚至整個應用程式做性能分析，幫助我們快速定位效率低或者資源消耗多的地方。(*FD).Read net.(*netFD).Read net.(*conn).Read net/http.
  • C/C++程序CPU問題分析
    本次我們收集了14個CPU類的問題，和大家一起分析下這些問題的種類和原因。另外，對於C/C++程序而言，目前已經有了很多CPU問題定位的工具，本文也會進行比較分析。程序CPU類問題的主要現象是：程序佔用的CPU過高，比程序升級前有很大的升高。導致程序CPU佔用過高的主要原因是程序設計不合理，絕大部分的CPU問題都是程序設計的問題。因此，提高程序的設計質量是避免CPU問題的主要手段。
  • cpu高不是問題?如果不是,那什麼才是問題?
    因此有時候cpu很高，但是列印線程堆棧出來發現高cpu的線程在查詢資料庫等待中，不要覺得奇怪，因為cpu統計的是採樣時間內的數據。假設top觀察某段時間用戶空間cpu一直很高，那麼意味著這段時間用戶的程序一直在佔據著cpu做事情。
  • Golang程序性能分析(一)pprof和go-torch
    在Go 語言中，主要關注的程序運行情況包括以下幾種：CPU profile：報告程序的 CPU 使用情況，按照一定頻率去採集應用程式在 CPU 和寄存器上面的數據Memory Profile（Heap Profile）：報告程序的內存使用情況Block Profile：報告導致阻塞的同步原語的情況，可以用來分析和查找鎖的性能瓶頸Goroutine
  • Web應用程式開發五步法
    那麼作為一名Web開發人員，怎樣去開發一款優秀的Web應用程式呢？這個問題沒有一個簡單的答案，甚至那些教育機構都未必能清楚的知道。所以，像大多數在這個領域裡的web開發人員一樣，我們只是通過去做，去實驗才學會了這些。沒有人告訴我們如何去做，我們從給自己做點什麼東西開始，學會如何開發web應用程式是在這個過程中的一個副產品。這是學習任何語言的一個非常有效的方法。
  • .Net Web開發技術棧(更全的知識體系)
    ：基於內存的數據存儲系統，高性能分布式內存緩存服務，適用於高並發場合...網站優化默認隱藏段（拒絕客戶端訪問）App_Browsers：包含瀏覽器定義(.browser文件),ASP.NET會使用這些文件來識別個別瀏覽器並判斷它們的功能App_Code：包含用於公用程序和商務對象(Business Object) , (例如, .cs ; .vb和.jsl文件)的程序原始碼,要將它編譯為應用程式的一部分
  • 多些體驗 10個免費web分析工具應用程式
    分析工具和應用程式，他們可以幫助你收集和分析與你網站內容有關的數據。Web analytics 是在web分析行業佔據主導地位的Google Analytics的另一個替代選擇。yahoo網站分析工具全面提供你需要的web分析工具，比如圖表工具，自定義設計（並且可列印）報表、以及實時數據跟蹤。5.
  • 記一次 .NET 某流媒體獨角獸 API 句柄洩漏分析
    講故事上上周有位朋友找到我，說他的程序CPU和句柄都在不斷的增長，無回頭趨勢，查了好些天也沒什麼進展，特加wx尋求幫助，截圖如下：看的出來這位朋友也是非常鬱悶，出問題還出兩個，氣人哈，關於 cpu 爆高的問題我準備單獨用一篇文章去偵讀，這篇就先聊聊 句柄洩漏 的問題，畢竟寫了20多篇，也是第一次聊到 handle
  • node故障排查從原理到實操-分析cpu耗時瓶頸
    內存洩露講了通過heapsnapshot文件分析內存佔用過高的某一時刻，進程中哪個對象佔用內存較大來找出內存洩露的原因。那麼本次來講如何分析cpu耗時較長的函數來找出性能瓶頸。        其實除了本次講解的cpu佔用時間過長的瓶頸以外，我們還需要關注的是進程是否進入了無限循環的同步函數中導致cpu長時間飆到100%，進而變成無法執行事件循環和接收請求的假死狀態。
  • 記一次jmeter壓測實戰總結
    三．測試結果分析1、有錯誤率同開發確認，確定是否允許錯誤的發生或者錯誤率允許在多大的範圍內；2、Throughput吞吐量每秒請求的數大於並發數，則可以慢慢的往上面增加；若在壓測的機器性能很好的情況下，出現吞吐量小於並發數，說明並發數不能再增加了，可以慢慢的往下減，找到最佳的並發數；3、壓測結束，登陸相應的web伺服器查看CPU等性能指標，進行數據的分析；4、最大的
  • 記一次.Net代碼審計-通過machineKey偽造任意用戶身份
    0x01 起因某次機緣巧合，領導給了一套國內某主流.net BPM系統源碼，要求審計，於是便開始了這次審計之旅。。。BPM（業務流程管理系統），這套系統採用前後端分離架構，前端ExtJS，後端.net的一般處理程序+windows服務開放socket埠1580，一般處理程序與伺服器本地1580埠通信。資料庫Oracle/SQLServer等。環境搭建好後，使用VS打開站點，使用附加到進程，選擇IIS進程，開啟調試，配合Reflector查看DLL封裝。