天天看點

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

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

起因和現象

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

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

是以 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...

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 是同步阻塞的。

一切都能解釋了。

怎麼改?

// 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)
  • 阮一峰:如何讀懂火焰圖?

繼續閱讀