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

起因和現象

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

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

所以 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)

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

本站聲明:網站內容來源於博客園,如有侵權,請聯繫我們,我們將及時處理

【其他文章推薦】

※產品缺大量曝光嗎?你需要的是一流包裝設計!

※自行創業缺乏曝光? 網頁設計幫您第一時間規劃公司的形象門面

※回頭車貨運收費標準

※推薦評價好的iphone維修中心

※超省錢租車方案

※台中搬家遵守搬運三大原則,讓您的家具不再被破壞!

※推薦台中搬家公司優質服務,可到府估價

周六生產服務器出現redis服務器不可用狀態，錯誤信息為:

狀態不可用，等待後台檢查程序恢復方可使用。Unexpected end of stream; expected type ‘Status’

如下圖所示，下圖6300就是我們redis服務器運行的端口。

 

頭一次碰到此類問題，心想難道是redis掛掉了，隨即通過telnet ip+端口。發現運行正常，然後就想着進入redis看下目前連接情況。一看發現竟然高達1903條這麼多。

然後想着應該是代碼創建redis連接過多導致的，查看代碼。

發現redis創建只有這一個地方有，這裏也是服務註冊時才執行。也就是應用程序啟動時才被執行一次。然後整個項目查找，沒有其他地方再有調用redis初始化。

心有不甘，難道是每次在redis讀寫數據時都會創建連接嗎？會和讀寫頻繁有關係嗎？總感覺不會啊，隨即創建測試代碼進行測試一番。

在本地搭建了一個redis環境，測試之前先看看接數多少，目前看只有1個，也就是目前的cmd連接客戶端，這個屬於正常的了。

開始測試，運行程序。代碼是創建一個連接對象，並一共測試1000次寫，和1000次讀。

 

不管我怎麼測試連接都是6個，那麼也就是說我們程序最多創建了5個連接，當然主要有線程池在裏面。

 

所以基本的存儲讀取這塊代碼肯定是沒問題。

但代碼這塊也沒算完全放棄排查，因為生產服務器通過docker運行着大約6個應用程序。都是連接的同一個redis,會不會是其他應用程序導致的？

然後就想直接通過redis 連接列表裡的中隨便一個端口來查詢對應的進程信息就可以知道是哪些應用程序了。

Linux 中通過查詢網絡端口號显示進程信息。

netstat -atunlp | grep 60852 

首先看這端口對應的IP，比如這裏第一個是172.17.0.1。熟悉docker的同學應該知道這個ip是docker網關IP。我們容器中的程序都是通過這個網關IP來和我們宿主主機來通訊的。我們通過ifconfig就能發現docker這個網關IP，第二個172.17.0.3:6379這個一看就是redis的容器IP，

這樣一看確實無法找到具體對應哪個容器中的程序和我們建立連接的。

有一個最笨的辦法就是挨個進入容器裏面。即docker exec –it test /bin/bash 然後查看當前容器的網絡連接情況。這樣非常麻煩，並且需要安裝很多組件才能執行一系列命令。

另外一個辦法lsof命令,如果沒有則需要安裝。我們可以通過進程去找所有網絡連接情況。

比如我們剛發現我們的進程主要是docker，他的pid是582251。

lsof -i |grep 582251或者 lsof -i -p 582251

結果如下圖，右邊其實出現了具體IP，這個IP就是docker容器具體的IP地址。

 

現在知道所有IP和端口了，我們將命令執行結果下載下來。

首先找到自己每個容器對應的IP。

docker inspect name |grep IPAddress    //name 容器名稱或者id

 

找到每個ip后然後根據剛下載的所有網絡連接信息進行統計，看哪個IP連接最多，最多的一個肯定有問題。

然後我就找到這個IP對應的容器部署的程序，然後看redis配置。發現線程池設為200。

另外我通過github,發現CSRedisCore還有個預熱機制，也就是preheat，他默認值就是5個預熱連接。

我們線程池設置的是200加上本身有個預熱機制5個連接，我不知道是不是會創建200*5=1000個。這個有時間再好好研究下源代碼，目前只是猜測。

我現在已經將redis修改為poolsize=5, preheat=false。線程池5個，並且關閉預熱機制。

 

修改我們連接配置，並重啟應用服務器和redis服務器(為了徹底清除已建立的連接)后發現連接數有減少，但沒有很多。後來查詢發現，是redis的idle空閑時長太長，導致連接池維持太多連接，沒有被釋放。

我們設置下超時為30s

執行CONFIG SET timeout 30 (單位是秒，此種方式只是臨時修改，針對當前運行有效。長效記得修改redis配置文件)

然後再看下連接數多少，這樣一下子就減少了很多。

總結：

1、 redis連接暴增，首先從自身應用程序出發去尋找問題，比如我這邊發現的連接池設置過大，加上默認的預熱機制等。還有盡可能的看代碼層面在創建連接是否會被多次觸發，如果有就必須要改正。現在都是通過注入的方式創建實例，要看該地方是存在被多次調用。

2、修改redis服務器配置，比如連接空閑超時時間。包括也可也看下最大連接數多少，默認值。

 

本站聲明:網站內容來源於博客園,如有侵權,請聯繫我們,我們將及時處理

【其他文章推薦】

※回頭車貨運收費標準

※產品缺大量曝光嗎?你需要的是一流包裝設計!

※自行創業缺乏曝光? 網頁設計幫您第一時間規劃公司的形象門面

※推薦評價好的iphone維修中心

※教你寫出一流的銷售文案?

※台中搬家公司教你幾個打包小技巧,輕鬆整理裝箱!

※台中搬家遵守搬運三大原則,讓您的家具不再被破壞!