AutoMapper.Mapper.CreateMap報「System.NullReferenceException: 未將對象引用設置到對象的實例。」異常復現

>>Agenda：

>>Ⅰ.國慶假期問題出現

>>Ⅱ.雙休日異常再次出現

>>Ⅲ.排障

>>Ⅳ.異常覆盤

>>Ⅴ.修復後監測

>>Ⅵ.結束

Ⅰ.國慶假期問題出現TOP

國慶假期期間——10月5號——發現支付中心頻繁報異常「System.NullReferenceException: 未將對象引用設置到對象的實例。」，經過分析異常堆棧信息，代碼出如今QRCodeService的GetQRCode方法裏以下第8行代碼：

 1 /// <summary>
 2 /// 掃碼支付 獲取支付碼
 3 /// </summary>
 4 /// <param name="reqModel"></param>
 5 /// <returns></returns>
 6 public ResponseModelBase GetQRCode(QRCodeRequestModel reqModel)
 7 {
 8     AutoMapper.Mapper.CreateMap<QRCodeRequestModel, QRCodeRequestDTO>();
 9     var reqDto = AutoMapper.Mapper.Map<QRCodeRequestDTO>(reqModel);
10     if (reqDto.valid_minutes == 0)
11     {
12         reqDto.valid_minutes = 20;//默認設置爲20分鐘
13     }
14 
15     if (string.IsNullOrEmpty(reqModel.order_no))
16     {
17         throw new ResponseErrorException("未獲取訂單ID，請從新檢查訂單信息");
18     }
19     if (reqModel.pay_money <= 0)
20     {
21         throw new ResponseErrorException("訂單價格有誤,請從新驗證該訂單");
22     }
23     if (string.IsNullOrEmpty(reqModel.goods_name))
24     ......
25     ......
26 }

 

異常日誌：

 1 2017/10/5 14:03:40    [GetQRCode_140340241_DCB85]請求支付中心參數：{"biz_system":"5","goods_name":"W17720171005140403733142/qdrpayment3577421317952512T/","merchant_id":"102573307097-102125439412","notify_url":"http://papi1.shenbianhui.cn//OrderPayBack/BackResult","order_no":"DD2017100500470030","order_time":"20171005140340","pay_channel":"12","pay_money":"30000","remark":"","return_url":"http://120.55.16.195/pay/returnYimeiCallBack.do","sign":"de101b203758cbbe7f83ce04f20d6fb1","third_pay_platform":"61","valid_minutes":"10"}
 2 2017/10/5 14:03:40    [GetQRCode_140340241_DCB85]支付中心驗籤經過。
 3 2017/10/5 14:03:40    [GetQRCode_140340241_DCB85]獲取二維碼進入
 4 2017/10/5 14:03:40    [GetQRCode_140340241_DCB85]系統異常:System.NullReferenceException: 未將對象引用設置到對象的實例。
 5    在 AutoMapper.TypeMapFactory.<>c__DisplayClass3_0.<MapDestinationPropertyToSource>b__0(IMemberConfiguration _)
 6    在 System.Linq.Enumerable.Any[TSource](IEnumerable`1 source, Func`2 predicate)
 7    在 AutoMapper.TypeMapFactory.CreateTypeMap(Type sourceType, Type destinationType, IProfileConfiguration options, MemberList memberList)
 8    在 AutoMapper.ConfigurationStore.<>c__DisplayClass80_0.<CreateTypeMap>b__0(TypePair tp)
 9    在 System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
10    在 AutoMapper.ConfigurationStore.CreateMap[TSource,TDestination](String profileName, MemberList memberList)
11    在 PaymentService.QRCodeService.GetQRCode(QRCodeRequestModel reqModel)
12    在 PaymentPlatform.QRCode.GetQRCode.MyBiz(String requestJson)
13    在 PaymentPlatform.QRCode.HandlerBase.ProcessRequest(HttpContext context)

從第9行有ConcurrentDictionary，難不成是併發致使的？當時系統TPS併發在50以上。

系統運行數月來，之前從未遇到這樣的問題呢。

 

進一步排查，這個異常出現以後，後面全部對這個接口的請求處理都報這個異常。另外，三個負載節點中，只有其中的9177節點接連報這個異常。

直覺懷疑，隨着線上每週一兩次的發版，會不會是3個節點AutoMapper.DLL版本不一致呢。爲了將影響減到最低，緊急聯繫運維，將9177節點的站點文件刪掉，從其餘節點copy過來一份。 運維告知處理完畢後，問題未再復現。

此後的幾天，線上也沒有再發生相似事故。我也所以認爲是文件版本問題所致，就再也不關注。

Ⅱ.雙休日異常再次出現TOP

誰知，就在上週末的兩天，這個異常又出現了，仍是出如今9177節點。

那這回，就不能理解了。文件版本應該是一致了呀。

迅速聯繫運維，幫忙回收一下站點的應用程序池。

誰知回收完後，問題依舊。

諮詢運維，爲何只有這個節點報這個異常，運維披露10月5號也並未copy文件，只是重啓了一下iis。

那隻好應急讓運維再重啓一下iis了。 此事暫時平息。

 

Ⅲ.排障TOP

爲了能夠消停地過下個週末，決定今天把這個問題根治一下。

你們初步的分析是，AutoMapper.Mapper.CreateMap是靜態方法，多線程時可能會出現問題。

其實我也一直知道，AutoMapper建議把映射關係在程序啓動時作一次性初始化，而非在每次轉換對象時都作初始化。

只不過我當時在用AutoMapper時，並未重視這一點。就寫成了每次都是先建立映射接着轉換對象。

 

欠下的帳老是要還的。 系統此前沒出現這樣的異常，只能說時間不到。

就像墨菲定理說的，該發生的事情總會發生。 這不，不早不晚，就在國慶節和上週末兩個節假日出現了。

 

Ⅳ.異常覆盤TOP

有必要復現一下那個異常。固然，小几率問題，並不容易測出來。

好在，我有JMeter。

在項目裏新建了AutoMapperTest.ashx文件，ProcessRequest方法體以下：

public void ProcessRequest(HttpContext context)
{
    context.Response.ContentType = "text/plain";
    
    LogHelperUtil logHelper = new LogHelperUtil("", LogType.HFAgentPayService);
    LogHelper.Write("[AutoMapperTest]");
    
    Thread.Sleep(new Random().Next(1, 100));
    
    try
    {
        QRCodeRequestModel reqModel = new QRCodeRequestModel();

        AutoMapper.Mapper.CreateMap<QRCodeRequestModel, QRCodeRequestDTO>();
        var reqDto = AutoMapper.Mapper.Map<QRCodeRequestDTO>(reqModel);

        Thread.Sleep(new Random().Next(100, 1000));
        context.Response.Write(JsonConvert.SerializeObject(reqDto));
    }
    catch (Exception ex)
    {
        logHelper.Write("[AutoMapperTestException]" + ex.ToString());
        context.Response.Write(ex.ToString());
    }
}

 

發佈到測試環境。

接下來，建立JMeter的測試計劃，模擬1000個線程數來壓測這個ashx。

持續執行了20分鐘。

過程當中，以下兩件事，使得那個詭異的bug終於從洞裏鑽出來了：

• 從新覆蓋了一下站點的文件，AutoMapper.Mapper.CreateMap語句出現以下異常，在11:08:08這一秒出現了160次。

2017/10/17 11:08:08	[AutoMapperTestException]System.InvalidOperationException: 集合已修改；可能沒法執行枚舉操做。
   在 System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   在 System.Linq.Enumerable.Any[TSource](IEnumerable`1 source, Func`2 predicate)
   在 AutoMapper.TypeMapFactory.CreateTypeMap(Type sourceType, Type destinationType, IProfileConfiguration options, MemberList memberList)
   在 AutoMapper.ConfigurationStore.<>c__DisplayClass80_0.<CreateTypeMap>b__0(TypePair tp)
   在 System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   在 AutoMapper.ConfigurationStore.CreateMap[TSource,TDestination](String profileName, MemberList memberList)
   在 PaymentPlatform.Test.AutoMapperTest.ProcessRequest(HttpContext context)

 

• 中午找運維手動回收了一下應用程序池，AutoMapper.Mapper.CreateMap語句出現以下異常，和節假日出現的異常同樣！這個異常在12:02:04~12:03:17之間出現了43351次。   默認狀況下，iis會在每間隔固定時間29小時回收appPool，若是此時正好有許多請求在訪問此接口，那麼必然也會引起AutoMapper的這個異常。這大概就能解釋爲何線上出現這個bug了。

2017/10/17 12:02:04	[AutoMapperTestException]System.NullReferenceException: 未將對象引用設置到對象的實例。
   在 AutoMapper.TypeMapFactory.<>c__DisplayClass3_0.<MapDestinationPropertyToSource>b__0(IMemberConfiguration _)
   在 System.Linq.Enumerable.Any[TSource](IEnumerable`1 source, Func`2 predicate)
   在 AutoMapper.TypeMapFactory.CreateTypeMap(Type sourceType, Type destinationType, IProfileConfiguration options, MemberList memberList)
   在 AutoMapper.ConfigurationStore.<>c__DisplayClass80_0.<CreateTypeMap>b__0(TypePair tp)
   在 System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   在 AutoMapper.ConfigurationStore.CreateMap[TSource,TDestination](String profileName, MemberList memberList)
   在 PaymentPlatform.Test.AutoMapperTest.ProcessRequest(HttpContext context)

 

貼上JMeter壓測截圖：

 貼上IIS應用程序池的回收配置：

Ⅴ.修復後監測TOP

正如第《Ⅲ.排障》節所說，解決方案就是在全局的Application_Start時，定義全部的AutoMapper類型映射。這樣，就保證了映射關係的一次性初始化。後續代碼不需再定義，只關注對象轉換就能夠了。

發佈到測試環境。

再次啓動JMeter測試計劃，14分鐘內，不管在壓測過程當中更新文件，仍是回收站點應用程序池，都未出現那些併發請求所帶來的AutoMapper建立類型映射的異常。

Ⅵ.結束 TOP

再次強調，你應該儘可能統一管理AutoMapper的映射定義而且只作一次性初始化。

在博客園的一篇AutoMapper的《AutoMapper 最佳實踐》文章中介紹：

雖然AutoMapper並不強制要求在程序啓動時一次性提供全部配置，可是這樣作有以下好處：a) 能夠在程序啓動時對全部的配置進行嚴格的驗證（後文詳述）。b) 能夠統一指定DTO向Entity映射時的通用行爲（後文詳述）。c) 邏輯內聚：新增配置時方便模仿之前寫過的配置；對項目中一共有多少DTO以及它們與實體的映射關係也容易有直觀的把握。