В особо тяжелых случаях загружать процессор могут сразу несколько потоков.
Загрузка процессора может быть временной (когда она появляется иногда и через некоторое время пропадает) и перманентная (один раз начавшись не прекращается до момента убиения "виновного" процесса).
Проблемы такого рода в приложении подлежат искоренению :) Дабы не нервировать лишний раз пользователей. Здесь будет описан один такой случай из практики. И процесс поиска ответа на вопрос "Кто виноват и что делать?" (с).
Итак, с чего началась наша история: в какой-то момент приложение начало активно загружает процессор работой, чем ощутимо мешало нормальной работе компьютера (тем более, что последний имеет один одноядерный процессор). По прибытию на место происшествия, был снят дамп с "виновника" [1]. После чего процесс был пристрелен - для восстановления возможности нормальной работы за машиной.
Уже в другом месте, в спокойной обстановке, начинаем анализировать дамп. Для начала найдем "поток-эгоист", который выделяется среди других аппетитом по отношению к времени процессора:
0:000> !runaway
User Mode Time
Thread Time
25:8a8 0 days 0:07:40.625
17:f4c 0 days 0:00:13.140
0:9d0 0 days 0:00:10.343
16:f3c 0 days 0:00:04.656
9:d9c 0 days 0:00:00.734
19:f60 0 days 0:00:00.718
12:e40 0 days 0:00:00.687
26:8d4 0 days 0:00:00.500
43:e2c 0 days 0:00:00.437
32:984 0 days 0:00:00.359
24:854 0 days 0:00:00.281
34:974 0 days 0:00:00.156
14:ec4 0 days 0:00:00.140
...
Тут явно видно, что поток под номером 25 (TID=0x8a8) по параметру "User Mode Time" оставил далеко позади себя остальных. Вот таким бесхитростным образом был найден поток-виновник.
Возможна такая ситуация, когда команда runaway ругнется "Unable to get thread times" и ничего не покажет. В этом случае придется вручную просматривать стеки всех потоков в поисках "аномалий" - потоков, которые не находятся в режиме ожидания какого-либо события. Но лучше сразу на месте, где снимается дамп, в Process Explorer-e [2] подсмотреть ID гиперактивного потока.
Посмотрим на его стек (символой найти не удалось, так что анализ будет немного затруднен :)):
0:025> k
ChildEBP RetAddr
WARNING: Stack unwind information not available. Following frames may be wrong.
0380ff68 2115acfe pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0x11
0380ffa0 2000794a libEvents!RegisterEvents+0x4bae
0380ffb4 7c80b713 rtl100!SystemAssert$qqrx17SystemAnsiStringt1i+0x4a
0380ffec 00000000 kernel32!BaseThreadStart+0x37
Что же мы видим? Что во время снятия дампа, процесс был пойман в методе DRedBlackTree.RBIncrement (библиотеке DeCAL). Посмотрим на него:
procedure DRedBlackTree.RBincrement(var node : DTreeNode);
var
y: DTreeNode;
begin
if node.right <> nil_node then
begin
node := node.right;
while node.left <> nil_node do
node := node.left;
end
else
begin
y := node.parent;
while node = y.right do
begin
node := y;
y := y.parent;
end;
if node.right <> y then
node := y;
end;
end;
Сам по себе этот метод не сложный, так что вероятность при снятии дампа споймать поток именно в нем очень маленькая. Но тем не менее поток именно в нем и был пойман. Так что есть большое подозрение, что именно там поток и залип. Это косвенно подтверждается наличием двух циклов в DRedBlackTree.RBincrement - есть формальный повод зависнуть в одном из них :) Но вполне закономерно возникает вопрос - почему?
Попробуем это выяснить. Судя по стеку, поток запущен каким-то потомком TThread. Чтобы найти, каким именно, посмотрим, ссылки на какие объекты есть в стеке потока (т.к. Delphi по умолчанию использует соглашение вызова register, то ссылка на объект при вызове метода передается в регистре eax, а при вызове других методов того же объекта или методов других объектов, или при вызове обычных процедур, эта ссылка может сохраняться в стеке).
0:025> !stackobj
Range: 0380ff2c - 03810000 (length = 0xd4)
0380ff58 018f88b0 "DMap"
0380ff5c 018f1cf8 "DRedBlackTree"
0380ff9c 00b025a0 "TEvents"
Так-так-так, кое-какие концы мы нашли :) TEvents - это потомок TThread. Проведя небольшое детективное расследование (то бишь банальный поиск по коду), был найден такой код (вызывается из TEvents.Execute):
procedure TEvents.Process;
var
iter: DIterator;
begin
iter := fMap.start; // fMap: DMap
while not atEnd(iter) do
begin
// Полезная нагрузка
...
advance(iter);
end;
end;
Обычный обход всех элементов DMap. Как видно в этом методе тоже есть цикл while, а значит повляется еще одна версия зацикливания потока - в методе TEvents.Process.
Истина где-то рядом (с).
Путь к DRedBlackTree.RBIncrement из TEvents.Process здесь возможен только из advance. Таким образом мы можем восстановить "правильный" стек вызовов в момент снятия дампа:
pkUtils!Decal.DRedBlackTree.RBIncrement pkUtils!Decal.DInternalMap.iadvance pkUtils!Decal.advance libEvents!TEvents.Process libEvents!TEvents.Execute rtl100!System.ThreadWrapper kernel32!BaseThreadStart
Так-с. До окончательного и бесповоротного выяснения сермяжной правды осталось совсем немного. Мы уже практически на финишной прямой. Продолжим.
Для начала дизассемблируем начало метода DRedBlackTree.RBIncrement и помедитируем:
0:025> uf pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode
; eax - ссылка на объект DRedBlackTree
; edx - ссылка на объект DTreeNode
pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode:
2040a250 8b02 mov eax,dword ptr [edx] ; node -> eax
2040a252 8b4018 mov eax,dword ptr [eax+18h] ; node.right -> eax
2040a255 3b052c904520 cmp eax,dword ptr [pkUtils!pkutilsinitialization$qqrv+0x408 (2045902c)] ; node.right <> nil_node ?
2040a25b 7414 je pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0x21 (2040a271)
pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0xd:
2040a25d 8902 mov dword ptr [edx],eax ; node := node.right
2040a25f eb02 jmp pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0x13 (2040a263)
pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0x11:
2040a261 8902 mov dword ptr [edx],eax ; <- Вот тут поток был пойман при снятии дампа
pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0x13:
2040a263 8b02 mov eax,dword ptr [edx] ; node -> eax
2040a265 8b4014 mov eax,dword ptr [eax+14h] ; node := node.left
2040a268 3b052c904520 cmp eax,dword ptr [pkUtils!pkutilsinitialization$qqrv+0x408 (2045902c)]
2040a26e 75f1 jne pkUtils!DecalDRedBlackTreeRBIncrement$qqrrp15DecalDTreeNode+0x11 (2040a261)
...
В процессе медитации выясняется, что в момент снятия дампа в регистре edx находится адрес переменной, которая хранит ссылку на объект DTreeNode (а если конкретно, то edx = @iter.treeNode, где iter - локальная переменная, объявленная в TEvents.Process):
Но проверка показывает, что это не так:
0:000> !object poi(edx) Delphi object not found
Вспомним матчасть.
Поле DIterator.treeNode хранит адрес ноды (DTreeNode) красно-черного дерева (DRedBlackTree). При переборе всех элементов, хранящихся в DMap-e, это поле используется для хранения ссылки на текущий элемент и модифицируется процедурой advance при переходе к следующему элементу.
Но если это поле не указывает на объект типа DTreeNode, то указывать оно может на какую-то левую память. И тогда "путешествие" по полям left/right/parent DTreeNode (используемое в частности в DRedBlackTree.RBIncrement) может в конце концов закончится ошибкой доступа к памяти. Но этого на самом деле не наблюдалось - наоборот поток проявлял повышенную активность. Мистика какая-то...
Ну что же - попробуем пролить свет на этот феномен.
Из дизассемблерного листинга начала функции DRedBlackTree.RBIncrement видно, что в момент снятия дампа поток крутился в цикле:
...
while node.left <> nil_node do
node := node.left;
...
Текущее значение переменной node мы знаем - в этот момент оно хранится в регистре eax (здесь же покажем значение переменной nil_node, оно нам пригодится):
0:025> r eax eax=08374cb0 0:025> dp 2045902c l1 ; nil_node (2045902c - адрес переменной, хранящей nil_node) 2045902c 00b52090
Но хранящееся в нем значение не является ссылкой на валидный объект:
0:025> !object eax Delphi object not foundНу не является, так не является - в конце-концов это не уголовно-наказуемо.
Проверяем, чему равно значение поля node.left
0:025> dp 08374cb0+14 l1 ; 0x14 - смещение поля left в объекте DTreeNode 08374cc4 2007d0bc
Условние node.left <> nil_node не выполняется поэтому можно мысленно продолжить цикл и посмотреть, что их этого получится. Итак, node становится равным 2007d0bc.
node.left:
0:025> dp 2007d0bc+14 l1 08374cc4 08374cb0
Снова получили 08374cb0. Вернулись туда, откуда начали. А это означает, что цикл никогла не закончится. Место зацикливание локализовано, причина залипания выяснена.
А что же относительно главного вопроса - как такое могло получиться?
В данном ситуации ошибка заключается в отсутствии синхронизации доступа к объекту DMap при обходе его элементов. Т.к. вполне возможна ситуация, когда во время такого обхода из других потоков будет вызван метод Register/Unregister (первый из них додавляет элемент, а второй, соответственно, - удаляет). В самих методах Register/Unregister доступ к DMap синхронизируется - в том плане, что не может быть одновренно нескольких операций вставки/удаления. Но, как показал данный случай, перебор всех элементов тоже нуждается в защите.
Остается только удивляться, с какой "ювелирной" точностью был "поломан" итератор в TEvents.Process - что он привел к зацикливанию потока, а не к ошибке типа Access Violation :)
Ссылки
[1] Как создать дамп процесса
[2] Process Explorer
[3] Delphi WinDbg Extension Dll
Комментариев нет:
Отправить комментарий