Один из шагов, который мы предпринимаем перед выпуском стабильной версии, — это вставить последнюю сборку в наши собственные производственные серверы и посмотреть, что произойдет. Безусловно, это был довольно приятный процесс, и в основном он укрепил нашу уверенность в том, что мы можем перейти к производству с этой версией. Но иногда он делает то, что должен, и обнаруживает ошибки, которые очень сложно запустить в работе.
В этом случае, через несколько часов (я полагаю, от 8 до 12), мы обнаружили, что на некоторых наших сайтах мы начнем получать ошибки, такие как EsentOutOfSessionsException. Esent сессии являются основным способом доступа к Esent, и мы очень осторожны в управлении ими. Раньше на самом деле не было никакой возможности получить эту ошибку, это действительно первый раз, когда мы видели это за пределами лаборатории. Разница в 2.5 заключается в том, что мы разрешили использовать отдельные сеансы вместе с вызовами DTC. Это дало нам возможность ожидать фиксации между этапами подготовки и фиксации операции.
Пересматривая код, я обнаружил некоторые места, где мы неправильно распределяли сессии, что могло бы объяснить это. Поэтому я исправил это и выдвинул новую версию. Это заняло немного больше времени, но произошла та же ошибка. 
Хорошая вещь о том, чтобы это произошло на наших производственных серверах, состоит в том, что у меня есть полный доступ там Конечно, он находится в производстве, так что не отладить его напрямую, но взять дамп и перенести его на мою машину было достаточно просто.
Теперь откройте его с помощью WinDBG, запустите «.loadby sos clr» и начните расследование.
Первая команда, как всегда, это! И там я мог видеть несколько потоков, помеченных Microsoft.Isam.Esent.Interop.EsentOutOfSessionsException. Это было интересно, и сказали, что мы поймали проблему, как это происходило, и это было здорово.
Затем пришло время немного взглянуть на реальную память. Я запустил сеанс типа! DumpHeap
Моя реакция была такова: «Да! Для этого нет абсолютно никакого оправдания».
Now, the only question is why. So I decided to look at the class that holds the transaction state, assuming that this is probably what is holding onto all those sessions. I ran a !DumpHeap -type EsentTransactionContext:
And that tells me quite a lot. There appear to be now a total of 317 in-flight DTC transactions. Considering that I know what our usage is, that is a huge number, and it tells me that something isn’t right here. This is especially true when you consider that we don’t have that many open databases holding in-flight transactions: !DumpHeap -type EsentInFlightTransactionalState –stat
In other words, we have 8 loaded DBs, each of them holding their in-flight transactional state, and we have 317 opened transactions and 35 thousand sessions. That is pretty ridiculous. Especially given that I know that we are supposed to have a max of single-digit concurrent DTC transactions at any one time. So somehow we are leaking transactions and sessions, but I am still very unhappy with just “we are leaking sessions.” That is something that I knew before we started debugging everything.
I can already tell that we probably need to add a more robust way of expiring transactions, and I added that, but the numbers don’t add up to me. Since this is pretty much all I can do with WinDBG, I decided to use another tool, MemProfiler. This gives me the ability to import the dump file and then analyze it in a much nicer manner. Doing so, I quickly found this out:
Huh?!
Sessions are finalizable, sure, but I am very careful about making sure to dispose of them, especially after the previous code change. There should be just 317 undisposed sessions, and having that many items in the finalizer queue can certainly explain things. But I don’t know how they got there, and the numbers don’t match, either. We are missing about 7K items from the WinDBG numbers.
OK, next, I pulled ClrMD and wrote the following:
var dt = DataTarget.LoadCrashDump(@"C:\Users\Ayende\Downloads\w3wp\w3wp.dmp");
var moduleInfo = dt.ClrVersions[0].TryGetDacLocation();
var rt = dt.CreateRuntime(moduleInfo);
var clrHeap = rt.GetHeap();
var finalized = new HashSet<ulong>();
int cnt = 0;
foreach (var ptr in rt.EnumerateFinalizerQueue())
{
var type = clrHeap.GetObjectType(ptr);
if (type.Name == "Microsoft.Isam.Esent.Interop.Session")
{
finalized.Add(ptr);
}
}
Console.WriteLine(finalized.Count);
var live = new HashSet<ulong>();
foreach (var ptr in clrHeap.EnumerateObjects())
{
var type = clrHeap.GetObjectType(ptr);
if (type.Name == "Microsoft.Isam.Esent.Interop.Session")
{
if (finalized.Contains(ptr) == false)
live.Add(ptr);
}
}
Console.WriteLine(live.Count);
This gave me 28,112 sessions in the finalizer queue and 7,547 session that are still live. So something is creating a lot of instances, but not using or referencing them?
I did a code review over everything once again, and I think that I got it. The culprit is this guy:
Where createContext is defined as:
Now, what I think is going on is that the concurrent dictionary, which is what transactionContexts might be calling the createContext multiple times inside the GetOrAdd method, because those create values that have to be disposed… Now, in the normal course of things, the worst-case scenario would be that we would have them in the finalizer queue and they would be disposed of in due time. However, under load, we actually gather quite a few of them, and we run out of available sessions to operate with.
At least, this is my current theory. I changed the code to be like this:
So, if my value wasn’t created, I’ll properly dispose of it. I’ll be pushing this to production in a bit and seeing what is happening. Note that there isn’t locking, but we might be generating multiple sessions. That is fine, as long as only one of them survives.