24-ядрен процесор, а не мога да помръдна курсора на мишката

Превод на 24-core CPU and I can’t move my mouse

Всичко започна, когато моят компютър започна да се забавя. А това е моят работен компютър с Windows 10 и 24-ядрен (48 потока) процесор, натоварен до около 50%. Бързият SSD почти не се използваше. И все пак, когато помръднах мишката, курсорът не реагира веднага. Имах случаи на лагване с продължителност няколко секунди.

И този път направих това, което правя във всички подобни случаи – записах и трасирах събитията с помощта на ETW (Event Tracing for Windows). И да, открих бъг в ОС Windows 10, сериозно влияещ на производителността при завършването на процесите.

Трасирането с помощта на ETW показа, че потребителският интерфейс (UI) се срива в редица програми. Започнах с изследването на 1,125-секундното закъснение на курсора в диспечера на задачите Task Manager:

По-долният скрийншот показва използването на процесора от операционната система по време на този лаг. Процесите се виждат, но и добре се забелязва, че процесорът почти не се натоварва над 50%.

Таблицата CPU Usage (Precise) показва, че UI потокът на диспечера на задачите постоянно се блокира от извикванията на функцията SendMessageW, която явно изчаква в критична зона на ядрото, дълбоко в стека на извикванията win32kbase.sys!EnterCrit (тук това не е показано).

Ръчно преминах по цялата верига на изчакванията и отметнах десетки процеси, за да намеря, кой изяжда ресурсите на потребителския интерфейс. Получи се следното:

Taskmgr.exe (72392) увисва на 1,125 секунда (MsgCheckDelay) на нишката 69,196. Най-голямо забавяне от 115,6 ms внася win32kbase.sys!EnterCrit, подготвен за изпълнение от процеса conhost.exe (16264) на нишка 2560 в точка 3.273101862. След това conhost.exe (16264), 2560 е подготвен за 3.273077782 след изчакване на 115 640,966 ms от процеса mstsc.exe (79392), 71272. От своя страна mstsc.exe е подготвен (същото време на забавяне) от процеса UIforETW.exe (78120), 79584, който пък е подготвен от процеса conhost.exe (16264), 58696, който от своя страна е подготвен от процеса gomacc.exe (93668), 59948, подготвен от процеса gomacc.exe (95164), 76844.

Отказах се да продължавам, понеже повечето процеси преустановяват блокажа само след няколко микросекунди. Но в крайна сметка открих няколко процеса (процесите gomacc.exe) които задържат блокировката няколко стотици микросекунди. Или може да се каже, че те са подготвени от някой, който задържа блокировката, а след няколко микросекунди те подготвят друг процес за нейното прекъсване. Всички тези процеси свалят блокировката в рамките на NtGdiCloseProcess.

Омръзна ми ръчно да проследявам всички тези процеси на изчаквания и реших да прегледам, доколко често се среща този стек с извиквания. Това стана, като преместих колонката Ready Thread Stack наляво и потърсих в нея NtGdiCloseProcess. След това използвах опцията View Callers -> By Function във WPA, за да видя всички стекове Ready Thread Stacks с тази функция. Родителските стекове са показани по-долу:

Програмата изброи 5768 контекстни превключвания, докато процесът NtGdiCloseProcess се намира в стека Ready Thread Stack, като всяко едно от тях обозначава момента, когато се освобождава критична секция. Взети заедно, потоците в тези стекове, съхраняващи извикванията, изчакват общо 63,3 секунди – доста впечатляващо в сравнение с наблюдавания от мен лаг от 1,125 секунди. Ако всяко от тези събития протича след като потока задържа блокирането само с 200 микросекунди, получава се именно забавянето на интерфейса с 1,125 секунди.

Тази част на Windows не ми е особено позната, но съчетанието PspExitThread и NtGdiCloseProcess ясно показва, че това поведение се проявява при завършването на процеса.

Всичко това се случи по време на компилирането на Chrome, а това поражда наистина много процеси. А и аз използвах нашата фирмена разпределена система за компилиране, която създава много процеси, но и ги завършва много бързо.

Следващата стъпка бе да пресметна, колко точно време е изминало и изгубено вътре в NtGdiCloseProcess. Пренесох таблицата CPU Usage (Sampled) във WPA, за да разгледам извикванията на NtGdiCloseProcess. В скрийншота по-долу се вижда, че от 1,125 секундния лаг. около 1085 милисекунди са изразходвани от процеса NtGdiCloseProcess, а това са 96% от цялото време:

А това е твърде лошо – как може 96% от времето да бъде изразходвано от една функция и да не остане време за показване на съобщения и за да се обнови местоположението на курсора. Задълбочих се в този проблем и реших да направя експеримент. Написах тестова програма, която с максимална скорост създава 1000 процеса, изчаква 0,5 секунди и след това подава команда за едновременното завършване на всички тези процеси. В по-долния скрийншот е показано действието на тази програма на моя домашен лаптоп с 4-ядрен (8 потока) процесор:

Да разгледаме тази диаграма. Създаването на процеси е ограничено от възможностите на процесора и това е в реда на нещата. Но спирането на процесите се ограничава от процесора само в началото и края (червените пикове в дясната част, показваща спирането на процесите). Съвсем ясно се вижда, че в средата има един голям промеждутък (около една секунда), където алгоритъмът се обработва последователно и се използва само един от осемте достъпни потока в системата. Да си припомним, че моята програма създаде 1000 процеса и всички те се борят за единствената блокировка, намираща се в NtGdiCloseProcess. Това е сериозен проблем. Именно този промеждутък показва времето на лага, когато програмите силно се забавят, а движенията на курсора почти спират. Понякога това забавяне се разтяга до няколко секунди.

Забелязах че проблемът се задълбочава, когато компютърът е работил известно време. Разбира се, рестартирах компютъра и отново пуснах своята тестова програма. Спирането на процесите не бе толкова тежко, но проблемът си остана дори и в току що стартираната машина.

И тук се сетих за нещо друго. Стартирах своята програма на старичък компютър от 2008 година с Windows 7 и Intel Core 2 Q8200. Резултатите са съвсем съвсем други:

Създаването на нови процеси става по-бавно, както може да се очаква от един много по-слаб процесор. Но тяхното спиране и завършване става дори малко по-бързо от моя нов лаптоп със солиден процесор. Но по-важното е, че всичко става изцяло паралелно и няма престояване на потоци. Това се вижда в дясната страна на изображението, показващо спирането на процесите – промеждутък напълно липсва.

Това показва, че липсата на паралелно приключване на процесите е нов проблем, появил се някъде между Windows 7 и Windows 10.

Законът на Амдал гласи, че ако разпределите своя алгоритъм да се изпълнява на няколко процесорни ядра, то сумарното време на неговото изпълнение зависи от времето на изпълнение на най-дългия фрагмент, който не може да се разпаралели. Когато активно използвам своя работен компютър в продължение на няколко дни, проблемът се изявява все по-явно, а големият брой ядра с нищо не помага. За да ускоря компилацията и през това време курсорът да се движи и интерфейсът да реагира, трябва да рестартирам машината всеки ден. Но при проявата на този неприятен бъг, натоварването на процесора почти не преминава 50%, а дискът не се използва. Връщането към Windows 7 започна да ми изглежда все по-привлекателно.

Всъщност, добавянето на процесорни ядра в моята компютърна система забавя скоростта на реакция на потребителския интерфейс. Просто компилирането на Chrome поражда много процеси, а ако имате повече ядра, толкова повече процеси ще се борят за приключването на работата си. Тоест, май вместо да казвам „24-ядрен процесор, а не мога да помръдна курсора на мишката“ е по-добре да кажа „24-ядрен процесор и затова не мога да мръдна курсора на мишката„.

Съобщихме за този проблем на Microsoft и сега програмистите оглеждат нещата

Ето как изглежда моята тестова програма на моя мощен 24-ядрен компютър:

Виждате ли малката червена линия в долния десен ъгъл? Това е нагледна демонстрация на закона на Амдал, когато 98% от ресурсите на машината престояват почти две секунди, понеже процедурата по завършване на процесите използва само един поток и не може да ги спре. А аз не мога да помръдна курсора на мишката.