Вступ

У старій публікації я детально описував, як використовувати події ContentionStart та ContentionStop для вимірювання тривалості блокувань у .NET програмі. У pull request'і .NET 9 колишній колега з Criteo Grégoire Verdier додав нові події для сповіщення про час очікування, схожий на блокування, для таких об'єктів, як Mutex, Semaphore, Manual/AutoResetEvent. Детальніше читайте в його пості, де він пояснює, що саме він намагався дослідити.

В асинхронних та багатопоточних алгоритмах дуже важливо виявляти неочікуване очікування/блокування в наших додатках. Цей пост показує, як використовувати ці події для вимірювання тривалості таких очікувань і отримання стека викликів, коли очікування почалося:

Нові події WaitHandleWait

Ці нові події виводяться провайдером Microsoft-Windows-DotNETRuntime CLR, коли ви активуєте ключове слово WaitHandle (= 0x40000000000) з рівнем деталізації Verbose. Кожного разу, коли викликається WaitOne на об'єкті очікування і цей об'єкт вже зайнятий, генерується подія WaitHandleWaitStart. Коли об'єкт звільняється, генерується подія WaitHandleWaitStop.

Наприклад, наступний код:

static Mutex mutex = new Mutex();  

static void Main()  
{  
 var owningThread = new Thread(OwningThread);  
 owningThread.Start();  
 var mutexThread = new Thread(MutexThread);  
 mutexThread.Start();  

 owningThread.Join();  
 mutexThread.Join();  
}  

static void OwningThread()  
{  
 Console.WriteLine($" [{GetCurrentThreadId(), 8}] Start to hold resources");  
 Console.WriteLine("___________________________________________");  
 mutex.WaitOne();  

 Thread.Sleep(3000); // очікування має тривати близько 3 секунд  

 Console.WriteLine(" Release resources");  
 mutex.ReleaseMutex();  
}  

static void MutexThread()  
{  
 Console.WriteLine($" [{GetCurrentThreadId(), 8}] waiting for Mutex...");  
 mutex.WaitOne(); // події генеруються під час блокування  
 mutex.ReleaseMutex();  
 Console.WriteLine(" <-- Mutex");  
}

генерує пару подій Start і Stop:

125980 | 00000000-0000-0000-0000-000000000000 > event 301 __ [1| Start] WaitHandleWait/Start  
125980 | 00000000-0000-0000-0000-000000000000 > event 302 __ [2| Stop] WaitHandleWait/Stop

Оскільки немає асоційованого ID активності, можна покладатися на те, що той самий потік, який чекає (125980 в попередньому прикладі), генерує обидві події.

Прослуховування нових подій очікування

Як зазвичай, вам слід покладатися на пакет TraceEvent nuget, щоб розпочати сесію EventPipe з уже працюючим додатком .NET. Остання версія вже містить визначення ключового слова:

keywords |= ClrTraceEventParser.Keywords.WaitHandle; // .NET 9 тип блокування WaitHandle

та C# події для Start і Stop:

source.Clr.WaitHandleWaitStart += OnWaitHandleWaitStart;  
source.Clr.WaitHandleWaitStop += OnWaitHandleWaitStop;

Реалізація обробника проста.
Початок очікування записується для поточного потоку:

private void OnWaitHandleWaitStart(WaitHandleWaitStartTraceData data)  
{  
 // отримуємо інформацію про блокування для поточного потоку  
 ContentionInfo info = _contentionStore.GetContentionInfo(data.ProcessID, data.ThreadID);  
 if (info == null)  
 return;  

 // відстежуємо початок очікування  
 info.ContentionStartRelativeMSec = data.TimeStampRelativeMSec;  
}

Коли очікування завершується, обчислюється тривалість на основі записаного початку очікування, оскільки воно не надається в корисному навантаженні як для ContentionStop:

private void OnWaitHandleWaitStop(WaitHandleWaitStopTraceData data)  
{  
 ContentionInfo info = _contentionStore.GetContentionInfo(data.ProcessID, data.ThreadID);  
 if (info == null)  
 return;  
 // нещасний випадок, коли ми починаємо слухати тільки після події WaitHandleStart  
 if (info.ContentionStartRelativeMSec == 0)  
 {  
 return;  
 }  

 // На жаль, тривалість не надається в корисному навантаженні, як у ContentionStop...  
 var contentionDurationMSec = data.TimeStampRelativeMSec - info.ContentionStartRelativeMSec;  
 info.ContentionStartRelativeMSec = 0;  
 var duration = TimeSpan.FromMilliseconds(contentionDurationMSec);  
 Console.WriteLine($"{e.ThreadId,7} | {e.Duration.TotalMilliseconds} ms");  
}

Це добре, але було б корисніше, якби ми могли отримати стек викликів для довгих очікувань.

Стек викликів з EventPipe

У попередньому пості, я пояснив, що можливо отримати стек викликів, коли подія виводиться завдяки ClrStackWalk події, яка слідує за подією, що вас цікавить. На жаль, це більше не так для .NET 5+, який використовує EventPipe замість ETW.

Як Олів'є Коанет пояснює у своєму пості, ви можете отримати стек викликів як масив адрес з прихованого запису події, який відображається параметром TraceEvent, що передається кожному обробнику подій. Ця структура EVENT_RECORD містить поле ExtendedData, яке є масивом EVENTHEADEREXTENDEDDATAITEM:

public struct EVENT_HEADER_EXTENDED_DATA_ITEM  
{  
 public ushort Reserved1;  
 public ushort ExtType;  
 public ushort Reserved2;  
 public ushort DataSize;  
 public ulong DataPtr;  
}

Якщо значення ExtType дорівнює EVENTHEADEREXTTYPESTACK_TRACE64 (=6), то DataPtr вказує на структуру EVENTEXTENDEDITEMSTACKTRACE64:

public struct EVENT_EXTENDED_ITEM_STACK_TRACE64  
{  
 public ulong MatchId;  
 public unsafe fixed ulong Address[1];  
}

яка містить масив 64-бітних адрес.
Розмір цього масиву визначається значенням DataSize — sizeof(ulong).

Для 32-розрядних додатків ви отримаєте EVENTHEADEREXTTYPESTACK_TRACE32 (=5) як значення ExtType, і DataPtr вказуватиме на EVENTEXTENDEDITEMSTACKTRACE32:

public struct EVENT_EXTENDED_ITEM_STACK_TRACE32  
{  
 public ulong MatchId;  
 public unsafe fixed uint Address[1];  
}

яка зберігає масив 32-розрядних адрес.

Знаючи це, написання коду для отримання стеку викликів як масиву 64-розрядних адрес (для простоти, те ж саме для 32-розрядних додатків) буде досить простим:

public static EventPipeUnresolvedStack ReadStackUsingUnsafeAccessor(TraceEvent traceEvent)  
{  
 return GetFromEventRecord(traceEvent.eventRecord);  
}  

private static EventPipeUnresolvedStack GetFromEventRecord(TraceEventNativeMethods.EVENT_RECORD* eventRecord)  
{  
 if (eventRecord == null)  
 return null;  

 var extendedDataCount = eventRecord->ExtendedDataCount;  

 for (var dataIndex = 0; dataIndex < extendedDataCount; dataIndex++)  
 {  
 var extendedData = eventRecord->ExtendedData[dataIndex];  
 if (extendedData.ExtType == TraceEventNativeMethods.EVENT_HEADER_EXT_TYPE_STACK_TRACE64)  
 {  
 var stackRecord = (TraceEventNativeMethods.EVENT_EXTENDED_ITEM_STACK_TRACE64*)extendedData.DataPtr;  
 var addresses = &stackRecord->Address[0];  
 var addressCount = (extendedData.DataSize - sizeof(UInt64)) / sizeof(UInt64);  
 if (addressCount == 0)  
 return null;  

 var callStackAddresses = new ulong[addressCount];  
 for (var index = 0; index < addressCount; index++)  
 {  
 callStackAddresses[index] = addresses[index];  
 }  
 return new EventPipeUnresolvedStack(callStackAddresses);  
 }  
 else if (extendedData.ExtType == TraceEventNativeMethods.EVENT_HEADER_EXT_TYPE_STACK_TRACE32)  
 {  
 var stackRecord = (TraceEventNativeMethods.EVENT_EXTENDED_ITEM_STACK_TRACE32*)extendedData.DataPtr;  
 var addresses = &stackRecord->Address[0];  
 var addressCount = (extendedData.DataSize - sizeof(UInt32)) / sizeof(UInt32);  
 if (addressCount == 0)  
 return null;  

 var callStackAddresses = new ulong[addressCount]; // зберігаємо 32 адреси як 64-бітні адреси  
 for (var index = 0; index < addressCount; index++)  
 {  
 callStackAddresses[index] = addresses[index];  
 }  

 return new EventPipeUnresolvedStack(callStackAddresses);  
 }  
 }  

 return null;  
}

Зверніть увагу, що остання версія TraceEvent nuget надає публічний доступ до поля eventRecord, тому більше не потрібно використовувати атрибут UnsafeAccessor, який використовував Олів'є.

Символізація адрес стеку викликів

Адреса — це добре, але відповідна назва методу ще краща. Я не буду повторювати те, що вже детально пояснив у старому пості, який показує, як отримати ім'я рідного та керованого методу за адресою вказівника інструкції. Натомість, я хочу вказати на велику обмеженість цього рішення для прослуховування подій CLR постачальника MethodLoadVerbose/MethodDCStartVerboseV2. Якщо методи, які вас цікавлять, були скомпільовані за допомогою JIT ДО того, як ваш інструмент приєднається до додатка, ви ніколи не отримаєте ці події.

Ви можете отримати те ж саме відображення діапазону адрес/назви методу через іншого постачальника “Microsoft-Windows-DotNETRuntimeRundown” та його подію MethodDCEndVerbose, яка містить у своєму корисному навантаженні очікувані MethodStartAddress, MethodSize та MethodName.
Але мені потрібно отримати цю інформацію до завершення програми…

Переглянувши документацію, здається, що постачальник rundown приймає значення StartRundownKeyword, щоб генерувати події DCStart, коли постачальник увімкнений! З .NET 9 тепер можна передавати ключові слова, які ви хочете (раніше за замовчуванням значення не включало StartRundownKeyword) під час створення сесії EventPipe

// V-- це стандартне ключове слово для *rundown*  
rundownKeywords = 0x80020139 | (long)ClrTraceEventParser.Keywords.StartEnumeration;  
var config = new EventPipeSessionConfiguration(GetProviders(), 256, rundownKeywords, true);  
using (var session = client.StartEventPipeSession(config))  
{  
 var source = new EventPipeEventSource(session.EventStream);  
 RegisterListeners(source);  

 // це блокуючий виклик  
 source.Process();  
}

Зверніть увагу, що ви не повинні додавати постачальника rundown до списку, переданого як параметр.

На жаль, є поточна проблема в середовищі виконання з вересня 2020 року, яка вказує саме на цю проблему. Я навіть намагався створити та закрити сесію, щоб отримати події DCStop перед створенням нової, але не вдався.

Наступна частина розповість, як можна запустити .NET-додаток і отримувати події з його запуску… із проблемами, які виникають.

Перекладено з: Measuring the impact of locks and waits on latency in your .NET apps