一次依賴注入不慎引發的一連串事故
起因和現象
偶爾會看到線上服務啟動的時候第一波流量進來之後，
遲遲沒有任何的響應，同時服務的監控檢查接口正常，
所以 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維修中心
※超省錢租車方案
※台中搬家遵守搬運三大原則,讓您的家具不再被破壞!
※推薦台中搬家公司優質服務,可到府估價