关于.net:记一次-NET-某资讯论坛-CPU爆高分析

47次阅读

共计 4856 个字符，预计需要花费 13 分钟才能阅读完成。

大略有 11 天没发文了，真的不是因为懒，本想前几天抽空写，不晓得为啥最近求助的敌人比拟多，一天都能拿到 2 - 3 个求助 dump，早晨回来就是一顿剖析，有点意思的是大多敌人本人都剖析了几遍或者公司多年的牛皮藓问题，真的是心太累，不过也好，累那是走上坡路😂😂😂。

再回到正题，在一个月前，有位敌人 wx 找到我，他最近也在学习如何剖析 dump，可能教训不是很丰盛，剖析不上来了，截图如下：

尽管 dump 中的问题千奇百怪，但如果要汇成大类，还是有一些法则可循的，比方：gc 频繁触发，大量锁 等等，具体汇总能够观摩我的星球，好了，既然剖析不上来，那就来 windbg。

二：Windbg 剖析

1. 查看 CPU 利用率

既然报过去说 cpu 过高，我得用数据验证下不是，老命令 !tp。


0:057> !tp
CPU utilization: 100%
Worker Thread: Total: 51 Running: 30 Idle: 0 MaxLimit: 400 MinLimit: 4
Work Request in Queue: 11
    Unknown Function: 6a0bbb30  Context: 1b4ca258
    Unknown Function: 6a0bbb30  Context: 1b4ca618
    Unknown Function: 6a0bbb30  Context: 1b4ca758
    Unknown Function: 6a0bbb30  Context: 1cb88d60
    Unknown Function: 6a0bbb30  Context: 1b4ca798
    Unknown Function: 6a0bbb30  Context: 1b5a54d0
    AsyncTimerCallbackCompletion TimerInfo@01f6e530
    Unknown Function: 6a0bbb30  Context: 1b5a5a50
    Unknown Function: 6a0bbb30  Context: 1cb892a0
    Unknown Function: 6a0bbb30  Context: 1b4ca8d8
    Unknown Function: 6a0bbb30  Context: 1cb88da0
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 8 CurrentLimit: 1 MaxLimit: 400 MinLimit: 4

我去，cpu 打满了，对了，这里略微揭示下，CPU utilization: 100% 指的是以后机器而不是程序，话中有话就是当机器的 CPU 100% 时，并不一定是你所 dump 的程序造成的。

2. 是否为 GC 触发

面对这生疏的 dump，先进行一些经验性排查，比如说是否为 GC 触发导致? 那怎么去验证这个假如呢？为了让后果更精确一点，用 !t -special 导出线程列表，看看是否有 GC SuspendEE 字样。


0:057> !t -special
ThreadCount:      109
UnstartedThread:  0
BackgroundThread: 74
PendingThread:    0
DeadThread:       35
Hosted Runtime:   no

          OSID Special thread type
       14 2594 DbgHelper 
       15 2be4 GC SuspendEE 
       16  dc4 GC 
       17 2404 GC 
       18  bb4 GC 
       19 2498 Finalizer 
       20 312c ProfilingAPIAttach 
       21  858 Timer 
       22 3a78 ADUnloadHelper 
       27 290c GC 
       28 2e24 GC 
       29 28b0 GC 
       30 1e64 GC 
       38 3b24 ThreadpoolWorker 
       ...
       90 2948 Gate

从输入看，尼玛果然有，那就表明的确是 GC 触发所致，如果你还不置信的话，能够参考下 coreclr 源码。


size_t
GCHeap::GarbageCollectGeneration(unsigned int gen, gc_reason reason)
{dprintf (2, ("triggered a GC!"));

    gc_heap::gc_started = TRUE;

    {init_sync_log_stats();

#ifndef MULTIPLE_HEAPS
        cooperative_mode = gc_heap::enable_preemptive ();

        dprintf (2, ("Suspending EE"));
        BEGIN_TIMING(suspend_ee_during_log);
        GCToEEInterface::SuspendEE(SUSPEND_FOR_GC);
        END_TIMING(suspend_ee_during_log);
        gc_heap::proceed_with_gc_p = gc_heap::should_proceed_with_gc();
        gc_heap::disable_preemptive (cooperative_mode);
        if (gc_heap::proceed_with_gc_p)
            pGenGCHeap->settings.init_mechanisms();
        else
            gc_heap::update_collection_counts_for_no_gc();

#endif //!MULTIPLE_HEAPS
    }
}

看到下面的 SuspendEE 的吗，它的全称就是 Suspend CLR Execute Engine，接下来咱们用 ~*e !dumpstack 看看哪一个线程触发了 CLR 中的 GarbageCollectGeneration 办法。

从图中能够看到是 53 号线程触发了，切到 53 号线程后换用 !clrstack。

从线程栈看，程序做了一个 XXX.GetAll() 操作，一看这名字就蛮恐怖的，接下来咱们再看看这块源码，到底做了什么操作，简化后的源码如下：


        public static List<xxxx> GetAll()
        {
            string text = "xxxProperty_GetAll";
            SqlDatabase val = new SqlDatabase(m_strConnectionString);
            xxxPropertyTreeInfo xxxPropertyTreeInfo = null;
            List<xxxPropertieInfo> list = new List<xxxPropertieInfo>();
            DbCommand storedProcCommand = ((Database)val).GetStoredProcCommand(text);
            using (IDataReader reader = ((Database)val).ExecuteReader(storedProcCommand))
            {while (DataBase.DataReaderMoveNext(reader))
                {xxxPropertyTreeInfo = new xxxPropertyTreeInfo();
                    xxxPropertyTreeInfo.LoadDataReader(reader);
                    list.Add(xxxPropertyTreeInfo);
                }
            }
            return list;
        }

        public virtual void LoadDataReader(MethodBase method, object obj, IDataReader reader)
        {Hashtable hashtable = new Hashtable();
            for (int i = 0; i < reader.FieldCount; i++)
            {hashtable.Add(reader.GetName(i).ToLower(), reader.GetValue(i));
            }
            Hashtable fieldProperties = GetFieldProperties(method, FieldType.DBField);
            foreach (object key in fieldProperties.Keys)
            {PropertyInfo p = (PropertyInfo)fieldProperties[key];
                object v = null;
                if (hashtable.Contains(key))
                {v = hashtable[key];
                }
                if (v != null)
                {SetPropertieValue(ref obj, ref p, ref v);
                }
            }
        }

从源码逻辑看：它执行了一个存储过程 xxxProperty_GetAll , 而后把获取到数据的 reader 和 xxxPropertyTreeInfo 做了一个 mapping 映射，在映射的过程中触发了 GC。

3. 是否为数据过大导致？

依照以往教训，应该是从数据库中获取了过多数据导致，那本次 dump 是不是呢？要想寻找答案，先用 !dso 命令导出线程栈所有变量，而后用 !do xxx 查看 List<xxxPropertieInfo> list 的 size，如下图所示：

从图中看，这个 size 并不大，那为什么会导致 gc 频繁触发呢？就算做了 反射 产生了很多的小对象，应该也没多大影响哈。。。这又让我陷入了深思。。。

4. 寻找问题本源

通过一顿查找，我发现了几个疑点。

  1. 有 24 个线程正在执行 XXX.GetALL() 办法。

  1. 托管堆中发现了 123 个 list，大的 size 也有 1298，所以共计起来也不小哈。。。

0:053> !dumpheap -mt 1b9eadd0
 Address       MT     Size
02572a9c 1b9eadd0       24     
026eca58 1b9eadd0       24     
0273d2a0 1b9eadd0       24 
...

Statistics:
      MT    Count    TotalSize Class Name
1b9eadd0      123         2952 System.Collections.Generic.List`1[[xxxPropertieInfo, xxx.Model]]

0:053> !DumpObj /d 28261894
Name:        System.Collections.Generic.List`1[[xxxPropertieInfo, xxx.Model]]
MethodTable: 1b9eadd0
EEClass:     6e2c6f8c
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
6e6ff32c  4001891        4     System.__Canon[]  0 instance 23710638 _items
6e6f1bc0  4001892        c         System.Int32  1 instance     1298 _size
6e6f1bc0  4001893       10         System.Int32  1 instance     1298 _version
6e6f0100  4001894        8        System.Object  0 instance 00000000 _syncRoot
6e6ff32c  4001895        4     System.__Canon[]  0   static  <no information>
  1. 程序是 32bit

从内存地址就能判断以后程序是 32bit，这就意味着它的 segment 段会很小，也就意味着更多的 GC 回收。

三：总结

本次事变是因为：

  1. 多个线程频繁反复的调用 size=1298 的 GetALL() 办法。
  2. 应用低效的 反射形式 进行 model 映射，映射过程中产生了不少的小对象。
  3. 过小的 segment（32M）

三者联合造成 GC 频繁的触发。

改良办法也很简略。

  • 最简略粗犷的办法：将数据库的查问后果缓存一份。
  • 略微正规一点办法：用 Dapper 替换低效的 手工反射 ，将程序改成 64bit。

和敌人沟通了解，采纳了第一种办法，终于把 CPU 摁上来了，所有都复原了平静！

正文完
.net
发表至： .net
2021-10-27
 0
关于net:Microsoft-Azure-动手实验营实现-NET-应用现代化火热报名中
关于.net:NET程序崩溃了怎么抓-Dump-我总结了三种方案
关于.net:如何使用-C-中的-Lambda-表达式
关于.net:请查收NET-MAUI-的最新学习资源