[R] Intermittent valgrind failure

[asfimport]

A number of recent nightly builds have intermittent failures with valgrind, which fails because of possibly leaked memory around an exec plan. This seems related to a change in XXX that separated ExecPlan_prepare() from ExecPlan_run() and added a ExecPlan_read_table() that uses RunWithCapturedR(). The reported leaks vary but include ExecPlans and ExecNodes and fields of those objects.

A failed run: https://dev.azure.com/ursacomputing/crossbow/_build/results?buildId=30310&view=logs&j=0da5d1d9-276d-5173-c4c4-9d4d4ed14fdb&t=d9b15392-e4ce-5e4c-0c8c-b69645229181&l=24980

Some example output:

==5249== 14,112 (384 direct, 13,728 indirect) bytes in 1 blocks are definitely lost in loss record 1,988 of 3,883
==5249==    at 0x4849013: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==5249==    by 0x10B2902B: std::_Function_handler<arrow::Result<arrow::compute::ExecNode*> (arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&), arrow::compute::internal::RegisterAggregateNode(arrow::compute::ExecFactoryRegistry*)::{lambda(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&)#1}>::_M_invoke(std::_Any_data const&, arrow::compute::ExecPlan*&&, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >&&, arrow::compute::ExecNodeOptions const&) (exec_plan.h:60)
==5249==    by 0xFA83A0C: std::function<arrow::Result<arrow::compute::ExecNode*> (arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&)>::operator()(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&) const (std_function.h:622)
==5249== 14,528 (160 direct, 14,368 indirect) bytes in 1 blocks are definitely lost in loss record 1,989 of 3,883
==5249==    at 0x4849013: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==5249==    by 0x10096CB7: arrow::FutureImpl::Make() (future.cc:187)
==5249==    by 0xFCB6F9A: arrow::Future<arrow::internal::Empty>::Make() (future.h:420)
==5249==    by 0x101AE927: ExecPlanImpl (exec_plan.cc:50)
==5249==    by 0x101AE927: arrow::compute::ExecPlan::Make(arrow::compute::ExecContext*, std::shared_ptr<arrow::KeyValueMetadata const>) (exec_plan.cc:355)
==5249==    by 0xFA77BA2: ExecPlan_create(bool) (compute-exec.cpp:45)
==5249==    by 0xF9FAE9F: _arrow_ExecPlan_create (arrowExports.cpp:868)
==5249==    by 0x4953B60: R_doDotCall (dotcode.c:601)
==5249==    by 0x49C2C16: bcEval (eval.c:7682)
==5249==    by 0x499DB95: Rf_eval (eval.c:748)
==5249==    by 0x49A0904: R_execClosure (eval.c:1918)
==5249==    by 0x49A05B7: Rf_applyClosure (eval.c:1844)
==5249==    by 0x49B2122: bcEval (eval.c:7094)
==5249== 
==5249== 36,322 (416 direct, 35,906 indirect) bytes in 1 blocks are definitely lost in loss record 2,929 of 3,883
==5249==    at 0x4849013: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==5249==    by 0x10214F92: arrow::compute::TaskScheduler::Make() (task_util.cc:421)
==5249==    by 0x101AEA6C: ExecPlanImpl (exec_plan.cc:50)
==5249==    by 0x101AEA6C: arrow::compute::ExecPlan::Make(arrow::compute::ExecContext*, std::shared_ptr<arrow::KeyValueMetadata const>) (exec_plan.cc:355)
==5249==    by 0xFA77BA2: ExecPlan_create(bool) (compute-exec.cpp:45)
==5249==    by 0xF9FAE9F: _arrow_ExecPlan_create (arrowExports.cpp:868)
==5249==    by 0x4953B60: R_doDotCall (dotcode.c:601)
==5249==    by 0x49C2C16: bcEval (eval.c:7682)
==5249==    by 0x499DB95: Rf_eval (eval.c:748)
==5249==    by 0x49A0904: R_execClosure (eval.c:1918)
==5249==    by 0x49A05B7: Rf_applyClosure (eval.c:1844)
==5249==    by 0x49B2122: bcEval (eval.c:7094)
==5249==    by 0x499DB95: Rf_eval (eval.c:748)

We also occasionally get leaked Schemas, and in one case a leaked InputType that seemed completely unrelated to the other leaks (ARROW-17225).

I'm wondering if these have to do with references in lambdas that get passed by reference? Or perhaps a cache issue? There were some instances in previous leaks where the backtrace to the new allocator was different between reported leaks.

Reporter: Dewey Dunnington / @paleolimbot
Assignee: Dewey Dunnington / @paleolimbot

PRs and other links:

• GitHub Pull Request #13746
• GitHub Pull Request #13773
• GitHub Pull Request #13779
• GitHub Pull Request #13780

_{Note: This issue was originally created as ARROW-17252. Please see the migration documentation for further details.}

[asfimport]

Dewey Dunnington / @paleolimbot:
Another run that had some other failures, including the InputType one:

https://dev.azure.com/ursacomputing/crossbow/_build/results?buildId=30290&view=logs&j=0da5d1d9-276d-5173-c4c4-9d4d4ed14fdb&t=d9b15392-e4ce-5e4c-0c8c-b69645229181&l=25107

==5248== 56 bytes in 1 blocks are possibly lost in loss record 171 of 3,993
==5248==    at 0x4849013: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==5248==    by 0x10547EE7: allocate (new_allocator.h:121)
==5248==    by 0x10547EE7: allocate (alloc_traits.h:460)
==5248==    at 0x4849013: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==5248==    by 0x101AFFBA: allocate (new_allocator.h:121)
==5248==    by 0x101AFFBA: allocate (alloc_traits.h:460)
==5248==    by 0x101AFFBA: _M_allocate (stl_vector.h:346)
==5248==    by 0x101AFFBA: void std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >::_M_realloc_insert<arrow::compute::ExecNode*>(__gnu_cxx::__normal_iterator<arrow::compute::ExecNode**, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> > >, arrow::compute::ExecNode*&&) (vector.tcc:440)
==5248==    by 0x101AABBA: emplace_back<arrow::compute::ExecNode*> (vector.tcc:121)
==5248==    by 0x101AABBA: push_back (stl_vector.h:1204)
==5248==    by 0x101AABBA: arrow::compute::ExecNode::ExecNode(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >, std::shared_ptr<arrow::Schema>, int) (exec_plan.cc:414)
==5248==    by 0x101AAD22: arrow::compute::MapNode::MapNode(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, std::shared_ptr<arrow::Schema>, bool) (exec_plan.cc:476)
==5248==    by 0x101EC290: ProjectNode (project_node.cc:46)
==5248==    by 0x101EC290: EmplaceNode<arrow::compute::(anonymous namespace)::ProjectNode, arrow::compute::ExecPlan*&, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, std::shared_ptr<arrow::Schema>, std::vector<arrow::compute::Expression, std::allocator<arrow::compute::Expression> >, bool const&> (exec_plan.h:60)
==5248==    by 0x101EC290: arrow::compute::(anonymous namespace)::ProjectNode::Make(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&) (project_node.cc:73)
==5248==    by 0xFC20D83: std::_Function_handler<arrow::Result<arrow::compute::ExecNode*> (arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&), arrow::Result<arrow::compute::ExecNode*> (*)(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&)>::_M_invoke(std::_Any_data const&, arrow::compute::ExecPlan*&&, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >&&, arrow::compute::ExecNodeOptions const&) (invoke.h:60)
==5248==    by 0xFA838DC: std::function<arrow::Result<arrow::compute::ExecNode*> (arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&)>::operator()(arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&) const (std_function.h:622)
==5248==    by 0xFA81047: arrow::compute::MakeExecNode(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&, arrow::compute::ExecFactoryRegistry*) (exec_plan.h:438)
==5248==    by 0xFA77BE8: MakeExecNodeOrStop(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, arrow::compute::ExecPlan*, std::vector<arrow::compute::ExecNode*, std::allocator<arrow::compute::ExecNode*> >, arrow::compute::ExecNodeOptions const&) (compute-exec.cpp:53)
==5248==    by 0xFA7ADF2: ExecNode_Project(std::shared_ptr<arrow::compute::ExecNode> const&, std::vector<std::shared_ptr<arrow::compute::Expression>, std::allocator<std::shared_ptr<arrow::compute::Expression> > > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >) (compute-exec.cpp:307)
==5248==    by 0xF9FC997: _arrow_ExecNode_Project (arrowExports.cpp:986)
==5248==    by 0x4953BC4: R_doDotCall (dotcode.c:607)

[asfimport]

Dewey Dunnington / @paleolimbot:
I can get a similar leak locally, too using a dockerfile:

FROM ubuntu:20.04
ARG DEBIAN_FRONTEND=noninteractive
ENV TZ=America/Halifax
RUN apt-get update && apt-get install -y valgrind r-base cmake git libxml2-dev libcurl4-openssl-dev libssl-dev libgit2-dev libfontconfig1-dev libfreetype6-dev libharfbuzz-dev libfribidi-dev libpng-dev libtiff5-dev libjpeg-dev
RUN git clone https://github.com/apache/arrow.git /arrow && mkdir /arrow-build && cd /arrow-build && cmake /arrow/cpp -DARROW_CSV=ON -DARROW_FILESYSTEM=ON -DARROW_COMPUTE=ON -DBoost_SOURCE=BUNDLED && cmake --build . && cmake --install . --prefix /arrow-dist
RUN R -e 'install.packages(c("devtools", "cpp11", "R6", "assertthat", "bit64", "bit", "cli", "ellipsis", "glue", "magrittr", "purrr", "rlang", "tidyselect", "vctrs", "lubridate", "dplyr", "hms"), repos = "https://cloud.r-project.org")'
ENV ARROW_HOME /arrow-dist
ENV LD_LIBRARY_PATH /arrow-dist/lib
RUN cd /arrow/r && R CMD INSTALL .

Launching R with valgrind:

R -d "valgrind --tool=memcheck --leak-check=full"

...and I get this leak:

==387== 2,608 (72 direct, 2,536 indirect) bytes in 1 blocks are definitely lost in loss record 625 of 4,108
==387==    at 0x484A3C4: operator new(unsigned long) (in /usr/lib/aarch64-linux-gnu/valgrind/vgpreload_memcheck-arm64-linux.so)
==387==    by 0x1566648F: arrow::Table::FromRecordBatches(std::shared_ptr<arrow::Schema>, std::vector<std::shared_ptr<arrow::RecordBatch>, std::allocator<std::shared_ptr<arrow::RecordBatch> > > const&) (in /arrow-dist/lib/libarrow.so.900.0.0)
==387==    by 0x15629FB7: arrow::RecordBatchReader::ToTable() (in /arrow-dist/lib/libarrow.so.900.0.0)
==387==    by 0x1501C503: operator() (compute-exec.cpp:147)
==387==    by 0x1501C503: std::_Function_handler<arrow::Result<std::shared_ptr<arrow::Table> > (), ExecPlan_read_table(std::shared_ptr<arrow::compute::ExecPlan> const&, std::shared_ptr<arrow::compute::ExecNode> const&, cpp11::r_vector<SEXPREC*>, cpp11::r_vector<cpp11::r_string>, long)::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:286)
==387==    by 0x15023427: std::function<arrow::Result<std::shared_ptr<arrow::Table> > ()>::operator()() const (std_function.h:688)
==387==    by 0x1502352F: operator()<std::function<arrow::Result<std::shared_ptr<arrow::Table> >()>&> (future.h:150)
==387==    by 0x1502352F: __invoke_impl<void, arrow::detail::ContinueFuture&, arrow::Future<std::shared_ptr<arrow::Table> >&, std::function<arrow::Result<std::shared_ptr<arrow::Table> >()>&> (invoke.h:60)
==387==    by 0x1502352F: __invoke<arrow::detail::ContinueFuture&, arrow::Future<std::shared_ptr<arrow::Table> >&, std::function<arrow::Result<std::shared_ptr<arrow::Table> >()>&> (invoke.h:95)
==387==    by 0x1502352F: __call<void, 0, 1> (functional:400)
==387==    by 0x1502352F: operator()<> (functional:484)
==387==    by 0x1502352F: arrow::internal::FnOnce<void ()>::FnImpl<std::_Bind<arrow::detail::ContinueFuture (arrow::Future<std::shared_ptr<arrow::Table> >, std::function<arrow::Result<std::shared_ptr<arrow::Table> > ()>)> >::invoke() (functional.h:152)
==387==    by 0x1579636B: std::thread::_State_impl<std::thread::_Invoker<std::tuple<arrow::internal::ThreadPool::LaunchWorkersUnlocked(int)::{lambda()#1}> > >::_M_run() (in /arrow-dist/lib/libarrow.so.900.0.0)
==387==    by 0x71F4FAB: ??? (in /usr/lib/aarch64-linux-gnu/libstdc++.so.6.0.28)
==387==    by 0x55F1623: start_thread (pthread_create.c:477)
==387==    by 0x4DA949B: thread_start (clone.S:78)

(Although this dockerfile doesn't use r-devel...it uses R 3.6 which is a bit old).

[asfimport]

Dewey Dunnington / @paleolimbot:
The summary is: I'm not sure if these leaks are important or exactly which code change triggered them yet.

I did some digging into the nightly build failures, and the day that ARROW-16444 ( #13397 ) was merged really is the day that we started seeing intermittent leaks. This was also not the only PR that merged that day but it does seem like the most likely candidate.

I tried reverting bits of ARROW-16444 that modified the RunWithCapturedR/SafeCallIntoR syntax and completely removed the SafeCallIntoR syntax in #13746; however, this does not seem to stop the leaks. I could also try reverting some R code (will try this this evening).

I tried replicating the leaks using valgrind in a docker image. I could get leaks similar to those seen in CI but I couldn't replicate them reliably and couldn't replicate them at all running fewer test files at once (but perhaps I did not try this enough times). I could also try on the parent commit of the UDFs PR 791e5bd6e413c193a214237d042f4f721ccc0976 to see if I get the same kinds of leaks.

I tried replicating the leaks using valgrind on my local Ubuntu development setup. This takes a long time and the entire test suite using devtools::test() hasn't finished running yet.

[asfimport]

Neal Richardson / @nealrichardson:
Issue resolved by pull request 13773
#13773