Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ARROW-17859: [C++] Use self-pipe in signal-receiving StopSource #14250

Merged
merged 8 commits into from
Nov 23, 2022

Conversation

pitrou
Copy link
Member

@pitrou pitrou commented Sep 27, 2022

No description provided.

@pitrou

This comment was marked as outdated.

@pitrou
Copy link
Member Author

pitrou commented Sep 27, 2022

@paleolimbot Could you try R cancellation with this PR?

@paleolimbot
Copy link
Member

Cancellation works exactly the same on this branch as it does on the master branch!

It's probably not related to this PR, but it looks like attempting to call arrow from a forked process in R doesn't work. I think this is the same on the master branch (will check tomorrow).

library(arrow, warn.conflicts = FALSE)
#> Some features are not enabled in this build of Arrow. Run `arrow_info()` for more information.

tf <- tempfile()
readr::write_csv(vctrs::vec_rep(mtcars, 5e5), tf)

# try to slow down CSV reading
set_cpu_count(1)
set_io_thread_count(2)

# see if arrow actually works in a forked R process (it doesn't)
parallel::mclapply(1:4, function(...) read_csv_arrow(tf))
#> Warning in parallel::mclapply(1:4, function(...) read_csv_arrow(tf)): all
#> scheduled cores encountered errors in user code
#> [[1]]
#> [1] "Error in as.data.frame(tab) : object 'tab' not found\n"
#> attr(,"class")
#> [1] "try-error"
#> attr(,"condition")
#> <simpleError in as.data.frame(tab): object 'tab' not found>
#> 
#> [[2]]
#> [1] "Error in as.data.frame(tab) : object 'tab' not found\n"
#> attr(,"class")
#> [1] "try-error"
#> attr(,"condition")
#> <simpleError in as.data.frame(tab): object 'tab' not found>
#> 
#> [[3]]
#> [1] "Error in as.data.frame(tab) : object 'tab' not found\n"
#> attr(,"class")
#> [1] "try-error"
#> attr(,"condition")
#> <simpleError in as.data.frame(tab): object 'tab' not found>
#> 
#> [[4]]
#> [1] "Error in as.data.frame(tab) : object 'tab' not found\n"
#> attr(,"class")
#> [1] "try-error"
#> attr(,"condition")
#> <simpleError in as.data.frame(tab): object 'tab' not found>

Created on 2022-09-27 by the reprex package (v2.0.1)

@pitrou
Copy link
Member Author

pitrou commented Sep 27, 2022

"object 'tab' not found" is purely an R error? It looks weird.

@paleolimbot
Copy link
Member

Ok, the R error was a bug in our error "helper" that was obscuring an actual real related error.

This PR doesn't affect cancellation in the original process, but it does result in errors in a forked process (probably something I have to fix on that PR?):

library(arrow, warn.conflicts = FALSE)
#> Some features are not enabled in this build of Arrow. Run `arrow_info()` for more information.

tf <- tempfile()
readr::write_csv(vctrs::vec_rep(mtcars, 5e5), tf)

# try to slow down CSV reading
set_cpu_count(1)
set_io_thread_count(2)

# see if arrow actually works in a forked R process (it doesn't)
parallel::mclapply(1:2, function(...) read_csv_arrow(tf))
#> Warning in parallel::mclapply(1:2, function(...) read_csv_arrow(tf)): all
#> scheduled cores encountered errors in user code
#> [[1]]
#> [1] "Error in (function (file, delim = \",\", quote = \"\\\"\", escape_double = TRUE,  : \n  Invalid: Signal stop source was not set up\nCaused by error:\n! Invalid: Signal stop source was not set up\n"
#> attr(,"class")
#> [1] "try-error"
#> attr(,"condition")
#> <error/rlang_error>
#> Error:
#> ! Invalid: Signal stop source was not set up
#> Caused by error:
#> ! Invalid: Signal stop source was not set up
#> ---
#> Backtrace:
#>   1. parallel::mclapply(1:2, function(...) read_csv_arrow(tf))
#>   2. base::lapply(seq_len(cores), inner.do)
#>   3. parallel (local) FUN(X[[i]], ...)
#>  10. base::lapply(X = S, FUN = FUN, ...)
#>  11. global FUN(X[[i]], ...)
#>  16. arrow (local) `<fn>`(file = tf, delim = ",")
#> 
#> [[2]]
#> [1] "Error in (function (file, delim = \",\", quote = \"\\\"\", escape_double = TRUE,  : \n  Invalid: Signal stop source was not set up\nCaused by error:\n! Invalid: Signal stop source was not set up\n"
#> attr(,"class")
#> [1] "try-error"
#> attr(,"condition")
#> <error/rlang_error>
#> Error:
#> ! Invalid: Signal stop source was not set up
#> Caused by error:
#> ! Invalid: Signal stop source was not set up
#> ---
#> Backtrace:
#>   1. parallel::mclapply(1:2, function(...) read_csv_arrow(tf))
#>   2. base::lapply(seq_len(cores), inner.do)
#>   3. parallel (local) FUN(X[[i]], ...)
#>  10. base::lapply(X = S, FUN = FUN, ...)
#>  11. global FUN(X[[i]], ...)
#>  16. arrow (local) `<fn>`(file = tf, delim = ",")

Created on 2022-09-28 by the reprex package (v2.0.1)

@pitrou
Copy link
Member Author

pitrou commented Sep 28, 2022

Thanks for checking @paleolimbot . That's setting that might be fixed on the C++ side. I'll think about it.

@paleolimbot
Copy link
Member

I updated #13635 so that it just warns here instead of erroring. The gist of that is that the StopSource() that I have saved is not null; however, calling RegisterCancellingSignalHandler() errors saying that it is not set up.

If the stop token didn't live with the filesystem it probably wouldn't be an issue because the process in general would never be forked before a cancellable operation was invoked (although I'm sure somebody will try to use mclapply() in a user-defined function at some point, so it should still probably not error).

@paleolimbot
Copy link
Member

I'm getting other crashes on this PR and so it may not be related, but in case it is, there's a crash using Flight from Python from R next to a bunch of messages about the StopSource already being set up.

https://github.com/apache/arrow/actions/runs/3190877134/jobs/5206531644

Start test: flight_get
/arrow/cpp/src/arrow/status.cc:134: Invalid: Signal stop source already set up
  test-python-flight.R:56:5 [success]
End test: flight_get

Start test: flight_put with RecordBatch
/arrow/cpp/src/arrow/status.cc:134: Invalid: Signal stop source already set up
  test-python-flight.R:62:5 [success]
End test: flight_put with RecordBatch

Start test: flight_put with overwrite = FALSE
  test-python-flight.R:66:5 [success]

@pitrou
Copy link
Member Author

pitrou commented Oct 5, 2022

Well, in any case I'll need to rebase and also complete the TODOs above.

@github-actions
Copy link

@github-actions
Copy link

⚠️ Ticket has not been started in JIRA, please click 'Start Progress'.

@pitrou pitrou force-pushed the ARROW-17859-signal-self-pipe branch from c5478a5 to 9e2bf2d Compare October 10, 2022 15:51
@pitrou pitrou marked this pull request as ready for review October 10, 2022 16:04
@pitrou

This comment was marked as outdated.

@pitrou
Copy link
Member Author

pitrou commented Oct 10, 2022

@paleolimbot Would you like to try out this PR again?

@pitrou pitrou force-pushed the ARROW-17859-signal-self-pipe branch from 9e2bf2d to 7913919 Compare October 11, 2022 08:46
@pitrou

This comment was marked as outdated.

@paleolimbot
Copy link
Member

I'll investigate more when I'm back from PTO on Monday, but I did a quick check and (1) cancellation still works interactively and (2) this does seem to break forked process behaviour when using R + arrow:

library(arrow, warn.conflicts = FALSE)
#> Some features are not enabled in this build of Arrow. Run `arrow_info()` for more information.

tf <- tempfile()
readr::write_csv(vctrs::vec_rep(mtcars, 5e5), tf)

# try to slow down CSV reading
set_cpu_count(1)
set_io_thread_count(2)

# make sure we can cancel
read_csv_arrow(tf)
#> # A tibble: 16,000,000 × 11
#>      mpg   cyl  disp    hp  drat    wt  qsec    vs    am  gear  carb
#>    <dbl> <int> <dbl> <int> <dbl> <dbl> <dbl> <int> <int> <int> <int>
#>  1  21       6  160    110  3.9   2.62  16.5     0     1     4     4
#>  2  21       6  160    110  3.9   2.88  17.0     0     1     4     4
#>  3  22.8     4  108     93  3.85  2.32  18.6     1     1     4     1
#>  4  21.4     6  258    110  3.08  3.22  19.4     1     0     3     1
#>  5  18.7     8  360    175  3.15  3.44  17.0     0     0     3     2
#>  6  18.1     6  225    105  2.76  3.46  20.2     1     0     3     1
#>  7  14.3     8  360    245  3.21  3.57  15.8     0     0     3     4
#>  8  24.4     4  147.    62  3.69  3.19  20       1     0     4     2
#>  9  22.8     4  141.    95  3.92  3.15  22.9     1     0     4     2
#> 10  19.2     6  168.   123  3.92  3.44  18.3     1     0     4     4
#> # … with 15,999,990 more rows

# see if arrow works in a forked R process
parallel::mclapply(1:2, function(...) read_csv_arrow(tf))
#> Warning in parallel::mclapply(1:2, function(...) read_csv_arrow(tf)): scheduled
#> cores 1, 2 did not deliver results, all values of the jobs will be affected
#> [[1]]
#> NULL
#> 
#> [[2]]
#> NULL

Created on 2022-10-11 by the reprex package (v2.0.1)

@paleolimbot
Copy link
Member

Ok, I checked this again, and the errors that I get are:

/Users/dewey/Desktop/rscratch/arrow/cpp/src/arrow/status.cc:134: Invalid: Signal stop source was not set up
/Users/dewey/Desktop/rscratch/arrow/cpp/src/arrow/status.cc:134: Invalid: Signal stop source was not set up

In the code in the R package, I'm careful not error (but instead warn) on the result of RegisterCancellingSignalHandler(), and so I wonder if this is coming from C++ instead?

I would still prefer to not mess with signal handling in the R package since I have a limited ability to debug this myself. I'm aware that I have a poor understanding of the constraints here, but the R package could probably provide a thread-safe callable like bool (*should_we_stop)(void) and avoid imposing the constraints of R on this section of Arrow C++.

@pitrou
Copy link
Member Author

pitrou commented Oct 31, 2022 via email

@paleolimbot
Copy link
Member

The sequence is (for better or worse):

  • Package load: create stop source
  • Every R call into C++ that launches a new thread: register signal handlers
  • For every C++ call into R via SafeCallIntoR, unregister signal handlers for the duration of the call (this might not be necessary)
  • When the R call into C++ returns control to R, unregister signal handlers
  • On package unload (usually when the process is about to end), destroy the stop source

@paleolimbot
Copy link
Member

I don't know, can you try to turn this error into an abort and get a debugger backtrace?

I can look into how to do this tomorrow; off the top of my head I don't have something set up to do this. Usually I get a full backtrace with my errors because I have the extra error context turned on, and I don't know why it's not appearing here.

@paleolimbot
Copy link
Member

Oh, and the error is and abort, it just happens in a worker process so R reports it as a warning.

@paleolimbot
Copy link
Member

It also should be said that mclapply() is not commonly used with Arrow, I just happened to know that it forked the process and it seems like there should be a path to it working (even if that path is disabling cancellation in R).

@pitrou
Copy link
Member Author

pitrou commented Oct 31, 2022

The sequence is (for better or worse):

Can you describe where the fork() call happens in that sequence?

@paleolimbot
Copy link
Member

paleolimbot commented Nov 1, 2022

In the example I've been using the sequence is (I think)

  • Package load: create stop source
  • (do some Arrow setup stuff)
  • Use fork() to create workers in mclapply() and on each worker
    • Every R call into C++ that launches a new thread: register signal handlers
    • For every C++ call into R via SafeCallIntoR, unregister signal handlers for the duration of the call (this might not be necessary)
    • When the R call into C++ returns control to R, unregister signal handlers
    • On package unload (usually when the process is about to end), destroy the stop source
  • On package unload (usually when the process is about to end), destroy the stop source

I did another check, and it looks like the thing that "breaks" the mclapply behaviour is doing anything that registers signal handlers on the main thread before launching the workers:

library(arrow, warn.conflicts = FALSE)
#> Some features are not enabled in this build of Arrow. Run `arrow_info()` for more information.

tf <- tempfile()
write.csv(mtcars, tf, row.names = FALSE)

# If we use the signal handling infrastructure in the main process before
# doing the forked workers thing, then the calls will fail
# read_csv_arrow(tf)

parallel::mclapply(1:2, function(...) {
  read_csv_arrow(tf)
})
#> [[1]]
#> # A tibble: 32 × 11
#>      mpg   cyl  disp    hp  drat    wt  qsec    vs    am  gear  carb
#>    <dbl> <int> <dbl> <int> <dbl> <dbl> <dbl> <int> <int> <int> <int>
#>  1  21       6  160    110  3.9   2.62  16.5     0     1     4     4
#>  2  21       6  160    110  3.9   2.88  17.0     0     1     4     4
#>  3  22.8     4  108     93  3.85  2.32  18.6     1     1     4     1
#>  4  21.4     6  258    110  3.08  3.22  19.4     1     0     3     1
#>  5  18.7     8  360    175  3.15  3.44  17.0     0     0     3     2
#>  6  18.1     6  225    105  2.76  3.46  20.2     1     0     3     1
#>  7  14.3     8  360    245  3.21  3.57  15.8     0     0     3     4
#>  8  24.4     4  147.    62  3.69  3.19  20       1     0     4     2
#>  9  22.8     4  141.    95  3.92  3.15  22.9     1     0     4     2
#> 10  19.2     6  168.   123  3.92  3.44  18.3     1     0     4     4
#> # … with 22 more rows
#> 
#> [[2]]
#> # A tibble: 32 × 11
#>      mpg   cyl  disp    hp  drat    wt  qsec    vs    am  gear  carb
#>    <dbl> <int> <dbl> <int> <dbl> <dbl> <dbl> <int> <int> <int> <int>
#>  1  21       6  160    110  3.9   2.62  16.5     0     1     4     4
#>  2  21       6  160    110  3.9   2.88  17.0     0     1     4     4
#>  3  22.8     4  108     93  3.85  2.32  18.6     1     1     4     1
#>  4  21.4     6  258    110  3.08  3.22  19.4     1     0     3     1
#>  5  18.7     8  360    175  3.15  3.44  17.0     0     0     3     2
#>  6  18.1     6  225    105  2.76  3.46  20.2     1     0     3     1
#>  7  14.3     8  360    245  3.21  3.57  15.8     0     0     3     4
#>  8  24.4     4  147.    62  3.69  3.19  20       1     0     4     2
#>  9  22.8     4  141.    95  3.92  3.15  22.9     1     0     4     2
#> 10  19.2     6  168.   123  3.92  3.44  18.3     1     0     4     4
#> # … with 22 more rows

Created on 2022-11-01 with reprex v2.0.2

@pitrou
Copy link
Member Author

pitrou commented Nov 7, 2022

I'll update this to use the at-fork facility introduced in #14594

@pitrou pitrou force-pushed the ARROW-17859-signal-self-pipe branch from 7913919 to 9ef40c2 Compare November 14, 2022 15:01
@paleolimbot
Copy link
Member

Yes, those are in the child process.

@pitrou
Copy link
Member Author

pitrou commented Nov 22, 2022

I just looked up the new PIDs that popped up and attached lldb one of them...it doesn't take a special R package build

Hmm, ok. Since I'm a R newbie, can you tell me how to run the reproducer code exactly? :-)

@paleolimbot
Copy link
Member

paleolimbot commented Nov 22, 2022

can you tell me how to run the reproducer code exactly? :-)

What I did was:

  1. Checkout your branch
  2. Build + install the C++ library. The R package needs a folder with something/include and something/lib where the ARROW_HOME environment variable is set to "something".
  3. You'll need R (apt-get install r-base is an old version but works) + the package deps. The easiest way to get them is to install the version of arrow from CRAN before installing the one for your branch (R -e 'install.packages("arrow", repos = "https://cloud.r-project.org")'. This Dockerfile might be helpful: https://gist.github.com/paleolimbot/be77218201bdbd20353c084c74254824
  4. cd path/to/arrow/r && R CMD INSTALL .
  5. Open an interactive terminal, type in R, copy/paste this:
library(arrow, warn.conflicts = FALSE)

tf <- tempfile()
write.csv(mtcars, tf, row.names = FALSE)

read_csv_arrow(tf)

parallel::mclapply(1:2, function(...) {
  read_csv_arrow(tf)
})

Here's maybe some more raw output from lldb:


Console is in 'commands' mode, prefix expressions with '?'.
Attached to process 81057
Stop reason: signal SIGSTOP
t 1

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00000001b114e270 libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x00000001b118883c libsystem_pthread.dylib`_pthread_cond_wait + 1236
    frame #2: 0x00000001b10d7284 libc++.1.dylib`std::__1::condition_variable::wait(std::__1::unique_lock<std::__1::mutex>&) + 28
    frame #3: 0x00000002807fd8c0 libarrow.1100.0.0.dylib`void std::__1::condition_variable::wait<arrow::internal::SerialExecutor::RunLoop()::$_0>(this=0x0000000152e92578, __lk=0x000000016b48a638, __pred=(0x000000016b48a6a8))::$_0) at __mutex_base:404:9
    frame #4: 0x00000002807fcf14 libarrow.1100.0.0.dylib`arrow::internal::SerialExecutor::RunLoop(this=0x000000016b48a6a8) at thread_pool.cc:174:28
    frame #5: 0x00000001090bdda4 arrow.so`arrow::Future<std::__1::shared_ptr<arrow::Table>> arrow::internal::SerialExecutor::Run<std::__1::shared_ptr<arrow::Table>, arrow::Result<std::__1::shared_ptr<arrow::Table>>>(this=0x000000016b48a6a8, initial_task=arrow::internal::SerialExecutor::TopLevelTask<std::__1::shared_ptr<arrow::Table> > @ 0x000000016b48a6a0)>) at thread_pool.h:392:5 [opt]
    frame #6: 0x00000001090bd97c arrow.so`arrow::Result<std::__1::shared_ptr<arrow::Table>> arrow::internal::SerialExecutor::RunInSerialExecutor<std::__1::shared_ptr<arrow::Table>, arrow::Future<std::__1::shared_ptr<arrow::Table>>, arrow::Result<std::__1::shared_ptr<arrow::Table>>>(initial_task=arrow::internal::SerialExecutor::TopLevelTask<std::__1::shared_ptr<arrow::Table> > @ 0x000000016b48a700)>) at thread_pool.h:289:38 [opt]
    frame #7: 0x00000001090bd724 arrow.so`arrow::Result<std::__1::shared_ptr<arrow::Table>> RunWithCapturedR<std::__1::shared_ptr<arrow::Table>>(make_arrow_call=function<arrow::Future<std::__1::shared_ptr<arrow::Table> > ()> @ 0x000000016b48a798)>) at safe-call-into-r.h:287:29 [opt]
    frame #8: 0x00000001090ae3dc arrow.so`arrow::Result<std::__1::shared_ptr<arrow::Table>> RunWithCapturedRIfPossible<std::__1::shared_ptr<arrow::Table>>(make_arrow_call=function<arrow::Result<std::__1::shared_ptr<arrow::Table> > ()> @ 0x000000016b48a7f0)>) at safe-call-into-r.h:314:12 [opt]
    frame #9: 0x00000001090dd084 arrow.so`csv___TableReader__Read(table_reader=<unavailable>) at csv.cpp:165:17 [opt]
    frame #10: 0x0000000109062268 arrow.so`::_arrow_csv___TableReader__Read(table_reader_sexp=<unavailable>) at arrowExports.cpp:1265:24 [opt]
    frame #11: 0x0000000106065be4 libR.dylib`R_doDotCall(ofun=<unavailable>, nargs=<unavailable>, cargs=<unavailable>, call=0x00000001335a5318) at dotcode.c:601:17 [opt]
    frame #12: 0x00000001060ae2dc libR.dylib`bcEval(body=0x00000001335ab778, rho=<unavailable>, useCache=<unavailable>) at eval.c:7692:21 [opt]
    frame #13: 0x0000000106094588 libR.dylib`Rf_eval(e=0x00000001335ab778, rho=0x00000001127e7660) at eval.c:748:8 [opt]
    frame #14: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001336bac50, newrho=0x00000001127e7660, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #15: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001336bac50, op=0x00000001335b1270, arglist=0x00000001127e76d0, rho=0x00000001127e7778, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #16: 0x000000010609485c libR.dylib`Rf_eval(e=0x00000001336bac50, rho=0x00000001127e7778) at eval.c:871:12 [opt]
    frame #17: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001254fd078, newrho=0x00000001127e7778, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #18: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001254fd078, op=0x00000001127d4d68, arglist=0x0000000153816ce0, rho=0x000000011272f5b8, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #19: 0x000000010609b770 libR.dylib`bcEval(body=0x00000001255135e0, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #20: 0x0000000106094588 libR.dylib`Rf_eval(e=0x00000001255135e0, rho=0x000000011272f5b8) at eval.c:748:8 [opt]
    frame #21: 0x00000001060afae4 libR.dylib`forcePromise(e=0x00000001127e2d68) at eval.c:568:8 [opt]
    frame #22: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x00000001127e2d68, symbol=0x0000000153866750, rho=0x00000001127e2ba8, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #23: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x00000001127e2ba8, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #24: 0x0000000106098b50 libR.dylib`bcEval(body=0x000000015319a230, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #25: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015319a230, rho=0x00000001127e2ba8) at eval.c:748:8 [opt]
    frame #26: 0x00000001060afae4 libR.dylib`forcePromise(e=0x00000001127e2748) at eval.c:568:8 [opt]
    frame #27: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x00000001127e2748, symbol=0x0000000153866750, rho=0x00000001127e24a8, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #28: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x00000001127e24a8, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #29: 0x0000000106098b50 libR.dylib`bcEval(body=0x0000000153196090, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #30: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153196090, rho=0x00000001127e24a8) at eval.c:748:8 [opt]
    frame #31: 0x00000001060afae4 libR.dylib`forcePromise(e=0x00000001127e2400) at eval.c:568:8 [opt]
    frame #32: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x00000001127e2400, symbol=0x0000000153866750, rho=0x00000001127e8070, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #33: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x00000001127e8070, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #34: 0x0000000106098b50 libR.dylib`bcEval(body=0x000000015319a578, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #35: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015319a578, rho=0x00000001127e8070) at eval.c:748:8 [opt]
    frame #36: 0x00000001060afae4 libR.dylib`forcePromise(e=0x00000001127e7fc8) at eval.c:568:8 [opt]
    frame #37: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x00000001127e7fc8, symbol=0x0000000153866750, rho=0x00000001127e7d28, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #38: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x00000001127e7d28, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #39: 0x0000000106098b50 libR.dylib`bcEval(body=0x000000015319a8f8, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #40: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015319a8f8, rho=0x00000001127e7d28) at eval.c:748:8 [opt]
    frame #41: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000015319bbc8, newrho=0x00000001127e7d28, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #42: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000015319bbc8, op=0x00000001127e8038, arglist=0x00000001127e7f90, rho=0x00000001127e8070, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #43: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000153195db8, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #44: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153195db8, rho=0x00000001127e8070) at eval.c:748:8 [opt]
    frame #45: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x0000000153196608, newrho=0x00000001127e8070, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #46: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x0000000153196608, op=0x00000001127e2b00, arglist=0x00000001127e23c8, rho=0x00000001127e24a8, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #47: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000153197088, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #48: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153197088, rho=0x00000001127e24a8) at eval.c:748:8 [opt]
    frame #49: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x0000000153197280, newrho=0x00000001127e24a8, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #50: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x0000000153197280, op=0x00000001127e2b70, arglist=0x00000001127e2710, rho=0x00000001127e2ba8, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #51: 0x000000010609b770 libR.dylib`bcEval(body=0x000000015318a3f0, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #52: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015318a3f0, rho=0x00000001127e2ba8) at eval.c:748:8 [opt]
    frame #53: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001254fd200, newrho=0x00000001127e2ba8, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #54: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001254fd200, op=0x000000015318a540, arglist=0x00000001127e2d30, rho=0x000000011272f5b8, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #55: 0x000000010609b770 libR.dylib`bcEval(body=0x00000001254e9498, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #56: 0x0000000106094588 libR.dylib`Rf_eval(e=0x00000001254e9498, rho=0x000000011272f5b8) at eval.c:748:8 [opt]
    frame #57: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000011272ca58, newrho=0x000000011272f5b8, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #58: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000011272ca58, op=0x00000001254ea308, arglist=0x000000011272fa50, rho=0x000000011272a2b0, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #59: 0x000000010609485c libR.dylib`Rf_eval(e=0x000000011272ca58, rho=0x000000011272a2b0) at eval.c:871:12 [opt]
    frame #60: 0x00000001060b5d4c libR.dylib`do_eval(call=<unavailable>, op=0x0000000153837290, args=0x000000011272fbd8, rho=<unavailable>) at eval.c:3366:13 [opt]
    frame #61: 0x000000010609bf80 libR.dylib`bcEval(body=0x0000000153873608, rho=<unavailable>, useCache=<unavailable>) at eval.c:7136:14 [opt]
    frame #62: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153873608, rho=0x000000011272fc48) at eval.c:748:8 [opt]
    frame #63: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001539179a8, newrho=0x000000011272fc48, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #64: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001539179a8, op=0x00000001539170e8, arglist=0x000000011272fd98, rho=0x000000011272ff90, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #65: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000153917cb8, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #66: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153917cb8, rho=0x000000011272ff90) at eval.c:748:8 [opt]
    frame #67: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001254e5448, newrho=0x000000011272ff90, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #68: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001254e5448, op=0x0000000153917d60, arglist=0x0000000112730038, rho=0x000000011272dd28, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #69: 0x000000010609b770 libR.dylib`bcEval(body=0x00000001254e00d0, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #70: 0x0000000106094588 libR.dylib`Rf_eval(e=0x00000001254e00d0, rho=0x000000011272dd28) at eval.c:748:8 [opt]
    frame #71: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x0000000112711708, newrho=0x000000011272dd28, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #72: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x0000000112711708, op=0x00000001254de3a8, arglist=0x000000011272a208, rho=0x000000011272a2b0, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #73: 0x000000010609485c libR.dylib`Rf_eval(e=0x0000000112711708, rho=0x000000011272a2b0) at eval.c:871:12 [opt]
    frame #74: 0x00000001060b4324 libR.dylib`do_begin(call=0x00000001127116d0, op=0x0000000153820320, args=0x00000001127115b8, rho=0x000000011272a2b0) at eval.c:2539:10 [opt]
    frame #75: 0x0000000106094788 libR.dylib`Rf_eval(e=0x00000001127116d0, rho=0x000000011272a2b0) at eval.c:823:12 [opt]
    frame #76: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000011272a4a8, newrho=0x000000011272a2b0, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #77: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000011272a4a8, op=0x000000011272a710, arglist=0x000000011272a3c8, rho=0x000000011272a898, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #78: 0x00000001060b23dc libR.dylib`R_forceAndCall(e=0x000000011272a4a8, n=1, rho=0x000000011272a898) at eval.c:1985:8 [opt]
    frame #79: 0x0000000105ffaa98 libR.dylib`do_lapply(call=<unavailable>, op=<unavailable>, args=<unavailable>, rho=0x000000011272a898) at apply.c:75:8 [opt]
    frame #80: 0x00000001060faed0 libR.dylib`do_internal(call=<unavailable>, op=<unavailable>, args=<unavailable>, env=0x000000011272a898) at names.c:1399:11 [opt]
    frame #81: 0x000000010609c170 libR.dylib`bcEval(body=0x0000000153938b28, rho=<unavailable>, useCache=<unavailable>) at eval.c:7156:15 [opt]
    frame #82: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153938b28, rho=0x000000011272a898) at eval.c:748:8 [opt]
    frame #83: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000012308c278, newrho=0x000000011272a898, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #84: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000012308c278, op=0x0000000153938c08, arglist=0x000000011272a9e8, rho=0x000000011271c390, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #85: 0x000000010609b770 libR.dylib`bcEval(body=0x000000012308aec8, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #86: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000012308aec8, rho=0x000000011271c390) at eval.c:748:8 [opt]
    frame #87: 0x00000001060afae4 libR.dylib`forcePromise(e=0x000000011272bd98) at eval.c:568:8 [opt]
    frame #88: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x000000011272bd98, symbol=0x0000000153866750, rho=0x000000011272bc48, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #89: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x000000011272bc48, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #90: 0x0000000106098b50 libR.dylib`bcEval(body=0x0000000153410f48, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #91: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153410f48, rho=0x000000011272bc48) at eval.c:748:8 [opt]
    frame #92: 0x00000001060afae4 libR.dylib`forcePromise(e=0x000000011272bbd8) at eval.c:568:8 [opt]
    frame #93: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x000000011272bbd8, symbol=0x0000000153866750, rho=0x000000011272ba18, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #94: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x000000011272ba18, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #95: 0x0000000106098b50 libR.dylib`bcEval(body=0x000000015319a230, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #96: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015319a230, rho=0x000000011272ba18) at eval.c:748:8 [opt]
    frame #97: 0x00000001060afae4 libR.dylib`forcePromise(e=0x000000011272b5f0) at eval.c:568:8 [opt]
    frame #98: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x000000011272b5f0, symbol=0x0000000153866750, rho=0x000000011272b350, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #99: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x000000011272b350, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #100: 0x0000000106098b50 libR.dylib`bcEval(body=0x0000000153196090, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #101: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153196090, rho=0x000000011272b350) at eval.c:748:8 [opt]
    frame #102: 0x00000001060afae4 libR.dylib`forcePromise(e=0x000000011272b2a8) at eval.c:568:8 [opt]
    frame #103: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x000000011272b2a8, symbol=0x0000000153866750, rho=0x000000011272b008, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #104: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x000000011272b008, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #105: 0x0000000106098b50 libR.dylib`bcEval(body=0x000000015319a578, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #106: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015319a578, rho=0x000000011272b008) at eval.c:748:8 [opt]
    frame #107: 0x00000001060afae4 libR.dylib`forcePromise(e=0x000000011272af60) at eval.c:568:8 [opt]
    frame #108: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x000000011272af60, symbol=0x0000000153866750, rho=0x000000011272acc0, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #109: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153866750, rho=0x000000011272acc0, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #110: 0x0000000106098b50 libR.dylib`bcEval(body=0x000000015319a8f8, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #111: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015319a8f8, rho=0x000000011272acc0) at eval.c:748:8 [opt]
    frame #112: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000015319bbc8, newrho=0x000000011272acc0, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #113: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000015319bbc8, op=0x000000011272afd0, arglist=0x000000011272af28, rho=0x000000011272b008, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #114: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000153195db8, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #115: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153195db8, rho=0x000000011272b008) at eval.c:748:8 [opt]
    frame #116: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x0000000153196608, newrho=0x000000011272b008, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #117: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x0000000153196608, op=0x000000011272b970, arglist=0x000000011272b270, rho=0x000000011272b350, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #118: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000153197088, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #119: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153197088, rho=0x000000011272b350) at eval.c:748:8 [opt]
    frame #120: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x0000000153197280, newrho=0x000000011272b350, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #121: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x0000000153197280, op=0x000000011272b9e0, arglist=0x000000011272b5b8, rho=0x000000011272ba18, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #122: 0x000000010609b770 libR.dylib`bcEval(body=0x000000015318a3f0, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #123: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000015318a3f0, rho=0x000000011272ba18) at eval.c:748:8 [opt]
    frame #124: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x0000000153407990, newrho=0x000000011272ba18, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #125: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x0000000153407990, op=0x000000015318a540, arglist=0x000000011272bba0, rho=0x000000011272bc48, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #126: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000153407a38, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #127: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153407a38, rho=0x000000011272bc48) at eval.c:748:8 [opt]
    frame #128: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000012308c358, newrho=0x000000011272bc48, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #129: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000012308c358, op=0x0000000153407cd8, arglist=0x000000011272bd60, rho=0x000000011271c390, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #130: 0x000000010609b770 libR.dylib`bcEval(body=0x000000012308b018, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #131: 0x0000000106094588 libR.dylib`Rf_eval(e=0x000000012308b018, rho=0x000000011271c390) at eval.c:748:8 [opt]
    frame #132: 0x00000001060afae4 libR.dylib`forcePromise(e=0x000000011272bf20) at eval.c:568:8 [opt]
    frame #133: 0x00000001060bb9b8 libR.dylib`getvar [inlined] FORCE_PROMISE(value=0x000000011272bf20, symbol=0x0000000153a95ee0, rho=0x000000011272be40, keepmiss=FALSE) at eval.c:5157:15 [opt]
    frame #134: 0x00000001060bb9b0 libR.dylib`getvar(symbol=0x0000000153a95ee0, rho=0x000000011272be40, dd=<unavailable>, keepmiss=FALSE, vcache=<unavailable>, sidx=<unavailable>) at eval.c:5198:14 [opt]
    frame #135: 0x0000000106098b50 libR.dylib`bcEval(body=0x0000000112728668, rho=<unavailable>, useCache=<unavailable>) at eval.c:6888:20 [opt]
    frame #136: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000112728668, rho=0x000000011272be40) at eval.c:748:8 [opt]
    frame #137: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000012308c400, newrho=0x000000011272be40, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #138: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000012308c400, op=0x0000000112728a90, arglist=0x000000011272bee8, rho=0x000000011271c390, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #139: 0x000000010609b770 libR.dylib`bcEval(body=0x00000001230a1640, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #140: 0x0000000106094588 libR.dylib`Rf_eval(e=0x00000001230a1640, rho=0x000000011271c390) at eval.c:748:8 [opt]
    frame #141: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x000000011271a390, newrho=0x000000011271c390, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #142: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x000000011271a390, op=0x000000011271a940, arglist=0x000000011271c470, rho=0x000000011271a748, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #143: 0x00000001060b23dc libR.dylib`R_forceAndCall(e=0x000000011271a390, n=1, rho=0x000000011271a748) at eval.c:1985:8 [opt]
    frame #144: 0x0000000105ffaa98 libR.dylib`do_lapply(call=<unavailable>, op=<unavailable>, args=<unavailable>, rho=0x000000011271a748) at apply.c:75:8 [opt]
    frame #145: 0x00000001060faed0 libR.dylib`do_internal(call=<unavailable>, op=<unavailable>, args=<unavailable>, env=0x000000011271a748) at names.c:1399:11 [opt]
    frame #146: 0x000000010609c170 libR.dylib`bcEval(body=0x0000000153938b28, rho=<unavailable>, useCache=<unavailable>) at eval.c:7156:15 [opt]
    frame #147: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000153938b28, rho=0x000000011271a748) at eval.c:748:8 [opt]
    frame #148: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001230bead8, newrho=0x000000011271a748, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #149: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001230bead8, op=0x0000000153938c08, arglist=0x000000011271a898, rho=0x0000000112710cc0, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #150: 0x000000010609b770 libR.dylib`bcEval(body=0x0000000133842c40, rho=<unavailable>, useCache=<unavailable>) at eval.c:7104:12 [opt]
    frame #151: 0x0000000106094588 libR.dylib`Rf_eval(e=0x0000000133842c40, rho=0x0000000112710cc0) at eval.c:748:8 [opt]
    frame #152: 0x00000001060b1b94 libR.dylib`R_execClosure(call=0x00000001127111c8, newrho=0x0000000112710cc0, sysparent=<unavailable>, rho=<unavailable>, arglist=<unavailable>, op=<unavailable>) at eval.c:0 [opt]
    frame #153: 0x00000001060b03cc libR.dylib`Rf_applyClosure(call=0x00000001127111c8, op=0x00000001338438f0, arglist=0x0000000112710f98, rho=0x00000001538504c8, suppliedvars=<unavailable>) at eval.c:1844:16 [opt]
    frame #154: 0x000000010609485c libR.dylib`Rf_eval(e=0x00000001127111c8, rho=0x00000001538504c8) at eval.c:871:12 [opt]
    frame #155: 0x00000001060e6d7c libR.dylib`Rf_ReplIteration(rho=0x00000001538504c8, savestack=<unavailable>, browselevel=<unavailable>, state=0x000000016b4a19a0) at main.c:264:2 [opt]
  
  frame #156: 0x00000001060e82ac libR.dylib`R_ReplConsole(rho=0x00000001538504c8, savestack=0, browselevel=0) at main.c:316:11 [opt]
    frame #157: 0x00000001060e81e4 libR.dylib`run_Rmainloop at main.c:1137:5 [opt]
    frame #158: 0x00000001060e8390 libR.dylib`Rf_mainloop at main.c:1144:5 [opt]
    frame #159: 0x00000001053bbe34 rsession-arm64`___lldb_unnamed_symbol29449 + 424
    frame #160: 0x0000000105392954 rsession-arm64`___lldb_unnamed_symbol28802 + 4424
    frame #161: 0x0000000104aa74b0 rsession-arm64`___lldb_unnamed_symbol5093 + 19664
    frame #162: 0x0000000105b6108c dyld`start + 520

t 2

bt
* thread #2
  * frame #0: 0x00000001b114b634 libsystem_kernel.dylib`read + 8
    frame #1: 0x00000002807c9be4 libarrow.1100.0.0.dylib`arrow::internal::(anonymous namespace)::SelfPipeImpl::Wait(this=0x00006000013e15a8) at io_util.cc:1268:24
    frame #2: 0x00000002807682f4 libarrow.1100.0.0.dylib`arrow::(anonymous namespace)::SignalStopState::ReceiveSignals(self_pipe=std::__1::shared_ptr<arrow::internal::SelfPipe>::element_type @ 0x00006000013e15a8 strong=3 weak=3) at cancel.cc:246:39
    frame #3: 0x0000000280769294 libarrow.1100.0.0.dylib`decltype(__f=0x0000000152e82008, __args=nullptr)(static_cast<std::__1::shared_ptr<arrow::internal::SelfPipe>>(fp0))) std::__1::__invoke<void (*)(std::__1::shared_ptr<arrow::internal::SelfPipe>), std::__1::shared_ptr<arrow::internal::SelfPipe>>(void (*&&)(std::__1::shared_ptr<arrow::internal::SelfPipe>), std::__1::shared_ptr<arrow::internal::SelfPipe>&&) at type_traits:3918:1
    frame #4: 0x000000028076920c libarrow.1100.0.0.dylib`void std::__1::__thread_execute<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(std::__1::shared_ptr<arrow::internal::SelfPipe>), std::__1::shared_ptr<arrow::internal::SelfPipe>, 2ul>(__t=size=3, (null)=__tuple_indices<2> @ 0x000000016c132f7f)(std::__1::shared_ptr<arrow::internal::SelfPipe>), std::__1::shared_ptr<arrow::internal::SelfPipe>>&, std::__1::__tuple_indices<2ul>) at thread:287:5

  frame #5: 0x00000002807688ac libarrow.1100.0.0.dylib`void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(std::__1::shared_ptr<arrow::internal::SelfPipe>), std::__1::shared_ptr<arrow::internal::SelfPipe>>>(__vp=0x0000000152e82000) at thread:298:5
    frame #6: 0x00000001b118826c libsystem_pthread.dylib`_pthread_start + 148

(edit: I fixed the bactraces to have both threads)

@pitrou
Copy link
Member Author

pitrou commented Nov 22, 2022

Okay, I'm certainly going to use one of the Docker configurations.
The problem is that it doesn't build R Arrow separately, it just runs this all-in-one script: https://github.com/apache/arrow/blob/master/ci/scripts/r_test.sh

Would you like to explain how I can modify that script to just build R Arrow but not run the whole gamut of checks/tests/etc.?

Edit: R CMD INSTALL . simply did the trick it seems.

@pitrou
Copy link
Member Author

pitrou commented Nov 22, 2022

@paleolimbot I see that the R Arrow bindings are compiled with -O2, is there a way to disable that to get better debugging?

@pitrou
Copy link
Member Author

pitrou commented Nov 22, 2022

By the way, I actually reproduce the issue on git master, so the issue is not specifically with this PR, right?

@pitrou
Copy link
Member Author

pitrou commented Nov 22, 2022

Last finding: things work fine with parallel::mclapply(1:1, function(...) { read_csv_arrow(tf) }), but not with parallel::mclapply(1:2, function(...) { read_csv_arrow(tf) }).

Edit: it simply seems to be because parallel::mclapply(1:1, ...) doesn't actually fork :-)

@paleolimbot
Copy link
Member

By the way, I actually reproduce the issue on git master, so the issue is not specifically with this PR, right?

When we started this conversation I had tried both and the hanging was specific to this PR, but very possible that some other code change affected that (I tested with Arrow 10.0.0 via install.packages("arrow") which included some cancellation features and this does work there). You're welcome to defer that to another PR but it's not something that I have any idea how to fix.

I am going to revisit the section of code that's hanging on the R side (specifically, I'm going to try avoiding the IO thread pool to launch the "do arrow stuff" thread) soon whilst trying to fix #14582 in a more permanent way and perhaps that may be a good time to revisit.

I see that the R Arrow bindings are compiled with -O2, is there a way to disable that to get better debugging?

Yes...I will add it to the Dockerfile later today. It's along the lines of mkdir ~/.R && echo "CXX17FLAGS := -g -O0" > .R/Makevars but it always takes me a few tries.

@pitrou
Copy link
Member Author

pitrou commented Nov 22, 2022

Ok, I think I've found the issue. It is a problem with initialization order of static/global variables in Arrow C++: #14704

@pitrou pitrou force-pushed the ARROW-17859-signal-self-pipe branch from 653a584 to 17b576d Compare November 23, 2022 16:20
@pitrou
Copy link
Member Author

pitrou commented Nov 23, 2022

I've rebased this now that #14704 is merged. @paleolimbot Can you check the cancellation behavior in R again?

@pitrou
Copy link
Member Author

pitrou commented Nov 23, 2022

@github-actions crossbow submit -g cpp -g python -g wheel

@github-actions
Copy link

Revision: 17b576d

Submitted crossbow builds: ursacomputing/crossbow @ actions-9e8fdbbef9

Task Status
test-alpine-linux-cpp Github Actions
test-build-cpp-fuzz Github Actions
test-conda-cpp Github Actions
test-conda-cpp-valgrind Azure
test-conda-python-3.10 Github Actions
test-conda-python-3.11 Github Actions
test-conda-python-3.7 Github Actions
test-conda-python-3.7-hdfs-2.9.2 Github Actions
test-conda-python-3.7-hdfs-3.2.1 Github Actions
test-conda-python-3.7-pandas-0.24 Github Actions
test-conda-python-3.7-pandas-latest Github Actions
test-conda-python-3.7-spark-v3.1.2 Github Actions
test-conda-python-3.8 Github Actions
test-conda-python-3.8-hypothesis Github Actions
test-conda-python-3.8-pandas-latest Github Actions
test-conda-python-3.8-pandas-nightly Github Actions
test-conda-python-3.8-spark-v3.2.0 Github Actions
test-conda-python-3.9 Github Actions
test-conda-python-3.9-dask-latest Github Actions
test-conda-python-3.9-dask-upstream_devel Github Actions
test-conda-python-3.9-pandas-upstream_devel Github Actions
test-conda-python-3.9-spark-master Github Actions
test-cuda-cpp Github Actions
test-cuda-python Github Actions
test-debian-10-cpp-amd64 Github Actions
test-debian-10-cpp-i386 Github Actions
test-debian-11-cpp-amd64 Github Actions
test-debian-11-cpp-i386 Github Actions
test-debian-11-python-3 Azure
test-fedora-35-cpp Github Actions
test-fedora-35-python-3 Azure
test-ubuntu-18.04-cpp Github Actions
test-ubuntu-18.04-cpp-release Github Actions
test-ubuntu-18.04-cpp-static Github Actions
test-ubuntu-20.04-cpp Github Actions
test-ubuntu-20.04-cpp-20 Github Actions
test-ubuntu-20.04-cpp-bundled Github Actions
test-ubuntu-20.04-cpp-thread-sanitizer Github Actions
test-ubuntu-20.04-python-3 Azure
test-ubuntu-22.04-cpp Github Actions
wheel-macos-big-sur-cp310-arm64 Github Actions
wheel-macos-big-sur-cp311-arm64 Github Actions
wheel-macos-big-sur-cp38-arm64 Github Actions
wheel-macos-big-sur-cp39-arm64 Github Actions
wheel-macos-mojave-cp310-amd64 Github Actions
wheel-macos-mojave-cp311-amd64 Github Actions
wheel-macos-mojave-cp37-amd64 Github Actions
wheel-macos-mojave-cp38-amd64 Github Actions
wheel-macos-mojave-cp39-amd64 Github Actions
wheel-manylinux2014-cp310-amd64 Github Actions
wheel-manylinux2014-cp310-arm64 Travis CI
wheel-manylinux2014-cp311-amd64 Github Actions
wheel-manylinux2014-cp311-arm64 Travis CI
wheel-manylinux2014-cp37-amd64 Github Actions
wheel-manylinux2014-cp37-arm64 Travis CI
wheel-manylinux2014-cp38-amd64 Github Actions
wheel-manylinux2014-cp38-arm64 Travis CI
wheel-manylinux2014-cp39-amd64 Github Actions
wheel-manylinux2014-cp39-arm64 Travis CI
wheel-windows-cp310-amd64 Github Actions
wheel-windows-cp311-amd64 Github Actions
wheel-windows-cp37-amd64 Github Actions
wheel-windows-cp38-amd64 Github Actions
wheel-windows-cp39-amd64 Github Actions

@paleolimbot
Copy link
Member

I checked the R behaviour again and using this build of Arrow I can (1) cancel CSV reading and ExecPlans and (2) use Arrow from a forked process (i.e., mclapply()). All good! Thank you!

@pitrou pitrou requested a review from lidavidm November 23, 2022 17:54
@pitrou pitrou merged commit 94e45fa into apache:master Nov 23, 2022
@pitrou pitrou deleted the ARROW-17859-signal-self-pipe branch November 23, 2022 21:58
@ursabot
Copy link

ursabot commented Nov 26, 2022

Benchmark runs are scheduled for baseline = ada7e23 and contender = 94e45fa. 94e45fa is a master commit associated with this PR. Results will be available as each benchmark for each run completes.
Conbench compare runs links:
[Finished ⬇️0.0% ⬆️0.0%] ec2-t3-xlarge-us-east-2
[Finished ⬇️0.4% ⬆️0.0%] test-mac-arm
[Finished ⬇️0.0% ⬆️0.0%] ursa-i9-9960x
[Finished ⬇️0.31% ⬆️0.03%] ursa-thinkcentre-m75q
Buildkite builds:
[Finished] 94e45faf ec2-t3-xlarge-us-east-2
[Finished] 94e45faf test-mac-arm
[Finished] 94e45faf ursa-i9-9960x
[Finished] 94e45faf ursa-thinkcentre-m75q
[Finished] ada7e239 ec2-t3-xlarge-us-east-2
[Finished] ada7e239 test-mac-arm
[Finished] ada7e239 ursa-i9-9960x
[Finished] ada7e239 ursa-thinkcentre-m75q
Supported benchmarks:
ec2-t3-xlarge-us-east-2: Supported benchmark langs: Python, R. Runs only benchmarks with cloud = True
test-mac-arm: Supported benchmark langs: C++, Python, R
ursa-i9-9960x: Supported benchmark langs: Python, R, JavaScript
ursa-thinkcentre-m75q: Supported benchmark langs: C++, Java

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants