r-prof / winch Goto Github PK

High-level combined tracebacks

Home Page: https://r-prof.github.io/winch/

R 53.18% C 29.56% Shell 17.26%

winch's Introduction

winch

Winch provides stack traces for call chains that cross between R and C function calls. This is a useful tool for developers of R packages where a substantial portion of the code is C or C++.

Installation

Install the released version of winch from CRAN with:

install.packages("winch")

Install the development version from GitHub with:

devtools::install_github("r-lib/winch")

Example

Below is an example where an R function calls into C which calls back into R. Note the second-to-last entry in the trace:

library(winch)

foo <- function() {
  winch_call(bar)
}

bar <- function() {
  winch_trace_back()
}

foo()
#>                  func               ip
#> 1  Rf_NewFrameConfirm 00007ffa45274480
#> 2             Rf_eval 00007ffa452be4f0
#> 3        R_execMethod 00007ffa452c3550
#> 4             Rf_eval 00007ffa452be4f0
#> 5        R_execMethod 00007ffa452c1e90
#> 6             Rf_eval 00007ffa452be4f0
#> 7             Rf_eval 00007ffa452c0170
#> 8     Rf_applyClosure 00007ffa452c1090
#> 9             Rf_eval 00007ffa452be4f0
#> 10       R_execMethod 00007ffa452c1e90
#> 11            Rf_eval 00007ffa452be4f0
#> 12            Rf_eval 00007ffa452c0170
#> 13    Rf_applyClosure 00007ffa452c1090
#> 14            Rf_eval 00007ffa452be4f0
#> 15         winch_call 00007ffa32145240
#> 16 Rf_NewFrameConfirm 00007ffa452728a0
#> 17 Rf_NewFrameConfirm 00007ffa45274480
#> 18            Rf_eval 00007ffa452be4f0
#> 19       R_execMethod 00007ffa452c1e90
#> 20            Rf_eval 00007ffa452be4f0
#> 21            Rf_eval 00007ffa452c0170
#> 22    Rf_applyClosure 00007ffa452c1090
#> 23            Rf_eval 00007ffa452be4f0
#> 24       R_execMethod 00007ffa452c1e90
#> 25            Rf_eval 00007ffa452be4f0
#> 26            Rf_eval 00007ffa452c0170
#> 27    Rf_applyClosure 00007ffa452c1090
#> 28            Rf_eval 00007ffa452be4f0
#> 29     R_forceAndCall 00007ffa452c43a0
#> 30           do_Rprof 00007ffa452a8b80
#> 31            Rf_eval 00007ffa452be4f0
#> 32            Rf_eval 00007ffa452c0170
#> 33    Rf_applyClosure 00007ffa452c1090
#>                                        pathname
#> 1                        /usr/lib/R/lib/libR.so
#> 2                        /usr/lib/R/lib/libR.so
#> 3                        /usr/lib/R/lib/libR.so
#> 4                        /usr/lib/R/lib/libR.so
#> 5                        /usr/lib/R/lib/libR.so
#> 6                        /usr/lib/R/lib/libR.so
#> 7                        /usr/lib/R/lib/libR.so
#> 8                        /usr/lib/R/lib/libR.so
#> 9                        /usr/lib/R/lib/libR.so
#> 10                       /usr/lib/R/lib/libR.so
#> 11                       /usr/lib/R/lib/libR.so
#> 12                       /usr/lib/R/lib/libR.so
#> 13                       /usr/lib/R/lib/libR.so
#> 14                       /usr/lib/R/lib/libR.so
#> 15 /home/kirill/git/R/r-prof/winch/src/winch.so
#> 16                       /usr/lib/R/lib/libR.so
#> 17                       /usr/lib/R/lib/libR.so
#> 18                       /usr/lib/R/lib/libR.so
#> 19                       /usr/lib/R/lib/libR.so
#> 20                       /usr/lib/R/lib/libR.so
#> 21                       /usr/lib/R/lib/libR.so
#> 22                       /usr/lib/R/lib/libR.so
#> 23                       /usr/lib/R/lib/libR.so
#> 24                       /usr/lib/R/lib/libR.so
#> 25                       /usr/lib/R/lib/libR.so
#> 26                       /usr/lib/R/lib/libR.so
#> 27                       /usr/lib/R/lib/libR.so
#> 28                       /usr/lib/R/lib/libR.so
#> 29                       /usr/lib/R/lib/libR.so
#> 30                       /usr/lib/R/lib/libR.so
#> 31                       /usr/lib/R/lib/libR.so
#> 32                       /usr/lib/R/lib/libR.so
#> 33                       /usr/lib/R/lib/libR.so
#>  [ reached 'max' / getOption("max.print") -- omitted 99 rows ]

rlang::entrace() checks if winch is installed, and adds a native backtrace. As this cannot be easily demonstrated in a knitr document, the output is copied from a GitHub Actions run.

options(
  error = rlang::entrace,
  rlang_backtrace_on_error = "full",
  rlang_trace_use_winch = TRUE
)

vctrs::vec_as_location(quote, 2)

Error: Must subset elements with a valid subscript vector.
✖ Subscript has the wrong type `function`.
ℹ It must be logical, numeric, or character.
Backtrace:
    █
 1. └─vctrs::vec_as_location(quote, 2)
 2.   └─`/vctrs.so`::vctrs_as_location()
 3.     └─`/vctrs.so`::vec_as_location_opts()

How does it work?

winch uses a very simple heuristic. R’s traceback (and also profiling) infrastructure introduces the notion of a “context”. Every call to an R function opens a new context and closes it when execution of the function ends. Unfortunately, no new context is established for native code called with .Call() or .External(). Establishing contexts expends precious run time, so this may be the reason for the omission.

To work around this limitation, the source code of all R functions along the call chain is scanned for instances of .Call and .External. The native call stack (obtained via libunwind or libbacktrace) is scanned for chunks of code outside of libR.so (R’s main library) – these are assumed to correspond to .Call() or .External(). The native traces are embedded as artificial calls into the R stack trace.

Limitations

The matching will not be perfect, but it may still lead to faster discovery of the cause of an error.
On Windows winch only works on x64, and there the traces can be obtained only for one shared library at a time. See winch_init_library() for details.

Code of Conduct

Please note that the winch project is released with a Contributor Code of Conduct. By contributing to this project, you agree to abide by its terms.

winch's People

Contributors

Stargazers

Watchers

Forkers

jawond qulogic antonov548 barracuda156

winch's Issues

Performance of winch with testthat

devtools::test() with vctrs is 4 times slower with winch.

Integrate into rlang?

Requires very careful testing.

It would be easier to support "rlang_error".

Provide C callable replacement for Rf_error()

to record native backtrace when failure occurs in native code.

Update upstream libbacktrace sources

Currently vendored from my fork's main branch: https://github.com/krlmlr/libbacktrace.

winch corrupts rlang backtraces

Reprex:

> vctrs::num_as_location(-5, 4, oob = "extend", negative = "ignore")
Error in `if (error_frame) ...`:
! argument is not interpretable as logical
Backtrace:
   ....
Warning message:
In if (error_frame) { :
  the condition has length > 1 and only the first element will be used

In a debugging session I see this before and after enriching the backtrace with winch:

Browse[2]> df_print(trace)
# A data frame: 9 × 6
  call       parent visible namespace scope error_frame
  <list>      <int> <lgl>   <chr>     <chr> <lgl>      
1 <language>      0 TRUE    vctrs     ::    TRUE       
2 <language>      0 FALSE   rlang     :::   FALSE      
3 <language>      2 FALSE   rlang     ::    FALSE      
4 <language>      3 FALSE   rlang     ::    FALSE      
5 <language>      3 FALSE   rlang     ::    FALSE      
6 <language>      5 FALSE   rlang     :::   FALSE      
7 <language>      6 FALSE   devtools  ::    FALSE      
8 <language>      7 FALSE   pkgload   ::    FALSE      
9 <language>      8 FALSE   cli       ::    FALSE      

Browse[2]> > trace <- winch::winch_add_trace_back(trace)
Browse[2]> > df_print(trace)
# A data frame: 18 × 6
   call       parent visible namespace scope error_frame
 * <list>      <int> <lgl>   <chr>     <chr> <list>     
 1 <language>      0 TRUE    vctrs     ::    <language> 
 2 <language>      1 TRUE    /vctrs.so ::    <language> 
 3 <language>      2 TRUE    /vctrs.so ::    <language> 
 4 <language>      3 TRUE    /vctrs.so ::    <language> 
 5 <language>      4 TRUE    /vctrs.so ::    <language> 
 6 <language>      5 TRUE    /rlang.so ::    <language> 
 7 <language>      6 TRUE    /rlang.so ::    <language> 
 8 <language>      7 TRUE    /rlang.so ::    <language> 
 9 <language>      8 TRUE    /rlang.so ::    <language> 
10 <language>      9 TRUE    /rlang.so ::    <language> 
11 <language>     10 FALSE   rlang     :::   <language> 
12 <language>     11 FALSE   rlang     ::    <language> 
13 <language>     12 FALSE   rlang     ::    <language> 
14 <language>     12 FALSE   rlang     ::    <language> 
15 <language>     14 FALSE   rlang     :::   <language> 
16 <language>     15 FALSE   devtools  ::    <language> 
17 <language>     16 FALSE   pkgload   ::    <language> 
18 <language>     17 FALSE   cli       ::    <language>

Experiment with libunwind

Does it give better tracebacks?

Can it be loaded dynamically?

https://www.nongnu.org/libunwind/docs.html

Use getLoadedDLLs()

in examples and example test files.

Error in winch_trace_back() : unw_getcontext() error: -1073785320

Seems not to work on PPC:

R version 4.2.3 (2023-03-15) -- "Shortstop Beagle"
Copyright (C) 2023 The R Foundation for Statistical Computing
Platform: powerpc-apple-darwin10.0.0d2 (32-bit)

> library(winch)
> 
> foo0 <- function() {
+   winch_call(bar0)
+ }
> 
> bar0 <- function() {
+   winch_call(baz0)
+ }
> 
> baz0 <- function() {
+   winch_trace_back()
+ }
> 
> if (winch_available()) {
+   foo0()
+ }
Error in winch_trace_back() : unw_getcontext() error: -1073785320
Calls: foo0 ... <Anonymous> -> winch_call -> <Anonymous> -> winch_trace_back
Execution halted

R version 4.2.3 (2023-03-15) -- "Shortstop Beagle"
Copyright (C) 2023 The R Foundation for Statistical Computing
Platform: powerpc-apple-darwin10.0.0d2 (32-bit)

  Natural language support but running in an English locale

> pkgname <- "winch"
> source(file.path(R.home("share"), "R", "examples-header.R"))
> options(warn = 1)
> library('winch')
> 
> base::assign(".oldSearch", base::search(), pos = 'CheckExEnv')
> base::assign(".old_wd", base::getwd(), pos = 'CheckExEnv')
> cleanEx()
> nameEx("winch_available")
> ### * winch_available
> 
> flush(stderr()); flush(stdout())
> 
> ### Name: winch_available
> ### Title: Are native tracebacks available?
> ### Aliases: winch_available
> 
> ### ** Examples
> 
> winch_available()
[1] TRUE
> 
> 
> 
> cleanEx()
> nameEx("winch_call")
> ### * winch_call
> 
> flush(stderr()); flush(stdout())
> 
> ### Name: winch_call
> ### Title: Call an R function from native code
> ### Aliases: winch_call
> 
> ### ** Examples
> 
> foo <- function() {
+   winch_call(bar)
+ }
> 
> bar <- function() {
+   writeLines("Hi!")
+ }
> 
> foo()
Hi!
NULL
> 
> 
> 
> cleanEx()
> nameEx("winch_init_library")
> ### * winch_init_library
> 
> flush(stderr()); flush(stdout())
> 
> ### Name: winch_init_library
> ### Title: Set library to collect symbols for native stack traces
> ### Aliases: winch_init_library
> 
> ### ** Examples
> 
> ## Don't show: 
> if (requireNamespace("rlang", quietly = TRUE)) (if (getRversion() >= "3.4") withAutoprint else force)({ # examplesIf
+ ## End(Don't show)
+ winch_init_library(getLoadedDLLs()[["rlang"]][["path"]])
+ ## Don't show: 
+ }) # examplesIf
> winch_init_library(getLoadedDLLs()[["rlang"]][["path"]])
> ## End(Don't show)
> 
> 
> 
> cleanEx()
> nameEx("winch_stop")
> ### * winch_stop
> 
> flush(stderr()); flush(stdout())
> 
> ### Name: winch_stop
> ### Title: Raise an error from native code
> ### Aliases: winch_stop
> 
> ### ** Examples
> 
> try(winch_stop("Test"))
Error in winch_stop("Test") : winch_stop(): Test
> 
> 
> 
> cleanEx()
> nameEx("winch_trace_back")
> ### * winch_trace_back
> 
> flush(stderr()); flush(stdout())
> 
> ### Name: winch_trace_back
> ### Title: Native stack trace
> ### Aliases: winch_trace_back
> 
> ### ** Examples
> 
> ## Don't show: 
> if (winch_available()) (if (getRversion() >= "3.4") withAutoprint else force)({ # examplesIf
+ ## End(Don't show)
+ winch_trace_back()
+ 
+ foo <- function() {
+   winch_call(bar)
+ }
+ 
+ bar <- function() {
+   winch_trace_back()
+ }
+ 
+ foo()
+ ## Don't show: 
+ }) # examplesIf
> winch_trace_back()
Error in winch_trace_back() : unw_getcontext() error: -1073785400
Calls: <Anonymous> ... source -> withVisible -> eval -> eval -> winch_trace_back
Execution halted

P. S. This error is independent of the fact that present macho.c code is missing two archs. I have tried both with unmodified version and with fixed source for macho.c, error is identical.

add_trace_back doesn't work correctly on 32-bit systems

On i686 and armv7hl, the tests in test-add_trace_back.R fail and seem to be missing some bits of the traceback. winch also outputs a warning of libR not found in backtrace, can't merge.

Revdep issue with vctrs

Is this ran on CRAN machines?

  Loading required package: vctrs
  Error in winch::winch_init_library(vctrs:::vctrs_init$dll[["path"]]) : 
    object 'vctrs_init' not found

print backtrace on crash?

I put together a small experiment using gdb to print a backtrace when the process crashes. The core implementation lives here:

https://github.com/kevinushey/mortem/blob/main/src/mortem.c

I wonder if winch could consider doing something similar; that is, register some signal handlers for fatal / deadly signals, and then use winch / libbacktrace to print a stack trace when that crash occurs?

This could be especially useful in debugging CI crashes.

Fix r-universe build

r-universe/r-prof#1