Лечу Crash'и NSLog'ами. Недорого. Многолетний опыт. 100% гарантия.
Примерно таким заголовком можно было бы описать то, что три с половиной месяца назад происходило у меня на одном из проектов. Вернее, это даже был не мой проект, но с проблемой crash'а пришлось разбираться именно мне.
Все началось с того, что на одном из относительно больших проектов начало стабильно вываливаться исключение при авторизации пользователя. «Ну и что тут такого? У всех бывает. Проверку на nil забыли поставить или где-то накосячили. „Тоже, мне, большое событие — crash на проекте“, — подумает большая часть программистов. В принципе — абсолютно согласен. Crash — не такое уж и редкое явление в программировании под iPhone, и с ним сталкиваешься по десять раз на день. Но этот был особенным. От него уже начало попахивать „магией“, когда мне сказали про его некоторые параметры и особенности:
- Воспроизводимость на симуляторе: 100%
- Воспроизводимость на устройстве: 0%
- Путь к крэшу (после локализации крэша): ~ 40 секунд
- Настройки оптимизации при компиляции (-O1,-O2...) не влияют на воспроизводимость
- XIB'ы в проекте не используются
Да выглядел он довольно безобидно:
// Code
UITextView * textView = [ [UITextView alloc] initWithFrame:CGRectMake(0, 150, _width, _height)];
// Exception
*** Terminating app due to uncaught exception 'CALayerInvalidGeometry',
reason: 'CALayer bounds contains NaN: [0 0; nan 200]'»Ну тут же и ежу понятно, что width — после вычисления — NaN!", — подумал я. Бегло поглядев где и как вычисляется ширина вьюхи, и не найдя ничего особого опасного, я, для утверждения своей догадки, поставил перед созданием вьюхи NSLog. А вдобавок, и точку останова на строке с созданием элемента.
// Source:
NSLog(@"width = %f", _width);
//Output:
width = 200
«Гм», — подумал про себя я, и продолжил выполнение программы после точки останова. И крэша не произошло…
Тестовый проект, в котором воспроизводится данный Crash
Для тех людей, которым интересно самим поглядеть на этого зверя — тестовый проект лежит у меня.
Воспроизводится исключительно на iOS Simulator'е, Версия SDK 5.1 ( На SDK 6+ не воспроизводится, но если найдутся добрые люди, которые воспроизведут — пишите в личку, разместим)
Если Вы еще думаете, что здесь что-то тривиальное, тогда — спокойно читайте дальше. Когда дойдем до интересностей, я остановлюсь, и сделаю предупреждение про спойлеры.
What have I done?
Если подумать логически, то все становится ясно. Раз crash пропал, то это потому, что я что-то поменял (т.к. до этого воспроизводимость была 100%). Вопрос оставался только в том, что именно изменилось.
- Я добавил немного кода перед созданием вьюхи
- Я добавил NSLog
- Я приостановил поток
- Я доступился к переменной класса _width, перед передачей ее как параметр
- ....
Если у Вас еще есть идеи, что я мог поменять — можете записать. Потом сверитесь, были ли догадки верны. Но, скорее всего — вряд ли ;)
Все пункты достаточно легко проверялись. Я убрал все изменения и начал эксперементировать.
Я приостановил поток
Идея тут достаточно проста. Скорее всего — ошибка возникает из-за многопоточности.
Это было проверить легче всего, я поставил точку останова без NSLog'a. Код продолжал crash'иться, с теми же 100%.
Я доступился к переменной класса _width или Я добавил немного кода перед созданием вьюхи
Идея этих пунктов — в «особенностях» генерации кода, которые, чудесным образом, могли привести к непредвиденным последствиям.
Никакие танцы с бубном и дополнительные, случайным образом сгенерированные, строки кода с доступом к переменной _width, не давали результата. Приложение стабильно падало.
Я добавил NSLog
«Нет, ну Вы же несерьезно, правда?»
Оказалось серьезно. NSLog продолжал «лечить» крэш. Стабильно. Вне зависимости от передаваемых ему параметров. Обнаружились еще замечательные особенности. Приложение продолжало падать, даже если не использовать _width, _height как параметры. Без NSLog'а любое значение, передаваемое в -(id)initWithFrame:, приводило к падению приложения с той же ошибкой. Кроме всего прочего, оказалось, что совсем не обязательно ставить NSLog прямо перед созданием вьюхи. Его можно поставить в самом начале метода, где создавалась вьюха… или в методе, который вызвал этот метод… или даже в методе, который вызвал метод, который вызвал..., ну Вы поняли, в общем. Главное — чтобы перед созданием.
Success!
На этом все и закончилось. Проблема была «решена». Блокер устранен, и ничто не мешает спокойно тестировать приложение на симуляторе. А еще, было очень много работы, которую нужно было сделать, и мне пришлось на нее переключиться.
А решена ли проблема?
Этот вопрос мне не давал покоя несколько вечеров, пока я заканчивал основной проект. Решена ли проблема, или «лечилка» с NSLog'ом просто убрала симптомы какой-то более крупной проблемы, которая затаилась и ждет, пока проект уйдет в релиз? И тогда, когда все про нее забудут, и для ее фикса нужно будет ждать неделю сабмита в AppStore, она и проявится и начнет все ломать и крушить, только уже не на симуляторе?
Магия?
С одной стороны я понимал, что проблемы именно в моем коде. И, скорее всего, это не ошибка библиотеки UIKit. Знакомые программисты, так и говорили — ищи проблему в своем коде. И я с ними был согласен. Но как ее искать? Проект немаленький, попытки локализировать проблему в несколько строк — проваливаются. Хотелось все бросить, сказать «магия», и забить. И жить с ощущением магии в проекте. А то, ведь, если знаешь, как работает магия — теряется всякий интерес, все становится обыденно, согласно документации.
Все же, интерес к причине проблемы переосилил, и я стал копать. К этому времени мои идеи крутились вокруг желания понять: так что же все-таки такого интересного делает NSLog, и как он «лечит» падение программы? Вариантов было много как у меня, так и в локальном чате девелоперов. В конце концов сошлись на том, что наиболее вероятной причиной crash'а являются проблемы со stack'ом. Это передположение не объясняло причину стабильной работы на устройствах, но нужно было с чего-то начинать. Но до того, как я начал смотреть в сторону stack'а, я попробовал понять, где, все-таки возникает этот NaN?. Как раз в то время, знакомый darkproger активно рассказывал направо и налево, насколько крутая штука dtrace. И через несколько часов, с помощью этого инструмента, мне удалось немного сократить область поиска причины падения.
Dtrace magic
На тот момент, все что у меня было — это stacktrace до места падения. Проблема была где-то внутри него, ну или что-то приводило к тому, что все это благополучно падало.
#4 0x01d8b04a in -[CALayer setBounds:] () <---- NaN lives here
#5 0x02d1d714 in WebCore::TileGrid::updateHostLayerSize() ()
#6 0x02d1af26 in WebCore::TileCache::TileCache(WAKWindow*) ()
#7 0x02d52507 in -[WAKWindow initWithLayer:] ()
#8 0x002ee5e9 in -[UIWebTiledView initWithFrame:] ()
#9 0x001af9b5 in -[UIWebDocumentView initWithWebView:frame:] ()
#10 0x001af89e in -[UIWebDocumentView initSimpleHTMLDocumentWithStyle:frame:preferences:groupName:] ()
#11 0x0012cb6a in -[UITextView commonInitWithWebDocumentView:isDecoding:] ()
#12 0x0012bf0e in -[UITextView initWithFrame:] ()
С помощью относительно простого скрипта для dtrace удалось узнать, в каком месте появляется злополучный NaN. Оказалось, что параметры «теряются» аж под самый под конец:
QuartzCore`-[CALayer setBounds :] <------ (0, 0, NaN, height)
WebCore`WebCore::TileGrid::updateHostLayerSize()+0x140
WebCore`WebCore::TileCache::TileCache(WAKWindow*)+0x1c6
WebCore`-[WAKWindow initWithLayer:]+0xd7
UIKit`-[UIWebTiledView initWithFrame:]+0xec " <------ (0, 0, width, height)"
UIKit`-[UIWebDocumentView initWithWebView:frame:]+0xb5
UIKit`-[UIWebDocumentView initSimpleHTMLDocumentWithStyle:frame:preferences:groupName:]+0xfe
UIKit`-[UITextView commonInitWithWebDocumentView:isDecoding:]+0x198
UIKit`-[UITextView initWithFrame:]+0x70 " <------ (0, 0, width, height)"
Что делать? По всей видимости проблема не в нашем коде! С повышенным чувством собственной важности, я уже готовлюсь высылать баг-репорт в Apple. И лезу-таки смотреть, как там поживает stack.
Spoiler alert!
Если Вы все-таки собирались решить эту задачку сами, то самое время перестать читать эту статью ;)
Для тех, кто собирается разобраться в ней сам, и думает что проблемы заключаются в работе со стэком, или наоборот, думают, что проблемы вообще не связаны со стэком, небольшой спойлер
Stack troubles?
Как в Xcode'е посмотреть, что на текущий момент творится в стэке? Какие параметры передаются в функцию? Как они передаются и по каким правилам? И через стэк ли?
Это всего лишь малая часть вопросов, на которые на тот момент у меня не было ответов, но снова помогdarkproger(вообще Вова очень прилежно и терпеливо выслушивал, или делал вид, что выслушивал, все мои бредовые и не очень идеи причин и следствий ;), ткнув меня носом в весьма и весьма полезную документацию. А если быть конкретнее, то в конкретную ее часть. После беглого прочтения техноутов, мне удалось отобразить содержимое стэка.
Однако эти данные никак не помогли моему пониманию происходящего. Дело в том, что стэк был идентичен в обоих случаях. Никакой разницы. Все значения в памяти были абсолютно одинаковыми и стэковые регистры ссылались на одни и те же адреса памяти. Проверил несколько раз, перезапускал приложение, проверял адреса памяти ±. Все совпадало.
What's next?
Как я уже говорил, совпадали все значения в адресах памяти. Но что-то все-таки отличалось. Что-то было другим. Правда, поиск этого «чего-то» временно отошел на второй план — я нашел злополучный NaN.
Размещался он в одном из st регистров FPU процессора. Так как я не знал, что это за регистры, пришлось полезть в документацию от Intel'а. Согласно документации, группа регистров st0-st7 являются циклическим стэком для FPU, через который работают инструкции процессора, отвечающие за операции с плавающей запятой. Все стало проясняться. Кто-то кладет в FPU стэк значение NaN, а затем снимает его, как результат операции. Осталось найти только, кто это делает.
Около часа я убил на внезапно появившийся кусок магии, который объяснялся простым «читайте документацию внимательно». Проявлялась эта магия следующим образом. «Неправильно» работала инструкция fstp (страница 190). Команда должна выполнять следующие операции: Взять текущее значение с вершины FPU стэка st0, записать его по указанному адресу (в моем случае — в $ebp-0x64), и вытолкнуть значение с FP стэка.
Вот только после выполнения этой инструкции, по адресу $ebp+0x64 оказывался 0, вместо нужного мне значения 320.
Перед выполнение команды fstp
После выполнения команды fstp
Внимательные знатоки, наверное, уже видят проблему. Те, кто хотят сами убедиться в таком поведении — можете скачать тестовый проект, и поставить точку останова на функцию WebCore::TileGrid::updateHostLayerSize (). Внутри нее достаточно легко найти нужный кусок. Кому просто интересна причина моего провтыка — смело раскрывайте спойлер.
Stack overflow?
После того, как я разобрался с fstp, и fld. Я снова стал искать различия. И так как я уже точно знал, что причина не связана со стэком, то я сконцентрировался на значениях регистров процессора. И здесь нашлись отличия. И даже стало понятно, откуда берется NaN. Сначала я глянул на регистр $ftag, значение которого сразу сказало мне о наличи чего-то нехорошего в регистрах FPU стэка(стр 182).
Это можно, было, конечно, наблюдать, просто глянув в $st0-$st7, но $ftag позволяет узнать, в каком состоянии на данный момент находятся регистры — какие используются, какие заняты, а какие — пустые. В примере видно, что все регистры заняты (valid), и только в одном из них что-то особенное.
Но окончательно все вопросы относительно магии развеялись, когда я увидел значения регистра $fstat(x87 FPU Status Register, стр 178).
Stack overflow
Stack overflow в FPU регистрах процессора. На самом деле stack overflow сам по себе не вызывает никаких исключений, и всего лишь выставляет флаг в контрольном слове, о том, что произошло исключение.
If the invalid-operation exception is masked, the x87 FPU returns the floating point, integer, or packed decimal integer indefinite value to the destination operand, depending on the instruction being executed. This value over- writes the destination register or memory location specified by the instruction.
Но, если использовать значение регистра с состоянием invalid, мы получим NaN, который, оказавшись в памяти, приходит как параметр при создании CALayer'а.
Итак, на самый нижний уровень проблемы я спустился. Я точно знал откуда появляются магические NaNы, в программе, и о stack overflow в стэковых регистрах FPU. Вот только ответа, где и когда это происходит у меня не было. В голове снова родилась идея, что это лажает UIKit, но без доказательств претензии не предъявишь. С другой стороны у меня совсем не было идей, каким образом код может вызывать FPU Stack Overflow(о существовании которого я узнал в тот день).
Виновник
За относительно небольшое время все-таки была локализована функция, которая была виновником всего происходящего. Вот он, виновник всего происходящего!
// ACLabel : UILabel
- (CGFloat)resizeToContents {
CGSize size = [self.text sizeWithFont:self.font
forWidth:self.frame.size.width
lineBreakMode:self.lineBreakMode];
CGRect oldFrame = self.frame;
oldFrame.size.height = size.height;
self.frame = oldFrame;
return size.height;
}
Пытаетесь найти что-то страшное? Пытайтесь. Я тоже пытался. Долго и нудно. Переписывал метод, переименовывал, делал категорией. И все напрасно. Именно этот метод оставлял мусор в FPU Stack'е. Причем, магия приобрела новую форму. Один и тот же метод оставлял мусор в стэке через раз. То есть «иногда» метод нормально «снимал» значение с вершины стэка, а иногда он про него совсем забывал, и игнорировал, тем самым приближая крэш. Так что же с этим кодом не так?
On systems based on the IA-32 architectures, when an application calls a function that returns a floating-point value, the returned floating-point value is supposed to be on the top of the floating-point stack. If the return value is not used, the compiler must pop the value off of the floating-point stack in order to keep the floating-point stack in the correct state.
«Как же мне от этого полегчало!» (сарказм). Теперь вектор вины плавно сместился с UIKit'а снова на компилятор. Ведь это он должен снять значение со FPU стэка! Должен, а не делает. Вернее делает… но не всегда. Так когда же?
За шаг до победы
А я Вам отвечу на этот вопрос. Но для начала у меня небольшой вопрос: «Идентичны ли строки, приведенные в примере?»
// Пример безобидного вызова метода
// Вариант №1
[obj someMethod];
// Вариант №2
[obj perfromSelector:@selector(someMethod)];
Простой такой вопрос. Его даже на собеседованиях иногда задают. И даже сходу не скажешь, что они могут работать по-разному. Ведь, по сути, это одно и то же, только вид сбоку. Правда, пример сильно упрощен в виду отсутствия факта о том, что возвращают данные методы. Подразумевается, что возвращают они void. А если бы методы возвращали id, или int или float. Поменялось бы что-нибудь?
Пока Вы думаете над ответом на вопрос, я дам небольшую выдержку из документации:
The performSelector: method is equivalent to sending an aSelector message directly to the receiver. For example, all three of the following messages do the same thing:
id myClone = [anObject copy];
id myClone = [anObject performSelector:@selector(copy)];
id myClone = [anObject performSelector:sel_getUid("copy")];
. For methods that return anything other than an object, use NSInvocation.
Когда зацепка выделена жирным шрифтом, то, конечно, ее замечают. Документация довольно понятно намекает, что если вдруг метод должен возвращать что-то кроме id, нам нужно использовать NSInvocation. Но я скажу, что даже если возвращать не объект, то все работает. Работало, во всяком случае. До того злосчастного дня.
Profit
Наверное, многие уже догадались, что здесь происходит. Все достаточно просто (особенно, после прочтения статьи, ну или двух с половиной дней игр с dtrace'ом, debugger'ом, копанием в документации и прочим).
- Компилятор, видит метод, который должен вернуть float, и исправно генерирует код, который после вызова метода, снимает возвращенное значение со стэка FPU.
- В случае с использованием метода performSelector, компилятор не знает, что возвращает метод, поэтому надеется на добросовестность программиста — считает, что метод будет возвращать id.
- В случае, если в коде используется performSelector для метода, который должен вернуть float (даже если не использовать возвращенный результат), то компилятор не знает о том, что надо снимать возвращенное значение со стэка FPU. Так что, при каждом вызове return-float-метода через performSelector, «забивается» один из регистров стэка FPU.
- После восьми таких вызовов (8 st-регистров), процессор поставит флаг о том, что стэк переполнен, и некоторые обычные операции с плавающей запятой начинают возвращать NaN в качестве результата. Это, в свою очередь, приводит к чему угодно. Вплоть до того, что за Вашей спиной может пробежать динозавр.
Мораль: Читайте документацию внимательно. Если что-то работает вопреки документации — не особо найдейтесь на то, что это не повлечет за собой большие проблемы.
NSLog
«Эй, эй, так что же там с NSLog'ом? Почему NSLog „лечит“ эту проблему?»
NSLog при своей работе использует операции с плавающей запятой. Причем, методом тыка было установлено, что для его работы нужно два регистра в стэке FPU. А стэк FPU, в случае полного заполнения, ставит соотвествующий флаг переполнения. А при операции, которая снимает значение со стэка, маркирует один из регистров стєка как «свободный для использования».
// Tag word (state of st0 - st7 registers)
// 00 - Used
// 10 - Invalid
// 11 - Unused
// before NSLog
st0 st1 st2 st3 st4 st5 st6 st7
10 00 00 00 00 00 00 00
// After NSLog
st0 st1 st2 st3 st4 st5 st6 st7
11 11 00 00 00 00 00 00
Вот таким образом с регистра st0 исчезает состояние Invalid, из-за этого никто при попытке забрать с него значение не получает NaN, и не передает его дальше как параметр к UITextView.
Так что, NSLog не лечит проблему. Он дает ей пожить еще немного, откладывая смерть приложения до времени под кодовым именем «Внезапно».
Вот такая вот «магия». Теперь можно смело писать в Вашем резюме строчку
Лечу Crash'и NSLog'ами. Недорого. Многолетний опыт. 100% гарантия.
Надеюсь было не только интересно, но и в некоторых местах — познавательно.
P.S. Еще раз спасибо и за то, что помогали и выслушивали мой поток мыслей.
Автор: Kilew
