Отладка кода
Анализ стека вызовов
Когда код реализован так, что внутри одной функции вызываются другие функция, бывает непросто разобраться, где же именно произошла ошибка. В реальности приходится разбираться в ситуациях ещё сложнее: например, функции могут быть объявлены в разных скриптах, организованы в каскад вложенных функций и тому подобные изыски.
В таких случаях при поиске ошибок полезно использовать функцию traceback(), которая отслеживает иерархию вызовов и указывает, на какой строчке какой функции возникла ошибка.
Например, у нас есть две функции, fun_h() и fun_z(), в первой вызывается вторая, и во второй есть некорректная операция — сложение числа со строкой.
# первая функция, с вложенным вызовом
fun_h <- function(x, y) {
x <- x + rnorm(1)
fun_z(x, y)
}
# функция с ошибкой
fun_z <- function(x, y) {
res <- x ^ 2 + abs(y) + 'z'
res
}Вызываем функцию fun_h(x = 3, y = -5) и смотрим результат traceback() (приведена копия вывода из консоли):
> fun_h(x = 3, y = -5)
Error in x^2 + abs(y) + "z" : non-numeric argument to binary operator
> traceback()
2: fun_z(x, y) at #3
1: fun_h(x = 3, y = -5)Вывод функции traceback() — последовательность выполненных выражений в порядке снизу вверх. Метка #3 означает, что ошибка произошла во время выполнения третьего выражения, так как сначала происходит выполнение выражения x + rnorm(1), потом вызов функции fun_z(x, y) и потом выполнение x ^ 2 + abs(y) + 'z'.
Вообще traceback() очень удобен в ситуации, когда используются функции из внешних скриптов, подгружаемые через source(): в таких случаях указывается не только номер строки (ситуации, когда на одной строке несколько выражений, достаточно редки), но и название файла, по маске filename.r#linenumber. Это позволяет легко искать и править ошибки в скриптах на сотни строк, что было бы очень сложно сделать иным способом.
При желании можно сразу задать в опциях сессии действия при возникновении ошибки, обычно это трейсбек или отладка (recover()). Указать трейсбек в действиях при ошибке можно таким выражением: options(error = traceback), снять — указав NULL, options(error = NULL).
> options(error = traceback)
> fun_h(x = 3, y = -5)
Error in x^2 + abs(y) + "z" : non-numeric argument to binary operator
2: fun_z(x, y) at #3
1: fun_h(x = 3, y = -5)
> options(error = NULL)Отладка с помощью debug()
Одно из самых неудобных в работе с функциями — сложно контролировать операции, которые происходят внутри функции и искать, когда что-то сломается. Наивное решение здесь — выносить тело функции в глобальное окружение, создавать одноимённые аргументам объекты и поочередно запускать и тестировать операции.
Ещё более простой путь — включить в функцию выражения вида print(x) и таким образом контролировать процесс выполнения функции. Решение по простоте и изяществу не уступает топору, поэтому нередко в сообществе встречаются самоироничные высказывания в духе дебажу принтом.
Намного удобнее, впрочем, воспользоваться встроенными функциями отладки — debug() / undebug() и debugonce(). В отличие от debug(), функция debugonce() вызывает интерфейс дебаггера однократно, его можно опознать по Browse в командной строке.
Команды для работы в режиме отладки:
n / Enter — выполнить следующее выражение (F10 в RStudio);
s — перейти в область видимости вложенной функции (Shift + F4);
f — завершить функцию или цикл (Shift + F6);
с — продолжить выполнение (Shift + F5);
Q — выйти из режима отладки (Shift + F8).
Допустим, у нас есть простая функция, которая считает, сколько раз встречается та или иная цифра в векторе числовых значений.
numbers_counter <- function(x) {
x <- as.character(x)
x <- gsub('[^0-9]', '', x)
x <- strsplit(x, "")
x <- unlist(x)
digit.vector <- factor(x, levels = 0:9)
res <- table(digit.vector)
res
}
numbers_counter(sample(15))## digit.vector
## 0 1 2 3 4 5 6 7 8 9
## 1 8 2 2 2 2 1 1 1 1Основной смысл отладки с помощью debugonce() — проверка, соответствует ли результат выполнения выражений в теле функции ожидаемому. Выражение debugonce(numbers_counter) указывает, что следующий запуск функции будет выполнен в режиме отладки (если указать debug(numbers_counter), то при каждом вызове, пока не будет прекращена отладка с помощью undebug(numbers_counter)).
Вот так выглядит лог отладки в консоли. В консоли с Browse[2]> можно выполнять различные команды, в первую очередь, конечно, те, которые помогут получить информацию об объекте или рабочем окружении функции. Строчка debug at маркирует, до какого выражения дошла отладка, но само это выражение ещё не выполнено.
Так, сначала мы смотрим, а какие же значения были переданы в аргумент x функции (первый print(x)). Далее последовательно выполняем выражения функции до выполнения unlist(x) — смотрим, что получилось в результате превращения переданного вектора значений в строки, удаления лишних знаков и разбора строкового вектора по символам с помощью strsplit() в вектор. После этого опять выполняем выражения почти до самого конца и перед последним выражением смотрим, что же вообще есть на этот момент в рабочем окружении функции (ls()). С выполнением последнего выражения функция завершает работу, и мы получаем её результат.
Так как использование дебаггера возможно только в интерактивном режиме, здесь и далее копии вывода выполненных в консоли команд, а не реально сгенерированный во время рендера документа вывод:
> debugonce(numbers_counter)
> numbers_counter(sample(15))
debugging in: numbers_counter(sample(15))
debug at #1: {
x <- as.character(x)
x <- gsub("[^0-9]", "", x)
x <- strsplit(x, "")
x <- unlist(x)
digit.vector <- factor(x, levels = 0:9)
res <- table(digit.vector)
res
}
Browse[2]> print(x)
[1] 12 6 14 10 13 9 2 4 5 1 3 11 15 7 8
Browse[2]> n
debug at #2: x <- as.character(x)
Browse[2]> n
debug at #3: x <- gsub("[^0-9]", "", x)
Browse[2]> n
debug at #4: x <- strsplit(x, "")
Browse[2]> n
debug at #5: x <- unlist(x)
Browse[2]> n
debug at #6: digit.vector <- factor(x, levels = 0:9)
Browse[2]> print(x)
[1] "1" "2" "6" "1" "4" "1" "0" "1" "3" "9" "2" "4" "5" "1" "3" "1" "1" "1" "5" "7"
[21] "8"
Browse[2]> n
debug at #7: res <- table(digit.vector)
Browse[2]> n
debug at #8: res
Browse[2]> ls()
[1] "digit.vector" "res" "x"
Browse[2]> n
exiting from: numbers_counter(sample(15))
digit.vector
0 1 2 3 4 5 6 7 8 9
1 8 2 2 2 2 1 1 1 1 Помимо debug(), есть альтернативная функция, recover(), которая в целом позволяет выбрать, какой из текущих вызовов, приведших к ошибке, следует проанализировать в дебаггере. Функцию recover() можно также указать в опциях действий при ошибке: options(error = recover).
breakpoints()
Когда известно, в каком месте может возникнуть ошибка (или же хочется проконтролировать какое-то определенное место в длинной функции, не проходя все выражения функции), то можно воспользоваться брекпоинтами. В IDE, в частности, в RStudio, брекпоинт ставится кликом мыши слева от номера строки выражения. Делать это нужно в файле, который потом будет вызван через source().
В чистом R брекпоинты можно поставить с помощью функции setBreakpoint() (механизм брекпоинтов в IDE также использует эту функцию). Для примера запишем функцию numbers_counter() в файл и выполним его:
# ещё раз объявляем функцию и смотрим её класс
numbers_counter <- function(x) {
x <- as.character(x)
x <- gsub('[^0-9]', '', x)
x <- strsplit(x, "")
x <- unlist(x)
digit.vector <- factor(x, levels = 0:9)
res <- table(digit.vector)
res
}
class(numbers_counter)## [1] "function"
# создаём файл и записываем в него функцию
dump('numbers_counter', file = 'numbers_counter.R')
# смотрим содержание файла
readLines('numbers_counter.R')## [1] "numbers_counter <-"
## [2] "function(x) {"
## [3] " x <- as.character(x)"
## [4] " x <- gsub('[^0-9]', '', x)"
## [5] " x <- strsplit(x, \"\")"
## [6] " x <- unlist(x)"
## [7] " digit.vector <- factor(x, levels = 0:9)"
## [8] " res <- table(digit.vector)"
## [9] " res"
## [10] "}"Поставим брекпоинт на восьмую строку, к этому моменту уже должны быть выполнены операции обработки вектора и создание объекта digit.vector класса factor. Брекпоинт также можно поставить по маске, как и в трейсбеке, — filename.r#linenumber.
source('numbers_counter.R')
setBreakpoint(srcfile = 'numbers_counter.R#8')## No source refs found.Выполним функцию. При выполнении в интерактивном режиме открывается окно Browse, как и при использовании debug(), но дебаг начинается с восьмого выражения функции, предыдущие уже выполнены.
# выполняем функцию
> numbers_counter(sample(15))
numbers_counter.R#8
Called from: numbers_counter(sample(15))
Browse[1]> n
debug: res <- table(digit.vector)
Browse[2]> ls()
[1] "digit.vector" "x"
Browse[2]> f
digit.vector
0 1 2 3 4 5 6 7 8 9
1 8 2 2 2 2 1 1 1 1 При установке брекпоинта класс функции меняется (становится functionWithTrace), также вносятся изменения в тело функции:
> class(numbers_counter)
[1] "functionWithTrace"
attr(,"package")
[1] "methods"
> body(numbers_counter)
{
x <- as.character(x)
x <- gsub("[^0-9]", "", x)
x <- strsplit(x, "")
x <- unlist(x)
digit.vector <- factor(x, levels = 0:9)
{
.doTrace({
cat(paste0("numbers_counter.R", "#", 8, "\n"))
browser(skipCalls = 4L)
})
res <- table(digit.vector)
}
res
}Дебаг в неинтерактивном режиме
Основные функции дебага предназначены для интерактивной работы. Однако и при неинтерактивном выполнении скриптов можно делать постмортем анализ, чем же была вызвана ошибка. Для этого требуется, во-первых, в опцию действий при ошибке указать функцию дампа рабочего окружения скрипта. Во-вторых, следует вызвать и проанализировать этот дамп с помощью помощью debugger().
Рассмотрим на уже использовавшихся ранее функциях fun_h() и fun_z(). Допустим, у нас есть скрипт, в начале которого задано, что при ошибке дамп пишется в файл, потом объявляются две функции и происходит их вызов:
readLines('script_with_errors.R')## [1] "# задаем опции"
## [2] "options(error = quote(dump.frames(dumpto = 'last_dump', to.file = TRUE)))"
## [3] "fun_h <-"
## [4] "function(x, y) {"
## [5] " x <- x + rnorm(1)"
## [6] " fun_z(x, y)"
## [7] "}"
## [8] "fun_z <-"
## [9] "function(x, y) {"
## [10] " res <- x ^ 2 + abs(y) + 'z'"
## [11] " res"
## [12] "}"
## [13] ""
## [14] "# вызываем функции"
## [15] "fun_h(x = 3, y = -5)"Выполняем скрипт script_with_errors.R — так как он написан с ошибкой, должен сгенерироваться файл дампа last_dump.rda.
system('Rscript script_with_errors.R')Проверим, что файл дампа есть:
file.exists('last_dump.rda')## [1] TRUE
# импортируем дамп
load('last_dump.rda')Запускаем дебаггер по дампу упавшего скрипта. Дебаггер так же, как и функция recover(), возвращает стек вызовов по порядку и предлагает выбрать, какое окружение запустить. При выборе 6, загрузки окружения функции fun_z(), открывается окно дебаггера:
> debugger(last_dump)
Message: Error in x^2 + abs(y) + "z" : non-numeric argument to binary operator
Available environments had calls:
1: source("script_with_errors.R")
2: withVisible(eval(ei, envir))
3: eval(ei, envir)
4: eval(ei, envir)
5: script_with_errors.R#15: fun_h(x = 3, y = -5)
6: script_with_errors.R#6: fun_z(x, y)
Enter an environment number, or 0 to exit
Selection: 6
Browsing in the environment with call:
script_with_errors.R#6: fun_z(x, y)
Called from: debugger.look(ind)
Browse[1]> ls()
[1] "x" "y"
Browse[1]> QЛогирование процесса
При работе больших проектов (или просто регулярно выполняемых скриптов) будет правильным и полезным логировать как минимум наиболее важные этапы. Например, при задачах ETL хорошо бы логировать время начала скрипта, исходные параметры источника данных (дата, источник и т. д.), какими версиями пакетов производилась обработка.
Простое и достаточно изящное решение здесь м воспользоваться пакетом futile.logger, который позволяет формировать сообщения с определённым набором параметров и выводить в консоль и/или записывать в файл лога (или любыми другими пакетами с подобным функционалом). Ещё одна приятная возможность futile.logger — создавать несколько параллельных логгеров с разными настройками.
Например, функция flog.info() указывает тип сообщения — информационный, в выводе также есть время вызова и собственно текст сообщения.
## INFO [2022-02-04 18:55:08] просто вывод в консольПри желании можно изменить формат сообщения, для этого есть набор параметров:
- ~l — уровень лога;
- ~t — дата и время вызова;
- ~n — пространство имён, в котором сделан вызов (актуально для системы логирования в пользовательских пакетах или же параллельно существующих логгерах);
- ~f — функция, в теле которой есть вывод лога (shell для скрипта);
- ~m — сообщение.
# задаём формат сообщения
log_format <- layout.format('~t [~l]: ~m')
flog.layout(log_format)## NULL
# простой вывод в консоль
flog.info('просто вывод в консоль')## 2022-02-04 18:55:08 [INFO]: просто вывод в консольПри желании можно даже сохранить формат вывода:
## 2022-02-04 18:55:08 [INFO]: Matrix:
##
## [,1] [,2] [,3] [,4]
## [1,] 2.0730537 -1.1363151 -0.65329622 -1.3717639
## [2,] 0.9632402 1.2394381 -0.30650136 -0.6406689
## [3,] -0.1791220 -0.6496477 0.04017464 2.5269507futile.logger предполагает иерархию типов сообщений по степени информативности/критичности: TRACE < DEBUG < INFO < WARN < ERROR < FATAL. Например, если необходимо подавить все сообщения, которые менее критичны, чем ошибки (TRACE - WARN), то можно задать порог отсечения с помощью функции flog.threshold():
# устанавливаем порог
flog.threshold(ERROR)## NULL
# все типы ниже порога подавляются
flog.info('info')
flog.trace('trace')
# тип выше порога выводится в консоль
flog.fatal('fatal')## 2022-02-04 18:55:08 [FATAL]: fatal
# возвращаем логирование всех типов
flog.threshold(TRACE)## NULLЛоги также можно писать в файл. Для вывода в файл надо указать, что запись будет вестись в файл, а также указать формат записи — дописывание файла или перезапись. Для примера будем писать лог во временный файл, в реальной практике, конечно же, необходимо создавать файл на диске. Для одновременного вывода в консоль и записи в файл можно воспользоваться функцией appender.tee().
Вот так выглядит минимальный логгер, когда во временный файл пишется стартовая информация о происходящем, потом выполняется функция с flog.info() внутри и в конце в лог дописывается информация о сессии из sessionInfo().
# создаём файл и указываем заголовок лога
log_file <- tempfile()
flog.appender(appender.file(log_file))## NULL
flog.info('Тестируем запись в файл')
# выполняем выражение и результат пишем в лог
m <- matrix(rnorm(12), nrow = 3)
flog.info("Matrix:", m, capture = TRUE)
# дописываем в файл лога информацию о системе
flog.info("SESSION INFO:", sessionInfo(), capture = TRUE)Результат:
readLines(log_file)## [1] "2022-02-04 18:55:08 [INFO]: Тестируем запись в файл"
## [2] "2022-02-04 18:55:08 [INFO]: Matrix:"
## [3] ""
## [4] " [,1] [,2] [,3] [,4]"
## [5] "[1,] 0.2225305 -0.2208278 -0.1546478 1.6840469"
## [6] "[2,] 0.4167829 0.2317318 -0.1111858 -0.4698932"
## [7] "[3,] -1.5205089 -0.1374083 0.6027375 -0.8110365"
## [8] "2022-02-04 18:55:08 [INFO]: SESSION INFO:"
## [9] ""
## [10] "R version 4.1.2 (2021-11-01)"
## [11] "Platform: x86_64-pc-linux-gnu (64-bit)"
## [12] "Running under: Ubuntu 20.04.3 LTS"
## [13] ""
## [14] "Matrix products: default"
## [15] "BLAS: /usr/lib/x86_64-linux-gnu/blas/libblas.so.3.9.0"
## [16] "LAPACK: /usr/lib/x86_64-linux-gnu/lapack/liblapack.so.3.9.0"
## [17] ""
## [18] "locale:"
## [19] " [1] LC_CTYPE=en_US.UTF-8 LC_NUMERIC=C "
## [20] " [3] LC_TIME=ru_RU.UTF-8 LC_COLLATE=en_US.UTF-8 "
## [21] " [5] LC_MONETARY=ru_RU.UTF-8 LC_MESSAGES=en_US.UTF-8 "
## [22] " [7] LC_PAPER=ru_RU.UTF-8 LC_NAME=C "
## [23] " [9] LC_ADDRESS=C LC_TELEPHONE=C "
## [24] "[11] LC_MEASUREMENT=ru_RU.UTF-8 LC_IDENTIFICATION=C "
## [25] ""
## [26] "attached base packages:"
## [27] "[1] stats graphics grDevices utils datasets methods base "
## [28] ""
## [29] "other attached packages:"
## [30] "[1] futile.logger_1.4.3"
## [31] ""
## [32] "loaded via a namespace (and not attached):"
## [33] " [1] knitr_1.36 xml2_1.3.2 magrittr_2.0.1 "
## [34] " [4] downlit_0.2.1 R6_2.5.1 rlang_0.4.12 "
## [35] " [7] fastmap_1.1.0 fansi_0.5.0 stringr_1.4.0 "
## [36] "[10] tools_4.1.2 xfun_0.26 utf8_1.2.2 "
## [37] "[13] lambda.r_1.2.4 jquerylib_0.1.4 htmltools_0.5.2 "
## [38] "[16] ellipsis_0.3.2 yaml_2.2.1 digest_0.6.29 "
## [39] "[19] tibble_3.1.6 lifecycle_1.0.1 crayon_1.4.2 "
## [40] "[22] bookdown_0.22.17 formatR_1.11 futile.options_1.0.1"
## [41] "[25] sass_0.4.0 vctrs_0.3.8 fs_1.5.0 "
## [42] "[28] evaluate_0.14 rmarkdown_2.11 stringi_1.7.6 "
## [43] "[31] compiler_4.1.2 bslib_0.3.1 pillar_1.6.4 "
## [44] "[34] jsonlite_1.7.2 pkgconfig_2.0.3 "