一次依賴注入不慎引發的一連串事故
起因和現象
偶爾會看到線上服務啟動的時候第一波流量進來之後，
遲遲沒有任何的響應，同時服務的監控檢查介面正常，
所以 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
$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 一定要拉上小夥伴一起吃