Что такое стектрейс ошибки

Практика показала, что хардкорные расшифровки с наших докладов хорошо заходят, так что мы решили продолжать. Сегодня у нас в меню смесь из подходов к поиску и анализу ошибок и крэшей, приправленная щепоткой полезных инструментов, подготовленная на основе доклада Андрея Паньгина aka apangin из Одноклассников на одном из JUG’ов (это была допиленная версия его доклада с JPoint 2016). В без семи минут двухчасовом докладе Андрей подробно рассказывает о стек-трейсах и хип-дампах.

Пост получился просто огромный, так что мы разбили его на две части. Сейчас вы читаете первую часть, вторая часть лежит здесь.

Сегодня я буду рассказывать про стек-трейсы и хип-дампы — тему, с одной стороны, известную каждому, с другой — позволяющую постоянно открывать что-то новое (я даже багу нашел в JVM, пока готовил эту тему).

Когда я делал тренировочный прогон этого доклада у нас в офисе, один из коллег спросил: «Все это очень интересно, но на практике это кому-нибудь вообще полезно?» После этого разговора первым слайдом в свою презентацию я добавил страницу с вопросами по теме на StackOverflow. Так что это актуально.

Сам я работаю ведущим программистом в Одноклассниках. И так сложилось, что зачастую мне приходится работать с внутренностями Java — тюнить ее, искать баги, дергать что-то через системные классы (порой не совсем легальными способами). Оттуда я и почерпнул большую часть информации, которую сегодня хотел вам представить. Конечно, в этом мне очень помог мой предыдущий опыт: я 6 лет работал в Sun Microsystems, занимался непосредственно разработкой виртуальной Java-машины. Так что теперь я знаю эту тему как изнутри JVM, так и со стороны пользователя-разработчика.

Стек-трейсы

Стек-трейсы exception

Когда начинающий разработчик пишет свой «Hello world!», у него выскакивает эксепшн и ему демонстрируется стек-трейс, где произошла эта ошибка. Так что какие-то представления о стек-трейсах есть у большинства.

Перейдем сразу к примерам.

Я написал небольшую программку, которая в цикле 100 миллионов раз производит такой эксперимент: создает массив из 10 случайных элементов типа long и проверяет, сортированный он получился или нет.

package demo1;

import java.util.concurrent.ThreadLocalRandom;

public class ProbabilityExperiment {

    private static boolean isSorted(long[] array) {
        for (int i = 0; i < array.length; i++) {
            if (array[i] > array[i + 1]) {
                return false;
            }
        }
        return true;
    }

    public void run(int experiments, int length) {
        int sorted = 0;

        for (int i = 0; i < experiments; i++) {
            try {
                long[] array = ThreadLocalRandom.current().longs(length).toArray();
                if (isSorted(array)) {
                    sorted++;
                }
            } catch (Exception e) {
                e.printStackTrace();
            }
        }

        System.out.printf("%d of %d arrays are sortedn", sorted, experiments);
    }

    public static void main(String[] args) {
        new ProbabilityExperiment().run(100_000_000, 10);
    }
}

По сути он считает вероятность получения сортированного массива, которая приблизительно равна 1/n!. Как это часто бывает, в программке ошиблись на единичку:

for (int i = 0; i < array.length; i++)

Что произойдет? Эксепшн, выход за пределы массива.
Давайте разбираться, в чем дело. У нас в консоль выводится:

java.lang.ArrayIndexOutOfBoundsException

но стек-трейсов никаких нет. Куда делись?

В HotSpot JVM есть такая оптимизация: у эксепшенов, которые кидает сама JVM из горячего кода, а в данном случае код у нас горячий — 100 миллионов раз дергается, стек-трейсы не генерируются.
Это можно исправить с помощью специального ключика:

-XX:-OmitStackTraceInFastThrow

Теперь попробуем запустить пример. Получаем все то же самое, только все стек-трейсы на месте.

Подобная оптимизация работает для всех неявных эксепшенов, которые бросает JVM: выход за границы массива, разыменование нулевого указателя и т.д.

Раз оптимизацию придумали, значит она зачем-то нужна? Понятно, что программисту удобнее, когда стек-трейсы есть.

Давайте измерим, сколько «стоит» у нас создание эксепшена (сравним с каким-нибудь простым Java-объектом, вроде Date).

@Benchmark
public Object date() {
    return new Date();
}

@Benchmark
public Object exception() {
    return new Exception();
}

С помощью JMH напишем простенькую бенчмарку и измерим, сколько наносекунд занимают обе операции.

Оказывается, создать эксепшн в 150 раз дороже, чем обычный объект.
И тут не все так просто. Для виртуальной машины эксепшн не отличается от любого другого объекта, но разгадка кроется в том, что практически все конструкторы эксепшн так или иначе сводятся к вызову метода fillInStackTrace, который заполняет стек-трейс этого эксепшена. Именно заполнение стек-трейса отнимает время.

Этот метод в свою очередь нативный, падает в VM рантайм и там гуляет по стеку, собирает все фреймы.

Метод fillInStackTrace публичный, не final. Давайте его просто переопределим:

@Benchmark
public Object exceptionNoStackTrace() {
    return new Exception() {
        @Override
        public Throwable fillInStackTrace() {
            return this;
        }
    };
}

Теперь создание обычного объекта и эксепшена без стек-трейса отнимают одинаковое время.

Есть и другой способ создать эксепшн без стек-трейса. Начиная с Java 7, у Throwable и у Exception есть protected-конструктор с дополнительным параметром writableStackTrace:

protected Exception(String message, Throwable cause,
                    boolean enableSuppression,
                    boolean writableStackTrace);

Если туда передать false, то стек-трейс генерироваться не будет, и создание эксепшена будет очень быстрым.

Зачем нужны эксепшены без стек-трейсов? К примеру, если эксепшн используется в коде в качестве способа быстро выбраться из цикла. Конечно, лучше так не делать, но бывают случаи, когда это действительно дает прирост производительности.

А сколько стоит бросить эксепшн?

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

@Param("1", "2", "10", "100", "1000"})
int depth;

@Benchmark
public Object throwCatch() {
    try {
        return recursive(depth);
    } catch (Exception e) {
        return e;
    }
}

Вот, что дают измерения:

Т.е. если у нас глубина небольшая (эксепшн ловится в том же фрейме или фреймом выше — глубина 0 или 1), эксепшн ничего не стоит. Но как только глубина стека становится большой, затраты совсем другого порядка. При этом наблюдается четкая линейная зависимость: «стоимость» исключения почти линейно зависит от глубины стека.

Дорого стоит не только получение стек-трейса, но и дальнейшие манипуляции — распечатка, отправка по сети, запись, — все, для чего используется метод getStackTrace, который переводит сохраненный стек-трейс в объекты Java.

@Benchmark
public Object fillInStackTrace() {
    return new Exception();
}

@Benchmark
public Object getStackTrace() {
    return new Exception().getStackTrace();
}

Видно, что преобразование стек-трейса в 10 раз «дороже» его получения:

Почему это происходит?

Вот метод getStackTrace в исходниках JDK:

Сначала через вызов нативного метода мы узнаем глубину стека, потом в цикле до этой глубины вызываем нативный метод, чтобы получить очередной фрейм и сконвертировать его в объект StackTraceElement (это нормальный объект Java с кучей полей). Мало того, что это долго, процедура отнимает много памяти.

Более того, в Java 9 этот объект дополнен новыми полями (в связи с известным проектом модуляризации) — теперь каждому фрейму приписывается отметка о том, из какого он модуля.

Привет тем, кто парсит эксепшены с помощью регулярных выражений. Готовьтесь к сюрпризам в Java 9 — появятся еще и модули.

Давайте подведем итоги

• создание самого объекта эксепшн — дешевое;
• занимает время получение его стек-трейса;
• еще дороже — преобразование этого внутреннего стек-трейса в Java-объект в StackTraceElement. Сложность этого дела прямо пропорциональна глубине стека.
• бросание эксепшн — быстрое, оно почти ничего не стоит (почти как безусловный переход),
• но только если эксепшн ловится в том же фрейме. Тут надо дополнить еще, что JIT у нас умеет инлайнить методы, поэтому один скомпилированный фрейм может в себя включать несколько Java-методов, заинлайниных друг в друга. Но если эксепшн ловится где-то глубже по стеку, его дороговизна пропорциональна глубине стека.

Пара советов:

• отключайте на продакшене оптимизацию, возможно, это сэкономит много времени на отладке:

  -XX:-OmitStackTraceInFastThrow

• не используйте эксепшены для управления потоком программы; это считается не очень хорошей практикой;
• но если вы все-таки прибегаете к этому способу, позаботьтесь о том, чтобы эксепшены были быстрыми и лишний раз не создавали стек-трейсы.

Стек-трейсы в тред дампах

Чтобы узнать, что же делает программа, проще всего взять тред дамп, например, утилитой jstack.

Фрагменты вывода этой утилиты:

Что здесь видно? Какие есть потоки, в каком они состоянии и их текущий стек.

Более того, если потоки захватили какие-то локи, ожидают входа в synchronized-секцию или взятия ReentrantLock, это также будет отражено в стек-трейсе.

Порой полезным оказывается малоизвестный идентификатор:

Он напрямую связан с ID потока в операционной системе. Например, если вы смотрите программой top в Linux, какие треды у вас больше всего едят CPU, pid потока — это и есть тот самый nid, который демонстрируется в тред дампе. Можно тут же найти, какому Java-потоку он соответствует.

В случае с мониторами (с synchronized-объектами) прямо в тред дампе будет написано, какой тред и какие мониторы держит, кто пытается их захватить.

В случае с ReentrantLock это, к сожалению, не так. Здесь видно, как Thread 1 пытается захватить некий ReentrantLock, но при этом не видно, кто этот лок держит. На этот случай в VM есть опция:

-XX:+PrintConcurrentLocks

Если мы запустим то же самое с PrintConcurrentLocks, в тред дампе увидим и ReentrantLock.

Здесь указан тот самый id лока. Видно, что его захватил Thread 2.

Если опция такая хорошая, почему бы ее не сделать «по умолчанию»?

Она тоже чего-то стоит. Чтобы напечатать информацию о том, какой поток какие ReentrantLock’и держит, JVM пробегает весь Java heap, ищет там все ReentrantLock’и, сопоставляет их с тредами и только потом выводит эту информацию (у треда нет информации о том, какие локи он захватил; информация есть только в обратную сторону — какой лок связан с каким тредом).

В указанном примере по названиям потоков (Thread 1 / Thread 2) непонятно, к чему они относятся. Мой совет из практики: если у вас происходит какая-то длинная операция, например, сервер обрабатывает клиентские запросы или, наоборот, клиент ходит к нескольким серверам, выставляйте треду понятное имя (как в случае ниже — прямо IP того сервера, к которому клиент сейчас идет). И тогда в дампе потока сразу будет видно, ответа от какого сервера он сейчас ждет.

Хватит теории. Давайте опять к практике. Этот пример я уже не раз приводил.

package demo2;

import java.util.stream.IntStream;

public class ParallelSum {
    static int SUM = IntStream.range(0, 100).parallel().reduce(0, (x, y) -> x + y);

    public static void main(String[] args) {
        System.out.println(SUM);
    }
}

Запускаем программку 3 раза подряд. 2 раза она выводит сумму чисел от 0 до 100 (не включая 100), третий — не хочет. Давайте смотреть тред дампы:

Первый поток оказывается RUNNABLE, выполняет наш reduce. Но смотрите, какой интересный момент: Thread.State вроде как RUNNABLE, но при этом написано, что поток in Object.wait().

Мне тоже это было не понятно. Я даже хотел сообщить о баге, но оказывается, такая бага заведена много лет назад и закрыта с формулировкой: «not an issue, will not fix».
В этой программке действительно есть дедлок. Его причина — инициализация классов.

Выражение выполняется в статическом инициализаторе класса ParallelSum:

static int SUM = IntStream.range(0, 100).parallel().reduce(0, (x, y) -> x + y);

Но поскольку стрим параллельный, исполнение происходит в отдельных потоках ForkJoinPool, из которых вызывается тело лямбды:

(x, y) -> x + y

Код лямбды записан Java-компилятором прямо в классе ParallelSum в виде приватного метода. Получается, что из ForkJoinPool мы пытаемся обратиться к классу ParallelSum, который в данный момент находится на этапе инициализации. Поэтому потоки начинают ждать, когда же закончится инициализация класса, а она не может закончиться, поскольку ожидает вычисления этой самой свертки. Дедлок.

Почему вначале сумма считалась? Просто повезло. У нас небольшое количество элементов суммируется, и иногда все исполняется в одном потоке (другой поток просто не успевает).

Но почему же тогда поток в стек-трейсе RUNNABLE? Если почитать документацию к Thread.State, станет понятно, что никакого другого состояния здесь быть не может. Не может быть состояния BLOCKED, поскольку поток не заблокирован на Java-мониторе, нет никакой synchronized-секции, и не может быть состояния WAITING, потому что здесь нет никаких вызовов Object.wait(). Синхронизация происходит на внутреннем объекте виртуальной машины, который, вообще говоря, даже не обязан быть Java-объектом.

Стек-трейс при логировании

Представьте себе ситуацию: в куче мест в нашем приложении что-то логируется. Было бы полезно узнать, из какого места появилась та или иная строчка.

В Java нет препроцессора, поэтому нет возможности использовать макросы __FILE__, __LINE__, как в С (эти макросы еще на этапе компиляции преобразуются в текущее имя файла и строку). Поэтому других способов дополнить вывод именем файла и номером строки кода, откуда это было напечатано, кроме как через стек-трейсы, нет.

public static String getLocation() {
    StackTraceElement s = new Exception().getStackTrace()[2];
	return s.getFileName() + ':' + s.getLineNumber();
}

Генерим эксепшн, у него получаем стек-трейс, берем в данном случае второй фрейм (нулевой — это метод getLocation, а первый — вызывает метод warning).

Как мы знаем, получение стек-трейса и, тем более, преобразование его в стек-трейс элементы очень дорого. А нам нужен один фрейм. Можно ли как-то проще сделать (без эксепшн)?

Помимо getStackTrace у исключения есть метод getStackTrace объекта Thread.

Thread.current().getStackTrace()

Будет ли так быстрее?

Нет. JVM никакой магии не делает, здесь все будет работать через тот же эксепшн с точно таким же стек-трейсом.

Но хитрый способ все-таки есть:

public static String getLocation() {
    StackTraceElement s = sun.misc.SharedSecrets.getJavaLangAccess()
            .getStackTraceElement(new Exception(), 2);

    return s.getFileName() + ':' + s.getLineNumber();
}

Я люблю всякие приватные штуки: Unsafe, SharedSecrets и т.д.

Есть аксессор, который позволяет получить StackTraceElement конкретного фрейма (без необходимости преобразовывать весь стек-трейс в Java-объекты). Это будет работать быстрее. Но есть плохая новость: в Java 9 это работать не будет. Там проделана большая работа по рефакторингу всего, что связано со стек-трейсами, и таких методов там теперь просто нет.

Конструкция, позволяющая получить какой-то один фрейм, может быть полезна в так называемых Caller-sensitive методах — методах, чей результат может зависеть от того, кто их вызывает. В прикладных программах с такими методами приходится сталкиваться нечасто, но в самой JDK подобных примеров немало:

В зависимости от того, кто вызывает Class.forName, поиск класса будет осуществляться в соответствующем класс-лоадере (того класса, который вызвал этот метод); аналогично — с получением ResourceBundle и загрузкой библиотеки System.loadLibrary. Также информация о том, кто вызывает, полезна при использовании различных методов, которые проверяют пермиссии (а имеет ли данный код право вызывать этот метод). На этот случай в «секретном» API предусмотрен метод getCallerClass, который на самом деле является JVM-интринсиком и вообще почти ничего не стоит.

sun.reflect.Reflection.getCallerClass

Как уже много раз говорилось, приватный API — это зло, использовать которое крайне не рекомендуется (сами рискуете нарваться на проблемы, подобные тем, что ранее вызвал Unsafe). Поэтому разработчики JDK задумались над тем, что раз этим пользуются, нужна легальная альтернатива — новый API для обхода потоков. Основные требования к этому API:

• чтобы можно было обойти только часть фреймов (если нам нужно буквально несколько верхних фреймов);
• возможность фильтровать фреймы (не показывать ненужные фреймы, относящиеся к фреймворку или системным классам);
• чтобы эти фреймы конструировались ленивым образом (lazy) — если нам не нужно получать информацию о том, с каким файлом он связан, эта информация преждевременно не извлекается;
• как в случае с getCallerClass — нам нужно не имя класса, а сам инстанс java.lang.Class.

Известно, что в публичном релизе Java 9 будет java.lang.StackWalker.
Получить его экземпляр очень просто — методом getInstance. У него есть несколько вариантов — дефолтный StackWalker или незначительно конфигурируемый опциями:

• опция RETAIN_CLASS_REFERENCE означает, что вам нужны не имена классов, а именно инстансы;
• прочие опции позволяют показать в стек-трейсе фреймы, относящиеся к системным классам и классам рефлекшн (по умолчанию они не будут показаны в стек-трейсе).

Также для оптимизации можно задавать примерную глубину, которая необходима (чтобы JVM могла оптимизировать получение стек-фреймов в batch).

Простейший пример, как этим пользоваться:

StackWalker sw = StackWalker.getInstance();
sw.forEach(System.out::println);

Берем StackWalker и вызываем метод forEach, чтобы он обошел все фреймы. В результате получим такой простой стек-трейс:

То же самое с опцией SHOW_REFLECT_FRAMES:

StackWalker sw = StackWalker.getInstance(StackWalker.Option.SHOW_REFLECT_FRAMES);
sw.forEach(System.out::println);

В этом случае добавятся методы, относящиеся к вызову через рефлекшн:

Если добавить опцию SHOW_HIDDEN_FRAMES (она, кстати, включает в себя SHOW_REFLECT_FRAMES, т.е. рефлекшн-фреймы тоже будут показаны):

StackWalker sw = StackWalker.getInstance(StackWalker.Option.SHOW_HIDDEN_FRAMES);
sw.forEach(System.out::println);

В стек-трейсе появятся методы динамически-сгенерированных классов лямбд:

А теперь самый главный метод, который есть в StackWalker API — метод walk с такой хитрой непонятной сигнатурой с кучей дженериков:

public <T> T walk(Function<? super Stream<StackFrame>, ? extends T> function)

Метод walk принимает функцию от стек-фрейма.

Его работу проще показать на примере.

Несмотря на то, что все это выглядит страшно, как этим пользоваться — очевидно. В функцию передается стрим, а уже над стримом можно проводить все привычные операции. К примеру, вот так выглядел бы метод getCallerFrame, который достает только второй фрейм: пропускаются первые 2, потом вызывается findFirst:

public static StackFrame getCallerFrame() {
    return StackWalker.getInstance()
            .walk(stream -> stream.skip(2).findFirst())
            .orElseThrow(NoSuchElementException::new);
}

Метод walk возвращает тот результат, который возвращает эта функция стрима. Все просто.
Для данного конкретного случая (когда нужно получить просто Caller класс) есть специальный shortcut метод:

return StackWalker.getInstance(RETAIN_CLASS_REFERENCE).getCallerClass();

Еще один пример посложнее.

Обходим все фреймы, оставляем только те, которые относятся к пакету org.apache, и выводим первые 10 в список.

StackWalker sw = StackWalker.getInstance();

List<StackFrame> frames = sw.walk(stream ->
        stream.filter(sf -> sf.getClassName().startsWith("org.apache."))
              .limit(10)
              .collect(Collectors.toList()));

Интересный вопрос: зачем такая длинная сигнатура с кучей дженериков? Почему бы просто не сделать у StackWalker метод, который возвращает стрим?

public Stream<StackFrame> stream();

Если дать API, который возвращает стрим, у JDK теряется контроль над тем, что дальше над этим стримом делают. Можно дальше этот стрим положить куда-то, отдать в другой поток, попробовать его использовать через 2 часа после получения (тот стек, который мы пытались обойти, давно потерян, а тред может быть давно убит). Таким образом будет невозможно обеспечить «ленивость» Stack Walker API.

Основной поинт Stack Walker API: пока вы находитесь внутри walk, у вас зафиксировано состояние стека, поэтому все операции на этом стеке можно делать lazy.

На десерт еще немного интересного.

Как всегда, разработчики JDK прячут от нас кучу сокровищ. И помимо обычных стек-фреймов они для каких-то своих нужд сделали живые стек-фреймы, которые отличаются от обычных тем, что имеют дополнительные методы, позволяющие не только получить информацию о методе и классе, но еще и о локальных переменных, захваченных мониторах и значениях экспрешн-стека данного стек-фрейма.

/* package-private */
interface LiveStackFrame extends StackFrame {

    public Object[] getMonitors();
    public Object[] getLocals();
    public Object[] getStack();
    public static StackWalker getStackWalker();
}

Защита здесь не ахти какая: класс просто сделали непубличным. Но кто же нам мешает взять рефлекшн и попробовать его? (Примечание: в актуальных сборках JDK 9 доступ к непубличному API через рефлекшн запрещён. Чтобы его разрешить, необходимо добавить опцию JVM --add-opens=java.base/java.lang=ALL-UNNAMED)

Пробуем на таком примере. Есть программа, которая рекурсивным методом ищет выход из лабиринта. У нас есть квадратное поле size x size. Есть метод visit с текущими координатами. Мы пытаемся из текущей клетки пойти влево / вправо / вверх / вниз (если они не заняты). Если дошли из правой-нижней клетки в левую-верхнюю, считаем, что нашли выход и распечатываем стек.

package demo3;

import java.util.Random;

public class Labyrinth {
    static final byte FREE = 0;
    static final byte OCCUPIED = 1;
    static final byte VISITED = 2;

    private final byte[][] field;

    public Labyrinth(int size) {
        Random random = new Random(0);
        field = new byte[size][size];

        for (int x = 0; x < size; x++) {
            for (int y = 0; y < size; y++) {
                if (random.nextInt(10) > 7) {
                    field[x][y] = OCCUPIED;
                }
            }
        }

        field[0][0] = field[size - 1][size - 1] = FREE;
    }

    public int size() {
        return field.length;
    }

    public boolean visit(int x, int y) {
        if (x == 0 && y == 0) {
            StackTrace.dump();
            return true;
        }

        if (x < 0 || x >= size() || y < 0 || y >= size() || field[x][y] != FREE) {
            return false;
        }

        field[x][y] = VISITED;
        return visit(x - 1, y) || visit(x, y - 1) || visit(x + 1, y) || visit(x, y + 1);
    }

    public String toString() {
        return "Labyrinth";
    }

    public static void main(String[] args) {
        Labyrinth lab = new Labyrinth(10);
        boolean exitFound = lab.visit(9, 9);
        System.out.println(exitFound);
    }
}

Запускаем:

Если я делаю обычный dumpStack, который был еще в Java 8, получаем обычный стек-трейс, из которого ничего не понятно. Очевидно — рекурсивный метод сам себя вызывает, но интересно, на каком шаге (и с какими значениями координат) вызывается каждый метод.

Заменим стандартный dumpStack на наш StackTrace.dump, который через рефлекшн использует live стек-фреймы:

package demo3;

import java.lang.reflect.Method;
import java.util.Arrays;

public class StackTrace {

    private static Object invoke(String methodName, Object instance) {
        try {
            Class<?> liveStackFrame = Class.forName("java.lang.LiveStackFrame");
            Method m = liveStackFrame.getMethod(methodName);
            m.setAccessible(true);
            return m.invoke(instance);
        } catch (ReflectiveOperationException e) {
            throw new AssertionError("Should not happen", e);
        }
    }

    public static void dump() {
        StackWalker sw = (StackWalker) invoke("getStackWalker", null);
        sw.forEach(frame -> {
            Object[] locals = (Object[]) invoke("getLocals", frame);
            System.out.println(" at " + frame + "  " + Arrays.toString(locals));
        });
    }
}

В первую очередь надо получить соответствующий StackWalker, вызвав метод getStackWalker. Все фреймы, которые будут передаваться в getStackWalker, на самом деле будут экземплярами лайв стек-фрейма, у которого есть дополнительные методы, в частности, getLocals для получения локальных переменных.

Запускаем. Получаем то же самое, но у нас отображается весь путь из лабиринта в виде значений локальных переменных:

На этом мы заканчиваем первую часть поста. Вторая часть здесь.

Простыми словами, трассировка стека – это список методов, которые были вызваны до момента, когда в приложении произошло исключение.

Простой случай

В указанном примере мы можем точно определить, когда именно произошло исключение. Рассмотрим трассировку стека:

Exception in thread "main" java.lang.NullPointerException
       at com.example.myproject.Book.getTitle(Book.java:16)
       at com.example.myproject.Author.getBookTitles(Author.java:25)
       at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

Это пример очень простой трассировки. Если пойти по списку строк вида «at…» с самого начала, мы можем понять, где произошла ошибка. Мы смотрим на верхний вызов функции. В нашем случае, это:

at com.example.myproject.Book.getTitle(Book.java:16)

Для отладки этого фрагмента открываем Book.java и смотрим, что находится на строке 16:

public String getTitle() {
    System.out.println(title.toString()); <-- line 16
    return title;
}

Это означает то, что в приведенном фрагменте кода какая-то переменная (вероятно, title) имеет значение null.

Пример цепочки исключений

Иногда приложения перехватывают исключение и выбрасывают его в виде другого исключения. Обычно это выглядит так:

try {
    ....
} catch (NullPointerException e) {
    throw new IllegalStateException("A book has a null property", e)
}

Трассировка в этом случае может иметь следующий вид:

Exception in thread "main" java.lang.IllegalStateException: A book has a null property
       at com.example.myproject.Author.getBookIds(Author.java:38)
       at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
       at com.example.myproject.Book.getId(Book.java:22)
       at com.example.myproject.Author.getBookIds(Author.java:35)
       ... 1 more

В этом случае разница состоит в атрибуте «Caused by» («Чем вызвано»). Иногда исключения могут иметь несколько секций «Caused by». Обычно необходимо найти исходную причину, которой оказывается в самой последней (нижней) секции «Caused by» трассировки. В нашем случае, это:

Caused by: java.lang.NullPointerException <-- root cause
       at com.example.myproject.Book.getId(Book.java:22) <-- important line

Аналогично, при подобном исключении необходимо обратиться к строке 22 книги Book.java, чтобы узнать, что вызвало данное исключение – NullPointerException.

Еще один пугающий пример с библиотечным кодом

Как правило, трассировка имеет гораздо более сложный вид, чем в рассмотренных выше случаях. Приведу пример (длинная трассировка, демонстрирующая несколько уровней цепочек исключений):

javax.servlet.ServletException: Произошло что–то ужасное
   at com.example.myproject.OpenSessionInViewFilter.doFilter(OpenSessionInViewFilter.java:60)
   at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
   at com.example.myproject.ExceptionHandlerFilter.doFilter(ExceptionHandlerFilter.java:28)
   at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
   at com.example.myproject.OutputBufferFilter.doFilter(OutputBufferFilter.java:33)
   at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
   at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
   at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
   at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
   at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
   at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)
   at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
   at org.mortbay.jetty.Server.handle(Server.java:326)
   at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
   at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:943)
   at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756)
   at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
   at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
   at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.java:228)
   at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
Caused by: com.example.myproject.MyProjectServletException
   at com.example.myproject.MyServlet.doPost(MyServlet.java:169)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
   at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
   at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
   at com.example.myproject.OpenSessionInViewFilter.doFilter(OpenSessionInViewFilter.java:30)
   ... 27 more
Caused by: org.hibernate.exception.ConstraintViolationException: could not insert: [com.example.myproject.MyEntity]
   at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:96)
   at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
   at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert(AbstractSelectingDelegate.java:64)
   at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2329)
   at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2822)
   at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:71)
   at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:268)
   at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:321)
   at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:204)
   at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:130)
   at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:210)
   at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:56)
   at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:195)
   at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:50)
   at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93)
   at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:705)
   at org.hibernate.impl.SessionImpl.save(SessionImpl.java:693)
   at org.hibernate.impl.SessionImpl.save(SessionImpl.java:689)
   at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
   at java.lang.reflect.Method.invoke(Method.java:597)
   at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:344)
   at $Proxy19.save(Unknown Source)
   at com.example.myproject.MyEntityService.save(MyEntityService.java:59) <-- relevant call (see notes below)
   at com.example.myproject.MyServlet.doPost(MyServlet.java:164)
   ... 32 more
Caused by: java.sql.SQLException: Violation of unique constraint MY_ENTITY_UK_1: duplicate value(s) for column(s) MY_COLUMN in statement [...]
   at org.hsqldb.jdbc.Util.throwError(Unknown Source)
   at org.hsqldb.jdbc.jdbcPreparedStatement.executeUpdate(Unknown Source)
   at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:105)
   at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert(AbstractSelectingDelegate.java:57)
   ... 54 more

В этом примере приведен далеко не полный стек вызовов. Что вызывает здесь наибольший интерес, так это поиск функций из нашего кода – из пакета com.example.myproject. В предыдущем примере мы сначала хотели отыскать «первопричину», а именно:

Caused by: java.sql.SQLException

Однако все вызовы методов в данном случае относятся к библиотечному коду. Поэтому мы перейдем к предыдущей секции «Caused by» и найдем первый вызов метода из нашего кода, а именно:

at com.example.myproject.MyEntityService.save(MyEntityService.java:59)

Аналогично предыдущим примерам, необходимо обратить внимание на MyEntityService.java, строка 59: именно здесь появилась ошибка (в данном случае ситуация довольно очевидная, так как об ошибке сообщает SQLException, но в этом вопросе мы рассматриваем именно процедуру отладки с помощью трассировки).

_{Перевод ответа: «What is a stack trace, and how can I use it to debug my application errors?» @Rob Hruska}

Когда что-то идет не так в запущенном приложении Java, часто первым признаком того, что вы увидите, являются строки, напечатанные на экране, которые выглядят следующим образом:

Exception in thread "main" java.lang.RuntimeException: Something has gone wrong, aborting!
  at com.myproject.module.MyProject.badMethod(MyProject.java:22)
  at com.myproject.module.MyProject.oneMoreMethod(MyProject.java:18)
  at com.myproject.module.MyProject.anotherMethod(MyProject.java:14)
  at com.myproject.module.MyProject.someMethod(MyProject.java:10)
  at com.myproject.module.MyProject.main(MyProject.java:6)

Это Stacktrace , и в этом посте я объясню, что это такое, как они сделаны и как их читать и понимать. Если это кажется вам болезненным, тогда читайте дальше…

Анатомия трассировки стека

Обычно трассировка стека отображается, когда Исключение неправильно обрабатывается в коде. Это может быть один из встроенных типов исключений или пользовательское исключение , созданное программой или библиотекой.

Трассировка стека содержит Тип исключения и сообщение , а также список всех вызовов методов , которые выполнялись, когда оно было вызвано.

Давайте проанализируем эту трассировку стека. Первая строка сообщает нам подробности исключения:

Это хорошее начало. Строка 2 показывает, какой код был запущен, когда это произошло:

Это помогает нам сузить круг проблем, но какая часть кода называется плохой метод ? Ответ находится на следующей строке ниже, которую можно прочитать точно так же. И как мы туда попали? Посмотрите на следующую строку. И так далее, пока вы не дойдете до последней строки, которая является основным методом приложения. Считывание трассировки стека снизу вверх вы можете проследить точный путь от начала вашего кода до исключения.

Что пошло не так?

То, что вызывает исключение, обычно является явным оператором throw . Используя имя файла и номер строки, вы можете точно проверить, какой код вызвал исключение. Вероятно, это будет выглядеть примерно так:

  throw new RuntimeException("Something has gone wrong, aborting!");

Это отличное место для начала поиска основной проблемы: существуют ли какие-либо утверждения “если” вокруг этого? Что делает этот код? Откуда берутся данные, используемые в этом методе?

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

• Исключение NullPointerException если obj является нулевым в коде, который вызывает obj.someMethod()
• Арифметическое исключение, если деление на ноль происходит в целочисленной арифметике, т. е. 1/0 – любопытно, что нет исключения, если это вычисление с плавающей запятой, хотя, 1.0/0.0 возвращает бесконечность просто отлично!
• Исключение NullPointerException, если нуль Целое число распаковывается в int в коде, подобном этому: Целое число; a++;
• В Спецификации языка Java есть несколько других примеров, поэтому важно знать, что исключения могут возникать без явного вызова.

Работа с исключениями, создаваемыми библиотеками

Одной из самых сильных сторон Java является огромное количество доступных библиотек. Любая популярная библиотека будет хорошо протестирована, поэтому, как правило, при возникновении исключения из библиотеки лучше сначала проверить, вызвана ли ошибка тем, как ее использует наш код.

Например, если мы используем класс Fraction из Apache Commons Lang и передаем ему некоторые входные данные следующим образом:

  Fraction.getFraction(numberOfFoos, numberOfBars);

Если Количество панелей равно нулю, то трассировка стека будет выглядеть следующим образом:

Exception in thread "main" java.lang.ArithmeticException: The denominator must not be zero
  at org.apache.commons.lang3.math.Fraction.getFraction(Fraction.java:143)   
  at com.project.module.MyProject.anotherMethod(MyProject.java:17)
  at com.project.module.MyProject.someMethod(MyProject.java:13)
  at com.project.module.MyProject.main(MyProject.java:9)

Многие хорошие библиотеки предоставляют Javadoc который содержит информацию о том, какие исключения могут возникать и почему. В этом случае Fraction.getfraction задокументировал выдаст исключение ArithmeticException, если дробь имеет нулевой знаменатель . Здесь это также ясно из сообщения, но в более сложных или неоднозначных ситуациях документы могут оказать большую помощь.

Чтобы прочитать эту трассировку стека, начните сверху с типа исключения – ArithmeticException и сообщения Знаменатель не должен быть равен нулю . Это дает представление о том, что пошло не так, но чтобы выяснить, какой код вызвал исключение, пропустите трассировку стека в поисках чего-то в пакете com.мой проект (это на 3-й строке здесь), затем отсканируйте до конца строки, чтобы увидеть, где находится код ( MyProject.java:17 ). Эта строка будет содержать некоторый код, который вызывает Fraction.getFraction . Это отправная точка для исследования: что передается в getFraction ? Откуда это взялось?

В больших проектах с большим количеством библиотек трассировки стека могут занимать сотни строк поэтому, если вы видите большую трассировку стека, потренируйтесь сканировать список at ... at ... at ... поиск собственного кода – это полезный навык для развития.

Наилучшая практика: Улавливание и Выбрасывание исключений

Допустим, мы работаем над большим проектом, который имеет дело с вымышленными Foobar , и наш код будет использоваться другими. Мы могли бы решить перехватить исключение ArithmeticException из Дроби и переопределить его как нечто специфичное для проекта, которое выглядит следующим образом:

  try {
    ....
    Fraction.getFraction(x,y);
    ....
  } catch ( ArithmeticException e ){ 
    throw new MyProjectFooBarException("The number of FooBars cannot be zero", e);
  }

Поймать исключение ArithmeticException и выбросить его имеет несколько преимуществ:

• Наши пользователи защищены от необходимости заботиться об исключении ArithmeticException , что дает нам гибкость в изменении способа использования commons-lang.
• Можно добавить больше контекста, например, указав, что проблема в количестве фообаров .
• Это также может облегчить чтение трассировок стека, как мы увидим ниже.

Не нужно ловить и бросать на каждое исключение , но там, где, кажется, происходит скачок в слоях вашего кода, например, вызов библиотеки, это часто имеет смысл.

Обратите внимание, что конструктор для Исключения Foo Bar моего проекта принимает 2 аргумента: сообщение и Исключение, которое его вызвало. Каждое исключение в Java имеет поле причина , и при выполнении перехвата и повторной обработки , как это, вы должны всегда устанавливать это, чтобы помочь людям отлаживать ошибки. Трассировка стека теперь может выглядеть примерно так:

Exception in thread "main" com.myproject.module.MyProjectFooBarException: The number of FooBars cannot be zero
  at com.myproject.module.MyProject.anotherMethod(MyProject.java:19)
  at com.myproject.module.MyProject.someMethod(MyProject.java:12)
  at com.myproject.module.MyProject.main(MyProject.java:8)
Caused by: java.lang.ArithmeticException: The denominator must not be zero
  at org.apache.commons.lang3.math.Fraction.getFraction(Fraction.java:143)
  at com.myproject.module.MyProject.anotherMethod(MyProject.java:17)
  ... 2 more

Последнее созданное исключение находится в первой строке, а место, где оно было создано, все еще находится в строке 2. Однако этот тип трассировки стека может вызвать путаницу, поскольку catch-and-retrow изменил порядок вызовов методов по сравнению с трассировками стека, которые мы видели ранее. Основной метод больше не находится внизу, а код, который первым выдал исключение, больше не находится вверху. Когда у вас есть несколько этапов перехвата и повторного броска, он становится больше, но схема одна и та же:

Проверьте разделы от первого до последнего в поисках вашего кода, затем прочитайте соответствующие разделы снизу вверх.

Библиотеки против фреймворков

Разница между библиотекой и фреймворком в Java заключается в следующем:

• Ваш код вызывает методы в библиотеке
• Ваш код вызывается методами в фреймворке

Распространенным типом фреймворка является сервер веб-приложений, такой как Spark Java или Spring Boot . Используя Spark Java и Commons-Lang с нашим кодом, мы могли бы увидеть трассировку стека, подобную этой:

com.framework.FrameworkException: Error in web request
    at com.framework.ApplicationStarter.lambda$start$0(ApplicationStarter.java:15)
    at spark.RouteImpl$1.handle(RouteImpl.java:72)
    at spark.http.matching.Routes.execute(Routes.java:61)
    at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:134)
    at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
    at org.eclipse.jetty.server.Server.handle(Server.java:503)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: com.project.module.MyProjectFooBarException: The number of FooBars cannot be zero
    at com.project.module.MyProject.anotherMethod(MyProject.java:20)
    at com.project.module.MyProject.someMethod(MyProject.java:12)
    at com.framework.ApplicationStarter.lambda$start$0(ApplicationStarter.java:13)
    ... 16 more
Caused by: java.lang.ArithmeticException: The denominator must not be zero
    at org.apache.commons.lang3.math.Fraction.getFraction(Fraction.java:143)
    at com.project.module.MyProject.anotherMethod(MyProject.java:18)
    ... 18 more

Хорошо, это уже довольно долго. Как и прежде, мы должны сначала заподозрить наш собственный код, но становится все труднее и труднее найти где это . Вверху находится исключение фреймворка, внизу – Библиотека, а прямо посередине – наш собственный код. Фу!

Сложный фреймворк и библиотека могут создать дюжину или более Вызвано разделами: , поэтому хорошей стратегией будет перейти к тем, кто ищет ваш собственный код: Вызвано: com.myproject... Затем прочтите этот раздел подробно, чтобы определить проблему.

Вкратце

Изучение того, как понимать трассировки стека и быстро их читать, позволит вам разобраться в проблемах и сделает отладку намного менее болезненной. Это навык, который совершенствуется с практикой, поэтому в следующий раз, когда вы увидите большую трассировку стека, не пугайтесь – там много полезной информации, если вы знаете, как ее извлечь.

Если у вас есть какие-либо советы или рекомендации по работе с Java Stacktraces, я бы хотел услышать о них, так что свяжитесь со мной и давайте поделимся тем, что мы знаем.

mgilliard@twilio.com @@Максимальная загрузка

Оригинал: “https://dev.to/twilio/how-to-read-and-understand-a-java-stacktrace-3796”

Стектрейс — это отладочный инструмент при разработке. В процессе выполнения программы выдает отчет о работающих стеках в выбранный момент времени, поэтому всегда есть возможность посмотреть класс и имя функции, которая выполняется прямо сейчас. Также можно посмотреть функцию, которая вызвала нужную работающую функцию, и вывести это все в виде списка. Это списки могут помочь найти функции и методы, вызвавшие ошибки в приложении.

До определенного момента стектрейс не был включен в стандарты разработки С++. Но в последнее время ситуация поменялась и отечественные разработчики тоже к тому приложили свои усилия.

Стектрейс в С++

Что такое stack trace — вы уже знаете. Но представьте себе, что каких-то пару лет назад он не был включен в стандарт С++. В 2018-м году Российская инициативная группа разработчиков собирала мнения других программистов по поводу стектрейс в С++ и донесла их в Международный комитет по стандартизации. Четко обосновав, что принятые изменения позволят упростить разработку на С++ и добавят в этот язык больше логики.

Работая над большими проектами на С++, часто возникает потребность узнать, откуда берет начало та или иная функция. Допустим, нужная нам функция вызывается только после возникновения ошибки, тогда не лишним было бы узнать, какие «вызовы» вызвали ошибку и нужную функцию.

Самым простым методом было бы применить отладчик,и остановить его работу в нужном месте и просмотреть стек. Но в некоторых сценариях отладки это сделать невозможно, например:

• когда необходимо просмотреть стек с устройства, где нет возможности наладить отладчик;

• когда невозможно «внешнее» вмешательство в отлаживаемое приложение.

В этих случаях возможно получать стек только в процессе выполнения программы. Тут и может помочь технология стектрейс. Но для этого нужно внести классы для просмотра стека прямо в стандарт С++. Именно это и инициировали русские разработчики.

Это не значит, что до сих пор никак это нельзя было сделать. До внедрения стектрейс в С++ это все делалось очень «громоздкими» методами такими как:

• использование большого обилия форматов;

• использование компиляторов и платформ;

• подключение различных библиотек и др.

По сути, эти действия только добавляли сложности в проект. А с внедрением стектрейс стало возможным все это сделать двумя строчками кода.

Плюсы использования стектрейс в С++

Стектрейс в С++ принес с собой определенные «облегчения» при отладке программ:

• больше не нужно ограничивать себя одной определенной платформой;

• отпадает зависимость от определенного компилятора — теперь можно использовать многие компиляторы, которые поддерживают стандарт стектрейс в С++;

• больше не нужно переживать по поводу формата отладочной информации;

• отпадает зависимость от использования определенных библиотек;

• и др.

Stack trace — это то, что облегчит вашу разработку и отладку приложений на языке С++. Стектрейс — это достаточно новая технология для С++, и со временем он будет только развиваться и дополняться новыми возможностями. К примеру, ближайшее дополнение — это добавление способности переноса стектрейсов между разными машинами.

public static void main(String[] args) {
    hereWillBeTrouble(42, 0);
}

public static void hereWillBeTrouble(int a, int b) {
    int oops = a / b;
    System.out.println(oops);
}

static void notGood() {
    System.out.println("Только не снова!");
    notGood();
}

public static void main(String[] args) {
    hereWillBeTrouble(42, 0);
}

public static void hereWillBeTrouble(int a, int b) {
    System.out.println("Всё, что было до...");
    int oops = a / b;
    System.out.println(oops);
    System.out.println("Всё, что будет после...");
}

public static void main(String[] args) {
    hereWillBeTrouble();
}

private static void hereWillBeTrouble(int a, int b) {
    int oops;
    try {
        System.out.println("Всё, что было до...");
        oops = a / b;
        System.out.println(oops);
        System.out.println("Всё, что будет после...");
    } catch (ArithmeticException e) {
        System.out.println("Говорили же не делить на ноль!");
        oops = 0;
    }
    System.out.println("Метод отработал");
}

public static void main(String[] args) {
    hereWillBeTrouble(42, 0);
}

private static void hereWillBeTrouble(int a, int b) {
    if (b == 0) {
        throw new ArithmeticException("ты опять делишь на ноль?");
    }
    int oops = a / b;
    System.out.println(oops);
}

Школа дронов для всех
Учим программировать беспилотники и управлять ими.
Узнать больше