一次依賴注入不慎引起的一連串事故

一次依賴注入不慎引起的一連串事故

原由和現象

偶爾會看到線上服務啓動的時候第一波流量進來以後，

遲遲沒有任何的響應，同時服務的監控檢查接口正常，

因此 K8S 集羣認爲服務正常，繼續放入流量。

查看日誌基本以下：

[2020-06-05T13:00:30.7080743+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test
[2020-06-05T13:00:30.7081525+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-balance does not match a supported file type
[2020-06-05T13:00:31.7074253+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR21" started.
[2020-06-05T13:00:31.7077051+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test/account-balance
[2020-06-05T13:00:31.7077942+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-balance does not match a supported file type
[2020-06-05T13:00:32.2103440+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR22" started.
[2020-06-05T13:00:32.2118432+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test/account-balance
[2020-06-05T13:00:32.2125894+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-ba'lan'ce does not match a supported file type
[2020-06-05T13:00:33.2223942+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR23" started.
[2020-06-05T13:00:33.2238736+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test/account-balance
[2020-06-05T13:00:33.2243808+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-balance does not match a supported file type
[2020-06-05T13:00:34.2177528+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR24" started.
[2020-06-05T13:00:34.2189073+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test/account-balance
[2020-06-05T13:00:34.2193483+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-balance does not match a supported file type
[2020-06-05T13:00:35.2169806+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR25" started.
[2020-06-05T13:00:35.2178259+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test/account-balance
[2020-06-05T13:00:35.2181055+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-balance does not match a supported file type
[2020-06-05T13:00:36.2183025+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR26" started.
[2020-06-05T13:00:36.2195050+00:00 Microsoft.AspNetCore.Hosting.Diagnostics INF] Request starting HTTP/1.0 GET http://172.16.2.52/v1/user/test/account-balance
[2020-06-05T13:00:36.2199702+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG] The request path /v1/user/test/account-balance does not match a supported file type
[2020-06-05T13:00:37.2373822+00:00 Microsoft.AspNetCore.Server.Kestrel DBG] Connection id "0HM09A1MAAR27" started.

---

引起的幾種後果

客戶端調用超時

通過了 30S 甚至更長時間後看到大量的數據庫鏈接被初始化，而後開始集中式返回。

此時可能對於客戶端調用來講這一批請求都是超時的，

嚴重影響用戶體驗和某些依賴於此的其餘接口。

數據庫鏈接暴漲

由於同時進入大量數據庫查詢請求觸發數據庫 DbContextPool 大量建立，

鏈接數隨之暴漲，數據庫查詢性能急速降低，可能引起其餘的應用問題。

引起服務「雪崩」效應，服務不可用

請求堆積的狀況下，

health-check 接口響應異常，

致使 k8s 主動重啓服務，重啓後繼續上述狀況，

不斷惡化最後致使服務不可用。

---

排查問題

數據庫的問題 ？

固然，首先懷疑的就是數據庫了。

存在性能瓶頸？慢查詢致使不響應？發佈期間存在其餘的異常？

這類的問題都意義排查起來了。

最後發現，

這種狀況發生的時候，數據庫監控裏面一片祥和。

數據庫 IO、CPU、內存都正常，

鏈接數暴漲是這種狀況發生的時候帶來的，

而不是鏈接數暴漲以後致使了此狀況。

數據庫驅動或者 EF Core 框架的問題？

是的，

這個懷疑一直都存在於腦海中。

最終，

昨天帶着「被捱罵的狀況」去問了下「Pomelo.EntityFrameworkCore.MySql」的做者。

春天的熊 18:34:08
柚子啊，我這邊的.NET Core服務剛起來，創建MySQL鏈接的時候好慢，而後同一批請求可能沒法正常響應，這個有什麼好的解決思路嗎？

Yuko丶柚子 18:34:29
Min Pool Size = 200

Yuko丶柚子 18:34:32
放鏈接字符串裏

春天的熊 18:34:53
這個字段支持了嗎？

Yuko丶柚子 18:35:07
一直都支持

春天的熊 18:35:56
等等，      public static IServiceCollection AddDbContextPool<TContext>([NotNullAttribute] this IServiceCollection serviceCollection, [NotNullAttribute] Action<DbContextOptionsBuilder> optionsAction, int poolSize = 128) where TContext : DbContext;

春天的熊 18:36:13
這裏不是默認最大的128麼？

Yuko丶柚子 18:36:18
你這個pool size是dbcontext的

Yuko丶柚子 18:36:21
我說的是mysql鏈接字符串的

Yuko丶柚子 18:36:28
dbcontext的pool有什麼用

春天的熊 18:43:13
我問個討打的問題，dbcontext 是具體的連接實例，EF用的，Min Pool Size 指的是這一個實例上面的鏈接池嗎「？

Yuko丶柚子 18:44:07
你在說什麼。。。

Yuko丶柚子 18:45:58
放到mysql的鏈接字符串上

Yuko丶柚子 18:46:14
這樣第一次調用MySqlConnection的時候就會創建200個鏈接

春天的熊 18:46:56
默認是多少來的？100嗎？

Yuko丶柚子 18:48:33
0

Yuko丶柚子 18:48:40
max默認是100

Yuko丶柚子 18:52:50
DbContextPool要解決的問題你都沒搞清楚

春天的熊 18:53:23
DbContextPool要解決的是儘可能不去重複建立DbContext

Yuko丶柚子 18:53:34
爲何不要重複建立DbContext

春天的熊 18:53:50
由於每一個DbContext建立的代價很高，並且很慢

Yuko丶柚子 18:54:01
建立DbContext有什麼代價

Yuko丶柚子 18:54:03
哪裏慢了

Yuko丶柚子 18:54:06
都是毫秒級的

Yuko丶柚子 18:54:20
他的代價不在於建立 而在於回收

Yuko丶柚子 18:54:25
DbContextPool要解決的問題是 由於DbContext屬於較大的對象，並且是頻繁被new，並且常常失去引用致使GC頻繁工做。

Yuko 大大說的狀況感受會是一個思路，

因此第一反應就是加了參數控制鏈接池。

不過，無果。

5 個實例，

有 3 個實例正常啓動，

2 個實例會重複「雪崩」效應，最終沒法正常啓動。

這個嘗試操做重複了好屢次，

根據文檔和 Yuko 大大指導繼續加了很多 MySQL 連接參數，

最後，

從新學習了一波連接參數的優化意義，

無果。

---

究竟數據庫驅動有沒有問題？

沒什麼好的思路了，

遠程到容器裏面 Debug 基本不太現實（從新打包 + 容器化打包 + k8s + 人肉和服務器垮大洋），

要不，試試把日誌登陸調節到 Debug 看看全部的行爲？

{
  "Using": ["Serilog.Sinks.Console"],
  "MinimumLevel": {
    "Default": "Debug",
    "Override": {
      "Microsoft": "Debug"
    }
  },
  "WriteTo": [
    {
      "Name": "Console",
      "Args": {
        "outputTemplate": "[{Timestamp:o}  {SourceContext} {Level:u3}] {Message:lj}{NewLine}{Exception}"
      }
    }
  ]
}

固然，這個事情沒有直接在正常的生產環境執行。

這裏是使用新配置，從新起新實例來操做。

而後咱們看到程序啓動的時候執行 EFMigration 的時候，

程序和整個數據庫交互的完整日誌。

[2020-06-05T12:59:56.4147202+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Opening connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.4159970+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Opened connection to database 'user_pool' on server 'a'li'yun'.
[2020-06-05T12:59:56.4161172+00:00 Microsoft.EntityFrameworkCore.Database.Command DBG] Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA='user_pool' AND TABLE_NAME='__EFMigrationsHistory';
[2020-06-05T12:59:56.4170776+00:00 Microsoft.EntityFrameworkCore.Database.Command INF] Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA='user_pool' AND TABLE_NAME='__EFMigrationsHistory';
[2020-06-05T12:59:56.4171630+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Closing connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.4172458+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Closed connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.4385345+00:00 Microsoft.EntityFrameworkCore.Database.Command DBG] Creating DbCommand for 'ExecuteReader'.
[2020-06-05T12:59:56.4386201+00:00 Microsoft.EntityFrameworkCore.Database.Command DBG] Created DbCommand for 'ExecuteReader' (0ms).
[2020-06-05T12:59:56.4386763+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Opening connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.4400143+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Opened connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.4404529+00:00 Microsoft.EntityFrameworkCore.Database.Command DBG] Executing DbCommand [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT `MigrationId`, `ProductVersion`
FROM `__EFMigrationsHistory`
ORDER BY `MigrationId`;
[2020-06-05T12:59:56.4422387+00:00 Microsoft.EntityFrameworkCore.Database.Command INF] Executed DbCommand (2ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT `MigrationId`, `ProductVersion`
FROM `__EFMigrationsHistory`
ORDER BY `MigrationId`;
[2020-06-05T12:59:56.4446400+00:00 Microsoft.EntityFrameworkCore.Database.Command DBG] A data reader was disposed.
[2020-06-05T12:59:56.4447422+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Closing connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.4447975+00:00 Microsoft.EntityFrameworkCore.Database.Connection DBG] Closed connection to database 'user_pool' on server 'aliyun-rds'.
[2020-06-05T12:59:56.5170419+00:00 Microsoft.EntityFrameworkCore.Migrations INF] No migrations were applied. The database is already up to date.

---

看到這裏的時候，因爲發現咱們以前對 DbContext 和 DbConnection 的理解不太好，

想搞清楚到底是不 db connection 建立的時候有哪些行爲，

因而咱們找到了 dotnet/efcore Github 的源碼開始拜讀，

PS： 源碼真香，能看源碼真好。

嘗試經過「Opening connection」找到日誌的場景。

想了解這個日誌輸出的時候代碼在作什麼樣的事情，可能同時會有哪些行爲。

在考慮是否是其餘的一些行爲致使了上面的服務問題？

最終在RelationalConnection.cs確認上面這些數據庫相關日誌確定是會輸出的，不存在其餘的異常行爲。

PS：不用細看，咱們認真瀏覽了代碼以後確認 DbContext 正常初始化，

/// <summary>
        ///     Asynchronously opens the connection to the database.
        /// </summary>
        /// <param name="errorsExpected"> Indicate if the connection errors are expected and should be logged as debug message. </param>
        /// <param name="cancellationToken">
        ///     A <see cref="CancellationToken" /> to observe while waiting for the task to complete.
        /// </param>
        /// <returns>
        ///     A task that represents the asynchronous operation, with a value of <see langword="true"/> if the connection
        ///     was actually opened.
        /// </returns>
        public virtual async Task<bool> OpenAsync(CancellationToken cancellationToken, bool errorsExpected = false)
        {
            if (DbConnection.State == ConnectionState.Broken)
            {
                await DbConnection.CloseAsync().ConfigureAwait(false);
            }

            var wasOpened = false;
            if (DbConnection.State != ConnectionState.Open)
            {
                if (CurrentTransaction != null)
                {
                    await CurrentTransaction.DisposeAsync().ConfigureAwait(false);
                }

                ClearTransactions(clearAmbient: false);
                await OpenDbConnectionAsync(errorsExpected, cancellationToken).ConfigureAwait(false);
                wasOpened = true;
            }

            _openedCount++;

            HandleAmbientTransactions();

            return wasOpened;
        }


        private async Task OpenDbConnectionAsync(bool errorsExpected, CancellationToken cancellationToken)
        {
            var startTime = DateTimeOffset.UtcNow;
            var stopwatch = Stopwatch.StartNew();

            // 日誌輸出在這裏
            var interceptionResult
                = await Dependencies.ConnectionLogger.ConnectionOpeningAsync(this, startTime, cancellationToken)
                    .ConfigureAwait(false);

            try
            {
                if (!interceptionResult.IsSuppressed)
                {
                    await DbConnection.OpenAsync(cancellationToken).ConfigureAwait(false);
                }
                // 日誌輸出在這裏
                await Dependencies.ConnectionLogger.ConnectionOpenedAsync(this, startTime, stopwatch.Elapsed, cancellationToken)
                    .ConfigureAwait(false);
            }
            catch (Exception e)
            {
                await Dependencies.ConnectionLogger.ConnectionErrorAsync(
                    this,
                    e,
                    startTime,
                    stopwatch.Elapsed,
                    errorsExpected,
                    cancellationToken)
                    .ConfigureAwait(false);

                throw;
            }

            if (_openedCount == 0)
            {
                _openedInternally = true;
            }
        }

固然，咱們同時也去看了一眼 MySqlConnector的源碼，

確認它自身是維護了數據庫鏈接池的。到這裏基本確認不會是數據庫驅動致使的上述問題。

---

某種猜想

確定是有什麼奇怪的行爲阻塞了當前服務進程，

致使數據庫鏈接的日誌也沒有輸出。

鎖？ 異步等同步？資源初始化問題？

週五晚上查到了這裏已經十一點了，

因而先下班回家休息了。

因而，

週六練完車以後 Call 了一下小夥伴，

又雙雙開始了愉快的 Debug。

---

插曲

小夥伴海林回公司前發了個朋友圈。

「 咋們繼續昨天的 bug，

特此立 flag：修很差直播吃 bug

反正不是你死就是我亡…」

我調侃評論說:

你等下，我打包下代碼去樓下打印出來待會當晚飯

---

開始鎖定問題

中間件致使的嗎？

[2020-06-05T13:00:35.2181055+00:00 Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware DBG]

The request path /v1/user/test/account-balance does not match a supported file type

咱們對着這個日誌思考了一會人生，

而後把引用此中間件的代碼註釋掉了，

不過，無果。

自定義 filters 致使的嗎？

[2020-06-05T13:01:05.3126001+00:00 Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker DBG] Execution plan of exception filters (in the following order): ["None"]
[2020-06-05T13:01:05.3126391+00:00 Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter", "XXX.Filters.HTTPHeaderAttribute (Order: 0)"]
[2020-06-05T13:01:05.3072206+00:00 Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker DBG] Execution plan of authorization filters (in the following order): ["None"]

看到這個日誌咱們考慮了一下，

是否是由於 filters 致使了問題。

畢竟在 HTTPHeaderAttribute 咱們還還作了 ThreadLocal<Dictionary<string, string>> CurrentXHeaders

這裏懷疑是否是咱們的實現存在鎖機制致使「假死問題」。

嘗試去掉。

不過，

無果。

---

嘗試使用 ptrace

沒什麼很好的頭緒了，要不上一下 ptrace 之類的工具跟一下系統調用？

最先在去年就嘗試過使用 ptrace 抓進程數據看系統調用，

後來升級到.NET Core3.0 以後，官方基於 Events + LTTng 之類的東西作了 dotnet-trace 工具，

官網說明：dotnet-trace performance analysis utility

改一下打包扔上去作一個數據收集看看。

FROM mcr.microsoft.com/dotnet/core/sdk:3.1 AS build-env
WORKDIR /app

# copy csproj and restore as distinct layers
COPY src/*.csproj ./
RUN dotnet restore

COPY . ./

# copy everything else and build
RUN dotnet publish src -c Release -o /app/out


# build runtime image
FROM mcr.microsoft.com/dotnet/core/aspnet:3.1

# debug
# Install .NET Core SDK
RUN dotnet_sdk_version=3.1.100 \
    && curl -SL --output dotnet.tar.gz https://dotnetcli.azureedge.net/dotnet/Sdk/$dotnet_sdk_version/dotnet-sdk-$dotnet_sdk_version-linux-x64.tar.gz \
    && dotnet_sha512='5217ae1441089a71103694be8dd5bb3437680f00e263ad28317665d819a92338a27466e7d7a2b1f6b74367dd314128db345fa8fff6e90d0c966dea7a9a43bd21' \
    && echo "$dotnet_sha512 dotnet.tar.gz" | sha512sum -c - \
    && rm -rf /usr/share/dotnet \
    && rm -rf /usr/bin/dotnet \
    && mkdir -p /usr/share/dotnet \
    && tar -ozxf dotnet.tar.gz -C /usr/share/dotnet \
    && rm dotnet.tar.gz \
    && ln -s /usr/share/dotnet/dotnet /usr/bin/dotnet \
    # Trigger first run experience by running arbitrary cmd
    && dotnet help
RUN dotnet tool install --global dotnet-trace
RUN dotnet tool install -g dotnet-dump
RUN dotnet tool install --global dotnet-counters
ENV PATH="$PATH:/root/.dotnet/tools"

# end debug

WORKDIR /app
COPY --from=build-env /app/out .
ENTRYPOINT ["dotnet", "Your-APP.dll"]

---

更新發布，等待服務正常啓動以後，

使用 ab -c 300 -n 3000 'http://172.16.2.52/v1/user/test/account-balance' 模擬 300 個用戶同時請求，

使得程序進入上述的「假死狀態」。

接着當即進入容器，執行'dotnet-trace collect -p 1' 開始收集日誌。

最後拿到了一份大概 13M trace.nettrace 數據, 這個文件是 PerView 支持的格式，

在 MacOS 或者 Linux 上沒法使用。

好在 dotnet-trace convert 能夠將 trace.nettrace 轉換成 speedscope/chromium 兩種格式。

speedscope/chromium

• speedscope:A fast, interactive web-based viewer for performance profiles.

• chrome-devtools evaluate-performance

• 全新 Chrome Devtool Performance 使用指南

$dotnet-trace convert 20200606-1753-trace.nettrace.txt  --format Speedscope
$dotnet-trace convert 20200606-1753-trace.nettrace.txt --format chromium
$speedscope 20200606-1753-trace.nettrace.speedscope.json

而後，炸雞了。

➜  Downloads speedscope 20200606-1625.trace.speedscope.json
Error: Cannot create a string longer than 0x3fffffe7 characters
    at Object.slice (buffer.js:652:37)
    at Buffer.toString (buffer.js:800:14)
    at main (/home/liguobao/.nvm/versions/node/v12.16.2/lib/node_modules/speedscope/bin/cli.js:69:39)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)

Usage: speedscope [filepath]

If invoked with no arguments, will open a local copy of speedscope in your default browser.
Once open, you can browse for a profile to import.

If - is used as the filepath, will read from stdin instead.

  cat /path/to/profile | speedscope -

哦， Buffer.toString 炸雞了。

看一眼 20200606-1625.trace.speedscope.json 多大?

900M。

牛逼。

那換 Chrome performance 看看。

手動裝載一下 20200606-1753-trace.nettrace.chromium.json 看看。

等下，20200606-1753-trace.nettrace.chromium.json 這貨多大？

哦，4G。應該沒事，Intel NUC 主機內存空閒 20G，吃掉 4G 徹底是沒有問題的。

看着進度條加載，看着內存漲起來，

而後...Chrome 控制檯奔潰。再見再見，原來你們彼此徹底沒有信任了。

唉，再來一次，把文件控制在 5M 左右看看。

最後，把 20200606-1753-trace.nettrace.chromium.json 控制在 1.5G 了，

終於能夠正常加載起來了。

---

Chrome Performance

首先， 咱們看到監控裏面有一堆的線程

隨便選一個線程看看它作撒,選擇 Call Tree 以後 點點點點點。

從調用棧能看到 整個線程當前狀態是「PerformWaitCallback」

整個操做應該的開頭應該是

Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection.System.Threading.IThreadPoolWorkItem.Execute()

PS： Kestrel (https://github.com/aspnet/KestrelHttpServer) is a lightweight cross-platform web server that supports .NET Core and runs on multiple platforms such as Linux, macOS, and Windows. Kestrel is fully written in .Net core. It is based on libuv which is a multi-platform asynchronous eventing library.

PS 人話： .NET Core 內置的 HTTP Server，和 Spring Boot 中的 tomcat 組件相似

很正常，說明請求正常到了咱們的服務裏面了。

再看一下剩下的調用鏈信息。

簡要的調用信息日誌在這裏：

System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection+<ExecuteAsync>d__32.MoveNext()
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnectionMiddleware`1[System.__Canon].OnConnectionAsync(class Microsoft.AspNetCore.Connections.ConnectionContext)   Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnection.ProcessRequestsAsync(class Microsoft.AspNetCore.Hosting.Server.IHttpApplication`1<!!0>)
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(!!0&)
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnection+<ProcessRequestsAsync>d__12`1[System.__Canon].MoveNext()
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync(class Microsoft.AspNetCore.Hosting.Server.IHttpApplication`1<!!0>)
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(!!0&)
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol+<ProcessRequestsAsync>d__216`1[System.__Canon].MoveNext()
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests(class Microsoft.AspNetCore.Hosting.Server.IHttpApplication`1<!!0>)
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(!!0&)
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol+<ProcessRequests>d__217`1[System.__Canon].MoveNext()
Microsoft.AspNetCore.Hosting.HostingApplication.ProcessRequestAsync(class Context)
Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
UserCenter.ErrorHandlingMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(!!0&)
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)

......
......
......

e.StaticFiles.StaticFileMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.Builder.UseMiddlewareExtensions+<>c__DisplayClass4_1.<UseMiddleware>b__2(class Microsoft.AspNetCore.Http.HttpContext)
dynamicClass.lambda_method(pMT: 00007FB6D3BBE570,class System.Object,pMT: 00007FB6D4739560,pMT: 00007FB6D0BF4F98)
Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.GetService(class System.IServiceProvider,class System.Type,class System.Type)
Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope.GetService(class System.Type)
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(!!0&)

Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor`2[Microsoft.Extensions.DependencyInjection.ServiceLookup.RuntimeResolverContext,System.__Canon].VisitCallSite(class Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceCallSite,!0)
System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start(!!0&)

看到這裏，其實又有了一些很給力的信息被暴露出來了。

---

PerformWaitCallback

• 直接字面理解，線程正在執行等待回調

調用鏈信息

耐心點，把全部的電調用鏈都展開。

咱們能看到程序已經依次通過了下面幾個流程：

->ProcessRequestsAsync(系統)

->ErrorHandlingMiddleware(已經加載了自定義的錯誤中間件)

-> HostFilteringMiddleware(加載了 Filter 中間件)

-> Microsoft.Extensions.DependencyInjection.ServiceLookup.CallSiteVisitor(調用鏈中的最後一個操做)

對應最上面的日誌來講，

請求進來，通過了中間件和 Filter 都是沒問題的，

最後在 DependencyInjection（依賴注入） 中沒有了蹤影。

到這裏，

再次驗證咱們昨天的思路：

這是一個 「資源阻塞問題」產生的問題

雖然作 ptrace 是想能直接抓到「兇手」的，

最後發現並無能跟蹤到具體的實現，

那可咋辦呢？

控制變量實踐

已知：

• 併發 300 訪問 /v1/user/test/account-balance 接口程序會假死
• 移除 Filter 中間件不能解決問題
• 併發 300 訪問 /v1/health 健康檢查接口程序正常
• ptrace 信息告訴咱們有「東西」在阻塞 DI 容器建立某些實例

開始控制變量 + 人肉二分查找。

挪接口代碼

/v1/user/test/account-balance 的邏輯是由 AccountService 實現的，

AccountService 大概依賴四五個其餘的 Service 和 DBContext，

最主要的邏輯是加載用戶幾個帳號，而後計算一下 balance。

大概代碼以下：

/// <summary>
/// 獲取用戶的AccountBalance彙總信息
/// </summary>
public async Task<AccountBalanceStat> LoadAccountBalanceStatAsync(string owner)
{
    // 數據庫查詢
    var accounts = await _dbContext.BabelAccounts.Where(ac => ac.Owner == owner).ToListAsync();
    // 內存計算
    return ConvertToAccountBalanceStat(accounts);
}

什麼都不改，直接把代碼 CP 到 Health 接口測一下。

神奇，300 併發抗住了。

結論：

• 上面這一段代碼並不會致使服務僵死
• 數據庫驅動沒有問題，DbContext 沒有問題，數據庫資源使用沒有問題
• 當前並不會觸發 DI 容器異常， 問題出在 /v1/user/test/account-balance 初始化

account-balance 有什麼神奇的東西嗎？

/// <summary>
/// 查詢用戶的Brick帳號餘額
/// </summary>
[HttpGet("v1/user/{owner}/account-balance")]
[SwaggerResponse(200, "獲取成功", typeof(AccountBrickStat))]
public async Task<IActionResult> GetAccountBricks(
    [FromRoute, SwaggerParameter("全部者", Required = true)] string owner)
{
    owner = await _userService.FindOwnerAsync(owner);
    return Ok(new { data = await _accountService.LoadAccountAsync(owner), code = 0 });
}

咱們剛剛驗證了 LoadAccountAsync 的代碼是沒有問題的，

要不 UserService DI 有問題，要不 AccountService DI 有問題。

把 UserService 加入到 HealthController 中。

public HealthController(UserService userService, UserPoolDataContext dbContext)
{
    _dbContext = dbContext;
    _userService= userService;
}

Bool。

300 併發沒有撐住，程序僵死啦。

完美，

問題應該在 UserService DI 初始化了。

接下來就是一個個驗證 UserService DI 須要的資源，

EmailSDK 沒有問題，

HTTPHeaderTools 沒有問題，

UserActivityLogService 沒有問題。

RedisClient...
RedisClient...
RedisClient...

OK
OK
Ok

復現炸雞了。

---

原來是 Redis 的鍋？

是，

也不是。

先看下咱們 RedisClient 是怎麼使用的。

// startup.cs 注入了單例的ConnectionMultiplexer
// 程序啓動的時候會調用InitRedis
private void InitRedis(IServiceCollection services)
{
    services.AddSingleton<ConnectionMultiplexer, ConnectionMultiplexer>(factory =>
    {
        ConfigurationOptions options = ConfigurationOptions.Parse(Configuration["RedisConnectionString"]);
        options.SyncTimeout = 10 * 10000;
        return ConnectionMultiplexer.Connect(options);
    });
}

//RedisClient.cs 經過構造函數傳入

public class RedisClient
{
    private readonly ConnectionMultiplexer _redisMultiplexer;

    private readonly ILogger<RedisClient> _logger;

    public RedisClient(ConnectionMultiplexer redisMultiplexer, ILogger<RedisService> logger)
    {
        _redisMultiplexer = redisMultiplexer;
        _logger = logger;
    }
}

DI 初始化 RedisClient 實例的時候，

須要執行 ConnectionMultiplexer.Connect 方法，

ConnectionMultiplexer.Connect 是同步阻塞的。

ConnectionMultiplexer.Connect 是同步阻塞的。

ConnectionMultiplexer.Connect 是同步阻塞的。

一切都能解釋了。

怎麼改？

// InitRedis 直接把連接建立好，而後直接注入到IServiceCollection中
private void InitRedis(IServiceCollection services)
{
    ConfigurationOptions options = ConfigurationOptions.Parse(Configuration["RedisConnectionString"]);
    options.SyncTimeout = 10 * 10000;
    var redisConnectionMultiplexer = ConnectionMultiplexer.Connect(options);
    services.AddSingleton(redisConnectionMultiplexer);
    Log.Information("InitRedis success.");
}

發佈驗證，

開門放併發 300 + 3000 請求。

完美抗住，絲通常順滑。

還有更優的寫法嗎？

• 看了下微軟 Cache 中間件源碼，更好的作法應該是經過信號量+異步鎖來建立 Redis 連接，下來再研究一下
• 數據庫中可能也存在相似的問題，不過當前會在 Startup 中戳一下數據庫鏈接，應該問題不大。

覆盤

程序啓動的時候依賴注入容器同步初始化 Redis 可能很慢(幾秒甚至更長)的時候，

其餘的資源都在同步等待它初始化好，

最終致使請求堆積，引發程序雪崩效應。

Redis 初始化過慢並不每次都發生， 因此以前服務也只是偶發。

DI 初始化 Redis 鏈接的時候，redis 打來鏈接仍是個同步的方法，

這種狀況下還可能發生異步請求中等待同步資源產生阻塞問題。

同時還須要排查使用其餘外部資源的時候是否會觸發同類問題。

---

幾個通用的小技巧

• ptrace 對此類問題分析頗有意義，不一樣語言框架都有相似的實現

• 同步、異步概念的原理和實現都要了解，這個有利於理解一些奇奇怪怪的問題

• 火焰圖、Chrome dev Performance 、speedscope 都是好東西

• Debug 日誌能給更多的信息，在隔離生產的狀況下大膽使用

• 這輩子都不可能看源碼的，寫寫 CURD 多美麗？源碼真香，源碼真牛逼。

• 控制變量驗證，大膽假設，當心求證，人肉二分查，先懷疑本身再懷疑框架

• 搞事的時候不要本身一我的，有 Bug 必定要拉上小夥伴一塊兒吃

---

相關資料

• IBM Developer ptrace 嵌入式系統中進程間通訊的監視方法

• 分析進程調用 pstack 和 starce

• pstack 顯示每一個進程的棧跟蹤

• 微軟：dotnet-trace performance analysis utility

• 知乎：全新 Chrome Devtool Performance 使用指南

• speedscope A fast, interactive web-based viewer for performance profiles.

• jdk 工具之 jstack(Java Stack Trace)

• 阮一峯:如何讀懂火焰圖？