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

Test suite hits 2GB limit on 32bit R-devel #2767

Closed
mattdowle opened this issue Apr 18, 2018 · 40 comments
Closed

Test suite hits 2GB limit on 32bit R-devel #2767

mattdowle opened this issue Apr 18, 2018 · 40 comments
Milestone

Comments

@mattdowle
Copy link
Member

mattdowle commented Apr 18, 2018

I've just seen this occur, here :
https://ci.appveyor.com/project/Rdatatable/data-table/build/1.0.2337/job/3rppwcw31ent8g1r

Jan saw it too today here :
#2761 (comment)

So, despite all our efforts, there's still more to do.

The error I saw is similar to Jan's :

  Running test id 1667.1      Error: memory exhausted (limit reached?)
  Error: memory exhausted (limit reached?)
  Error: memory exhausted (limit reached?)
  Execution halted

That message is R's, here :
https://github.com/wch/r-source/blob/trunk/src/main/memory.c#L2059
and looking at the context there (inside an err_malloc function) suggests AppVeyor instance is declining R's malloc request. (i.e. it doesn't seem like some kind of stack limit inside R itself).

@jangorecki

  • What is the memory limit of an AppVeyor instance? I had a quick look and 4GB came up quickly but I'm not sure if that's correct. If it is 4GB I don't see how we are reaching that.
  • We never knew before, but now with your new memtest charts, it seems the max memory used is towards the end of the test suite and reaches 160MB. If that's right, it seems very low. I can't imagine AppVeyor's limit being that low. Certainly a lot less than 4GB and we know it now passes on your 2GB instance.
  • I already reduced the memory usage of the non-equi-join tests in PR Nqjoin efficiency 2 #2733. I'm fairly confident that helped a lot and that the memory usage is no longer in that area.
  • According to the memtest charts there are 3 large step-ups in memory usage very early in the test suite. If the mem usage table could be sorted by change and the top 10 printed at the end of the test suite then we could see which tests those step-ups are for. If the data used in those 3 tests is rm()'d after those tests, then perhaps more memory will be available for the tests at the end. However, as I said above, it's strange that the memtest charts show only 160MB being used! Reducing those 3 tests will be wasted effort if, somehow, the memtest results are not capturing the actual mem usage on AppVeyor.
  • A long shot ... might it be that a Suggests package test is running on AppVeyor which eats more RAM, which does not run in the environment used to create the memtest charts.
@HughParsonage
Copy link
Member

Isn't i386 limited to 2 GB?

@mattdowle mattdowle added this to the v1.10.6 milestone Apr 18, 2018
@mattdowle mattdowle added the ci label Apr 18, 2018
@mattdowle
Copy link
Member Author

mattdowle commented Apr 18, 2018

@HughParsonage Oh ... yes! Just checked and yes both jobs failed just on 32bit. Thanks!

So it's not AppVeyor then. It's just a 32bit / 2GB issue. That leaves us with why there's a gap between the 160MB in memtest chart and 2GB. If the memtest scale is 10x out (does the output of ps change scale perhaps and needs to be fixed scale by passing a parameter?) then that would make more sense: 1600MB for R would then make sense to try to reduce by focussing on the 3 tests towards the start of the test suite.

(I guess internal R object headers have increased a little bit in R-devel, causing, on 32-bit, R-release to be just under the 2GB limit and R-devel to be just over. Explaining why it's just R-devel.)

@mattdowle mattdowle changed the title Memory limit on AppVeyor R-devel Test suite hits 2GB limit on 32bit R-devel Apr 18, 2018
@jangorecki
Copy link
Member

jangorecki commented Apr 19, 2018

Failed build that happened to me was on

Platform: x86_64-w64-mingw32/x64 (64-bit)
Running under: Windows Server 2012 R2 x64 (build 9600)

* using platform: x86_64-w64-mingw32 (64-bit)

And there were no suggested packages installed

Packages suggested but not available for checking:
  'bit64' 'curl' 'knitr' 'xts' 'nanotime' 'zoo' 'chron' 'reshape2'
  'testthat' 'GenomicRanges'

Probably we shouldn't use ps -o rss. There are many topics discussing that ps don't give proper memory measurement, also that RSS overestimate (surprisingly). I checked multiple sizes of data created in R and ps does not change unit, always returns KB.
Will try to add another tool to memtest then.

@mattdowle
Copy link
Member Author

mattdowle commented Apr 19, 2018

Just on that error, although yes the platform is 64bit, the multiarch R CMD check runs tests for both 32bit and 64bit. When I checked your fail, I downloaded the failure.zip artifact and looked inside both i386 and x64 directories. Just the i386 directory contained the main.fail file while x64 directory contained main.out passing ok.
Yes agree 'ps' next then. I can't think why the pattern of RAM usage makes sense but not the scale. The figures not being perfect makes sense, but not 10x off.

Oh ... how about just free -m. That's the one that matters and is reliable as far as I know. Deltas will work on that figure. In CI no other processes will be running, but if they are somehow, then we want to know anyway.

@jangorecki
Copy link
Member

jangorecki commented Apr 19, 2018

I checked locally memory usage with supposedly good tool /usr/bin/time --verbose (which is different app from bash time).
Results shows that R-devel is actually eating much less memory than R 3.4.4 (at least on Linux).
Still it is far from 2GB limit, anyway it doesn't seems to be related to test suite. More something about R-devel and memory management on 32bit Windows - maybe recent memory optimization does not play well on 32bit Win.
Next step to debug this issue would be to measure memory on Windows.
Building vignettes raises RSS by ~800MB on R 3.4.4 but they are disabled in appveyor script.

R 3.4.4

R CMD check took 364MB RSS.

	Command being timed: "R CMD check data.table_1.10.5.tar.gz --ignore-vignettes --no-manual"
	Maximum resident set size (kbytes): 364648

test.data.table took 351MB RSS.

	Command being timed: "Rscript -e require(data.table); test.data.table()"
	Maximum resident set size (kbytes): 351236

R-devel (2018-04-06)

R CMD check took 224MB RSS.

	Command being timed: "/home/jan/R-devel/bin/R CMD check data.table_1.10.5.tar.gz --ignore-vignettes --no-manual"
	Maximum resident set size (kbytes): 224640

test.data.table took 207MB RSS.

	Command being timed: "/home/jan/R-devel/bin/Rscript -e require(data.table); test.data.table()"
	Maximum resident set size (kbytes): 207032

@mattdowle mattdowle modified the milestones: v1.11.0, v1.11.2 Apr 29, 2018
@mattdowle
Copy link
Member Author

mattdowle commented Apr 29, 2018

Just happened on win-builder ...
https://win-builder.r-project.org/0UGUaRk3ifo2/

** running tests for arch 'i386' ... [81s] ERROR
  Running 'autoprint.R' [1s]
  Comparing 'autoprint.Rout' to 'autoprint.Rout.save' ... OK
  Running 'knitr.R' [1s]
  Comparing 'knitr.Rout' to 'knitr.Rout.save' ... OK
  Running 'main.R' [76s]
  Running 'testthat.R' [2s]
Running the tests in 'tests/main.R' failed.
Complete output:
  > require(data.table)
  Loading required package: data.table
  > test.data.table()  # runs the main test suite of 5,000+ tests in /inst/tests/tests.Rraw
  Running D:/temp/Rtmpqkla50/RLIBS_169b8128a64aa/data.table/tests/tests.Rraw 
  
  Running test id 1.1      
  Running test id 1.2      
...
  Running test id 1648.086      
  Running test id 1648.087      
  Running test id 1648.088      
  Running test id 1648.089      
  Running test id 1648.09      
  Running test id 1648.091      Error: cannot allocate vector of size 4 Kb
  Execution halted
** running tests for arch 'x64' ... [135s] OK

so, as before, it's ok on 64bit but not 32bit.

@mattdowle mattdowle removed the ci label Apr 29, 2018
@MichaelChirico
Copy link
Member

have we done something like -- every 500 tests, clean up all the stale test objects laying around (x, y, DT, DT1, DT2, dt, df, ...)? should be minor but might help

@HughParsonage
Copy link
Member

HughParsonage commented Apr 29, 2018

Perhaps change:

nq_fun = function(n=100L) {

to

nq_fun = function(n=if (identical(.Platform$OS.type, "windows") && identical(.Platform$r_arch, "i386")) 10L else 100L) {

or nq_fun = function(n = if (memory.limit() < 3*1024) 10L else 100L) {

@mattdowle
Copy link
Member Author

mattdowle commented Apr 29, 2018

@MichaelChirico Jan implemented the memory tracing but it doesn't look like it's using more than 150MB of RAM. It's odd. Yes I thought there would be some large stale objects to rm() but it doesn't seem like it from memtest.

@HughParsonage We don't think the nq tests are using the ram, though. Somewhere earlier. But ok might as well turn off on 32bit, no harm ...

@jangorecki
Copy link
Member

jangorecki commented Apr 29, 2018

My guess, not backed by anything, is that R 3.5.0 has some memory bug in 32bit win (AFAIK this issue is related only to this version/platform/arch). There were significant improvements for memory handling in R 3.5.0, on linux tests reports 207MB while R 3.4.4 took 351MB.
You can always run tests.Rraw interactively and at the end investigate objects that are left after tests. Anyway debugging makes more sense using 32bit windows.

@HughParsonage
Copy link
Member

HughParsonage commented Apr 29, 2018

I just ran test.data.table() on Windows 10 using the 32-bit version of R 3.5.0 and got through OK. (Some Bioconductor packages weren't installed though.)

@jangorecki
Copy link
Member

@HughParsonage could you occupy most of memory by some other process? leave 1.5-2GB of memory for tests.

@HughParsonage
Copy link
Member

With less than 1 GB available, I was able to run it without problems.

@mattdowle
Copy link
Member Author

mattdowle commented Apr 29, 2018

@HughParsonage bit64 installed and no messages from test.data.table() that it couldn't find packages? By Bioconductor packages do you mean GenomicRanges? It's possible the memory usage is there, I guess, if that's the only difference!

@HughParsonage
Copy link
Member

Yes, sorry just GenomicRanges not installed.

@mattdowle
Copy link
Member Author

mattdowle commented Apr 29, 2018

Trouble is we're flying blind as neither AppVeyor or win-builder tells use what and when uses the ram. Jan said GenomicRanges pulls in a large bunch of dependencies, and we want to remove it anyway, so that would be reasonable to try next then.

@mattdowle
Copy link
Member Author

Jan's idea is good to inspect the environment at the end of tests.Rraw to see if any large objects are left hanging around. If so, can be rm()'d after their test.

@jangorecki
Copy link
Member

jangorecki commented Apr 29, 2018

Installing GenomicRanges result installing 11 packages, one of them 17MB. Appveyor does not install GenomicRanges so issues are not related to it. Assuming win builder failure is caused by same issue as appveyor 32bit win r-devel builds.
From r-devel windows build on appveyor:

Packages suggested but not available for checking:
  'bit64' 'curl' 'knitr' 'xts' 'nanotime' 'zoo' 'chron' 'reshape2'
  'testthat' 'GenomicRanges'

Nice helpers for checking memory usage of objects in workspace: https://stackoverflow.com/questions/1358003/tricks-to-manage-the-available-memory-in-an-r-session

@mattdowle
Copy link
Member Author

mattdowle commented Apr 29, 2018

The plot thickens. Just got this from win-builder (with latest master as of now because I was testing my commits turning off large tests on 32bit) ...
https://win-builder.r-project.org/1W7om9wWK1Un

Running test id 1372.24      
  Running test id 1372.25      
  Running test id 1372.26      
  Running test id 1372.27      
  Running test id 1372.28      Error in initialize(value, ...) : 
    GC encountered a node (0x1089b0e0) with an unknown SEXP type: <unknown> at memory.c:1626
  Calls: test.data.table ... normalizeSingleBracketSubscript -> NSBS -> NSBS -> new2 -> new
  Execution halted

1372.* is GenomicRanges
Jan's guess that there's a rare bug in R 3.5 on 32bit looks good.

@jangorecki
Copy link
Member

jangorecki commented Apr 29, 2018

So testing with GenomicRanges make sense...
Mentioned error: https://github.com/wch/r-source/blob/trunk/src/main/memory.c#L3043-L3062
We can eventually try moving GenomicRanges tests to other.Rraw and GenomicRanges from DESCRIPTION to inst/tests/tests-DESCRIPTION. While it may help to pass the tests, it won't solve underlying issue.
Quite a lot of changes to memory.c in recent months: https://github.com/wch/r-source/commits/trunk/src/main/memory.c

@mattdowle mattdowle modified the milestones: v1.11.0, v1.11.2 Apr 30, 2018
@mattdowle
Copy link
Member Author

I may be imagining it, but AppVeyor 32bit seems more stable now after 3-4 runs. It was still failing with R's memory exhausted (limit reached?) error after the ijoin.c segv fix (so that didn't fix it). What's changed since then is I added back these lines to appveyor.yml :

# Include the subset of Suggests that test.data.table() has tests for :
- travis-tool.sh r_install bit64
- travis-tool.sh r_install xts
- travis-tool.sh r_install nanotime
- travis-tool.sh r_install chron

So that no tests are skipped by AppVeyor. It's possible that there's a sample() (or similar) in a test somewhere that doesn't have a set.seed(). Such test's data would depend on the sampling that has happened in the test suite up to that point, since the last set.seed(). When these extra tests now run (bit64, xts, etc) perhaps they do some sampling and change the data in the pesky test afterwards, by their existence. Perhaps the pesky test is taking a different branch now on the different data and not hitting the pesky line anymore.
So, to reproduce, removing these 4 packages locally and rerunning extra-strong R-devel --strict-barrier ASAN, together with valgrid instrumentation, might reveal the memory fault. Since it's still feasible that the memory exhausted is an artifact of a memory fault. There are still some uninitialized variables to clear up from valgrind, too. And there's full 100% coverage yet to achieve, too.

@mattdowle mattdowle modified the milestones: v1.11.4, 1.11.2 May 1, 2018
@mattdowle
Copy link
Member Author

mattdowle commented May 3, 2018

I removed those packages locally (bit64, xts, nanotime and chron) and reran test.data.table() in R compiled with ASAN and strict-barrier, in the hopes of seeing some hint of problem. But nothing. Works fine here.
I also ran 32bit R-devel (2018-04-28 r74669) on Windows without those 4 packages installed. Just like AppVeyor was doing. Also fine. No sign of either crash or memory fault. Task manager doesn't show anything close to R using 2GB; just 200MB, consistent with other results.
Have to do valgrind and new problem in R-devel anyway (#2820). Maybe it was to do with that.

@mattdowle
Copy link
Member Author

mattdowle commented May 3, 2018

One final attempt. On Windows 32bit R-devel I did the following :

for (i in 1:10) if (!test.data.table()) stop("one or more tests failed")

and then after a few iterations I saw it!!

Running test id 1253.466    Error: memory exhausted (limit reached?)
Error: memory exhausted (limit reached?)
Error: memory exhausted (limit reached?)

And indeed the R process (32bit) is close to 4GB.
image

which is way above what we have observed and were expecting since we know the test suite doesn't use that much.

Does anyone else see it on Windows? Need to repeat 10 times like that it seems.

Maybe if I repeat 10 times locally it'll hit that locally then I can trace with linux tools. Will try ...

Feels to me like a true data.table bug that is triggered by random data in a test causing a pesky branch to be hit. Not actually 32-bit or Windows related. Just showing up there, so far, by chance.

This could be the same as #2822, albeit a crash there.

mattdowle added a commit that referenced this issue May 4, 2018
@mattdowle
Copy link
Member Author

The latest 'memory exhausted' fail occurred on R-devel only, as before. But both 32bit and 64bit this time so it's not 32bit-only. Also, the suggests were loaded this time and their tests ran. So it's not to do with whether bit64, xts or nanotime are installed or not, either.

Link to log : https://ci.appveyor.com/project/Rdatatable/data-table/build/1.0.2472/job/17yi0fe0562dht8v

Copy and paste of AppVeyor log
Build started
$ErrorActionPreference = "Stop"
Invoke-WebRequest http://raw.github.com/krlmlr/r-appveyor/master/scripts/appveyor-tool.ps1 -OutFile "..\appveyor-tool.ps1"
Import-Module '..\appveyor-tool.ps1'
git clone -q https://github.com/Rdatatable/data.table.git C:\projects\data-table
git fetch -q origin +refs/pull/2832/merge:
git checkout -qf FETCH_HEAD
Running Install scripts
Bootstrap
== 05/04/2018 02:22:51: Bootstrap: Start
== 05/04/2018 02:22:51: Adding GnuWin32 tools to PATH
== 05/04/2018 02:22:51: Setting time zone
UTC
GMT Standard Time
== 05/04/2018 02:22:51: Version: devel
== 05/04/2018 02:22:51: URL path: 
== 05/04/2018 02:22:51: Downloading R from: https://cloud.r-project.org/bin/windows/base/R-devel-win.exe
== 05/04/2018 02:22:54: Running R installer
R is now available on drive C:
== 05/04/2018 02:23:16: Setting PATH
== 05/04/2018 02:23:16: Testing R installation
R Under development (unstable) (2018-05-02 r74682)
Platform: x86_64-w64-mingw32/x64 (64-bit)
Running under: Windows Server 2012 R2 x64 (build 9600)
Matrix products: default
locale:
[1] LC_COLLATE=English_United States.1252 
[2] LC_CTYPE=English_United States.1252   
[3] LC_MONETARY=English_United States.1252
[4] LC_NUMERIC=C                          
[5] LC_TIME=English_United States.1252    
attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base     
loaded via a namespace (and not attached):
[1] compiler_3.6.0
== 05/04/2018 02:23:17: Determining Rtools version
== 05/04/2018 02:23:17: Downloading Rtools from: https://cloud.r-project.org/bin/windows/Rtools/Rtools35.exe
== 05/04/2018 02:23:20: Running Rtools installer
Rtools is now available on drive C:
== 05/04/2018 02:24:04: Setting PATH
== 05/04/2018 02:24:04: Downloading and installing travis-tool.sh
@bash.exe ../travis-tool.sh %*
^\.travis\.yml$
^CONTRIBUTING\.md$
^ISSUE_TEMPLATE\.md$
^CRAN_Release\.cmd$
^deploy\.sh$
^\.emacs\.desktop
^\.emacs\.desktop\.lock
^.*\.Rproj$
^\.Rproj\.user$
^appveyor\.yml$
^.gitlab-ci\.yml$
^\.idea$
^\.RData$
^\.Rhistory$
^data\.table_.*\.tar\.gz$
^cc\.R$
^Makefile$
^NEWS.0.md$
^travis-tool\.sh\.cmd$
C:\Rtools\bin
C:\Rtools\MinGW\bin
C:\Rtools\mingw_64\bin
C:\R\bin\x64
C:\Rtools\mingw_64\bin
C:\MinGW\msys\1.0\bin
C:\Program Files (x86)\Git\bin
C:\Perl\site\bin
C:\Perl\bin
C:\Windows\system32
C:\Windows
C:\Windows\System32\Wbem
C:\Windows\System32\WindowsPowerShell\v1.0\
C:\Program Files\7-Zip
C:\Program Files\Microsoft\Web Platform Installer\
C:\Tools\GitVersion
C:\Tools\PsTools
C:\Program Files\Git LFS
C:\Program Files (x86)\Subversion\bin
C:\Program Files\Microsoft SQL Server\120\Tools\Binn\
C:\Program Files\Microsoft SQL Server\Client SDK\ODBC\110\Tools\Binn\
C:\Program Files (x86)\Microsoft SQL Server\120\Tools\Binn\
C:\Program Files\Microsoft SQL Server\120\DTS\Binn\
C:\Program Files (x86)\Microsoft SQL Server\120\Tools\Binn\ManagementStudio\
C:\Tools\WebDriver
C:\Program Files (x86)\Microsoft SDKs\TypeScript\1.4\
C:\Program Files (x86)\Microsoft Visual Studio 12.0\Common7\IDE\PrivateAssemblies\
C:\Program Files (x86)\Microsoft SDKs\Azure\CLI\wbin
C:\Ruby193\bin
C:\Tools\NUnit\bin
C:\Tools\xUnit
C:\Tools\MSpec
C:\Tools\Coverity\bin
C:\Program Files (x86)\CMake\bin
C:\go\bin
C:\Program Files\Java\jdk1.8.0\bin
C:\Python27
C:\Program Files\nodejs
C:\Program Files (x86)\iojs
C:\Program Files\iojs
C:\Users\appveyor\AppData\Roaming\npm
C:\Program Files\Microsoft SQL Server\130\Tools\Binn\
C:\Program Files (x86)\MSBuild\14.0\Bin
C:\Tools\NuGet
C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE\CommonExtensions\Microsoft\TestWindow
C:\Program Files\Microsoft DNX\Dnvm
C:\Program Files\Microsoft SQL Server\Client SDK\ODBC\130\Tools\Binn\
C:\Program Files (x86)\Microsoft SQL Server\130\Tools\Binn\
C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\
C:\Program Files\Microsoft SQL Server\130\DTS\Binn\
C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\
C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\
C:\Program Files (x86)\Apache\Maven\bin
C:\Python27\Scripts
C:\Tools\NUnit3
C:\Program Files\Mercurial\
C:\Program Files\LLVM\bin
C:\Program Files\dotnet\
C:\Tools\curl\bin
C:\Program Files\Amazon\AWSCLI\
C:\Program Files (x86)\Microsoft SQL Server\140\DTS\Binn\
C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE\Extensions\Microsoft\SQLDB\DAC\140
C:\Tools\vcpkg
C:\Program Files (x86)\Microsoft SQL Server\140\Tools\Binn\
C:\Program Files\Microsoft SQL Server\140\Tools\Binn\
C:\Program Files\Microsoft SQL Server\140\DTS\Binn\
C:\Program Files\PowerShell\6.0.0\
C:\Program Files\erl9.2\bin
C:\Program Files (x86)\nodejs\
C:\Program Files\Git\cmd
C:\Program Files\Git\usr\bin
C:\Program Files (x86)\Yarn\bin\
C:\Program Files (x86)\NSIS
C:\Tools\Octopus
C:\Program Files\Microsoft Service Fabric\bin\Fabric\Fabric.Code
C:\Program Files\Microsoft SDKs\Service Fabric\Tools\ServiceFabricLocalClusterManager
C:\ProgramData\chocolatey\bin
C:\Users\appveyor\AppData\Roaming\npm
C:\Users\appveyor\AppData\Local\Yarn\bin
C:\Program Files\AppVeyor\BuildAgent\
== 05/04/2018 02:24:04: Setting R_LIBS_USER
    Directory: C:\
Mode                LastWriteTime         Length Name                                                                                                                                                                                
----                -------------         ------ ----                                                                                                                                                                                
d-----         5/4/2018   2:24 AM                RLibrary                                                                                                                                                                            
== 05/04/2018 02:24:04: Setting TAR to 'internal'
== 05/04/2018 02:24:04: Bootstrap: Done
ECHO no Revision metadata added to DESCRIPTION
no Revision metadata added to DESCRIPTION
set _R_CHECK_FORCE_SUGGESTS_=false
travis-tool.sh r_install bit64
+ CRAN=http://cloud.r-project.org/
+ BIOC=http://bioconductor.org/biocLite.R
+ PKGTYPE=both
+ BIOC_USE_DEVEL=TRUE
++ uname -s
+ OS=MSYS_NT-6.3-WOW
+ PANDOC_VERSION=1.13.1
+ PANDOC_DIR=/opt/pandoc
+ PANDOC_URL=https://s3.amazonaws.com/rstudio-buildtools/pandoc-1.13.1.zip
+ PATH='/c/Rtools/bin:/c/Rtools/MinGW/bin:/c/Rtools/mingw_64/bin:/c/R/bin/x64:/c/Rtools/mingw_64/bin:/usr/bin:/c/Program Files (x86)/Git/bin:/c/Perl/site/bin:/c/Perl/bin:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0/:/c/Program Files/7-Zip:/c/Program Files/Microsoft/Web Platform Installer/:/c/Tools/GitVersion:/c/Tools/PsTools:/c/Program Files/Git LFS:/c/Program Files (x86)/Subversion/bin:/c/Program Files/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/110/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/ManagementStudio/:/c/Tools/WebDriver:/c/Program Files (x86)/Microsoft SDKs/TypeScript/1.4/:/c/Program Files (x86)/Microsoft Visual Studio 12.0/Common7/IDE/PrivateAssemblies/:/c/Program Files (x86)/Microsoft SDKs/Azure/CLI/wbin:/c/Ruby193/bin:/c/Tools/NUnit/bin:/c/Tools/xUnit:/c/Tools/MSpec:/c/Tools/Coverity/bin:/c/Program Files (x86)/CMake/bin:/c/go/bin:/c/Program Files/Java/jdk1.8.0/bin:/c/Python27:/c/Program Files/nodejs:/c/Program Files (x86)/iojs:/c/Program Files/iojs:/c/Users/appveyor/AppData/Roaming/npm:/c/Program Files/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/MSBuild/14.0/Bin:/c/Tools/NuGet:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/CommonExtensions/Microsoft/TestWindow:/c/Program Files/Microsoft DNX/Dnvm:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/110/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Apache/Maven/bin:/c/Python27/Scripts:/c/Tools/NUnit3:/c/Program Files/Mercurial/:/c/Program Files/LLVM/bin:/c/Program Files/dotnet/:/c/Tools/curl/bin:/c/Program Files/Amazon/AWSCLI/:/c/Program Files (x86)/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/Extensions/Microsoft/SQLDB/DAC/140:/c/Tools/vcpkg:/c/Program Files (x86)/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files/PowerShell/6.0.0/:/c/Program Files/erl9.2/bin:/c/Program Files (x86)/nodejs/:/c/Program Files/Git/cmd:/c/Program Files/Git/usr/bin:/c/Program Files (x86)/Yarn/bin/:/c/Program Files (x86)/NSIS:/c/Tools/Octopus:/c/Program Files/Microsoft Service Fabric/bin/Fabric/Fabric.Code:/c/Program Files/Microsoft SDKs/Service Fabric/Tools/ServiceFabricLocalClusterManager:/c/ProgramData/chocolatey/bin:/c/Users/appveyor/AppData/Roaming/npm:/c/Users/appveyor/AppData/Local/Yarn/bin:/c/Program Files/AppVeyor/BuildAgent/:/usr/texbin'
+ R_BUILD_ARGS=--no-manual
+ R_CHECK_ARGS=--no-manual
+ R_USE_BIOC_CMDS='source('\''http://bioconductor.org/biocLite.R'\''); tryCatch(useDevel(TRUE), error=function(e) {if (!grepl('\''already in use'\'', e)) {e}}); options(repos=biocinstallRepos());'
+ COMMAND=r_install
+ echo 'Running command: r_install'
Running command: r_install
+ shift
+ case $COMMAND in
+ RInstall bit64
+ [[ '' == \b\i\t\6\4 ]]
+ echo 'Installing R package(s): bit64'
Installing R package(s): bit64
+ Rscript -e 'install.packages(commandArgs(TRUE), repos="http://cloud.r-project.org/", INSTALL_opts="", type="both")' bit64
Installing package into 'c:/RLibrary'
(as 'lib' is unspecified)
also installing the dependency 'bit'
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/bit_1.1-12.zip'
Content type 'application/zip' length 240057 bytes (234 KB)
==================================================
downloaded 234 KB
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/bit64_0.9-7.zip'
Content type 'application/zip' length 546956 bytes (534 KB)
==================================================
downloaded 534 KB
package 'bit' successfully unpacked and MD5 sums checked
package 'bit64' successfully unpacked and MD5 sums checked
The downloaded binary packages are in
	C:\Users\appveyor\AppData\Local\Temp\1\RtmpoX0Fgh\downloaded_packages
travis-tool.sh r_install xts
+ CRAN=http://cloud.r-project.org/
+ BIOC=http://bioconductor.org/biocLite.R
+ PKGTYPE=both
+ BIOC_USE_DEVEL=TRUE
++ uname -s
+ OS=MSYS_NT-6.3-WOW
+ PANDOC_VERSION=1.13.1
+ PANDOC_DIR=/opt/pandoc
+ PANDOC_URL=https://s3.amazonaws.com/rstudio-buildtools/pandoc-1.13.1.zip
+ PATH='/c/Rtools/bin:/c/Rtools/MinGW/bin:/c/Rtools/mingw_64/bin:/c/R/bin/x64:/c/Rtools/mingw_64/bin:/usr/bin:/c/Program Files (x86)/Git/bin:/c/Perl/site/bin:/c/Perl/bin:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0/:/c/Program Files/7-Zip:/c/Program Files/Microsoft/Web Platform Installer/:/c/Tools/GitVersion:/c/Tools/PsTools:/c/Program Files/Git LFS:/c/Program Files (x86)/Subversion/bin:/c/Program Files/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/110/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/ManagementStudio/:/c/Tools/WebDriver:/c/Program Files (x86)/Microsoft SDKs/TypeScript/1.4/:/c/Program Files (x86)/Microsoft Visual Studio 12.0/Common7/IDE/PrivateAssemblies/:/c/Program Files (x86)/Microsoft SDKs/Azure/CLI/wbin:/c/Ruby193/bin:/c/Tools/NUnit/bin:/c/Tools/xUnit:/c/Tools/MSpec:/c/Tools/Coverity/bin:/c/Program Files (x86)/CMake/bin:/c/go/bin:/c/Program Files/Java/jdk1.8.0/bin:/c/Python27:/c/Program Files/nodejs:/c/Program Files (x86)/iojs:/c/Program Files/iojs:/c/Users/appveyor/AppData/Roaming/npm:/c/Program Files/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/MSBuild/14.0/Bin:/c/Tools/NuGet:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/CommonExtensions/Microsoft/TestWindow:/c/Program Files/Microsoft DNX/Dnvm:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/110/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Apache/Maven/bin:/c/Python27/Scripts:/c/Tools/NUnit3:/c/Program Files/Mercurial/:/c/Program Files/LLVM/bin:/c/Program Files/dotnet/:/c/Tools/curl/bin:/c/Program Files/Amazon/AWSCLI/:/c/Program Files (x86)/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/Extensions/Microsoft/SQLDB/DAC/140:/c/Tools/vcpkg:/c/Program Files (x86)/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files/PowerShell/6.0.0/:/c/Program Files/erl9.2/bin:/c/Program Files (x86)/nodejs/:/c/Program Files/Git/cmd:/c/Program Files/Git/usr/bin:/c/Program Files (x86)/Yarn/bin/:/c/Program Files (x86)/NSIS:/c/Tools/Octopus:/c/Program Files/Microsoft Service Fabric/bin/Fabric/Fabric.Code:/c/Program Files/Microsoft SDKs/Service Fabric/Tools/ServiceFabricLocalClusterManager:/c/ProgramData/chocolatey/bin:/c/Users/appveyor/AppData/Roaming/npm:/c/Users/appveyor/AppData/Local/Yarn/bin:/c/Program Files/AppVeyor/BuildAgent/:/usr/texbin'
+ R_BUILD_ARGS=--no-manual
+ R_CHECK_ARGS=--no-manual
+ R_USE_BIOC_CMDS='source('\''http://bioconductor.org/biocLite.R'\''); tryCatch(useDevel(TRUE), error=function(e) {if (!grepl('\''already in use'\'', e)) {e}}); options(repos=biocinstallRepos());'
+ COMMAND=r_install
+ echo 'Running command: r_install'
Running command: r_install
+ shift
+ case $COMMAND in
+ RInstall xts
+ [[ '' == \x\t\s ]]
+ echo 'Installing R package(s): xts'
Installing R package(s): xts
+ Rscript -e 'install.packages(commandArgs(TRUE), repos="http://cloud.r-project.org/", INSTALL_opts="", type="both")' xts
Installing package into 'c:/RLibrary'
(as 'lib' is unspecified)
also installing the dependency 'zoo'
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/zoo_1.8-1.zip'
Content type 'application/zip' length 1088462 bytes (1.0 MB)
==================================================
downloaded 1.0 MB
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/xts_0.10-2.zip'
Content type 'application/zip' length 944787 bytes (922 KB)
==================================================
downloaded 922 KB
package 'zoo' successfully unpacked and MD5 sums checked
package 'xts' successfully unpacked and MD5 sums checked
The downloaded binary packages are in
	C:\Users\appveyor\AppData\Local\Temp\1\RtmpYhGqGS\downloaded_packages
travis-tool.sh r_install nanotime
+ CRAN=http://cloud.r-project.org/
+ BIOC=http://bioconductor.org/biocLite.R
+ PKGTYPE=both
+ BIOC_USE_DEVEL=TRUE
++ uname -s
+ OS=MSYS_NT-6.3-WOW
+ PANDOC_VERSION=1.13.1
+ PANDOC_DIR=/opt/pandoc
+ PANDOC_URL=https://s3.amazonaws.com/rstudio-buildtools/pandoc-1.13.1.zip
+ PATH='/c/Rtools/bin:/c/Rtools/MinGW/bin:/c/Rtools/mingw_64/bin:/c/R/bin/x64:/c/Rtools/mingw_64/bin:/usr/bin:/c/Program Files (x86)/Git/bin:/c/Perl/site/bin:/c/Perl/bin:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0/:/c/Program Files/7-Zip:/c/Program Files/Microsoft/Web Platform Installer/:/c/Tools/GitVersion:/c/Tools/PsTools:/c/Program Files/Git LFS:/c/Program Files (x86)/Subversion/bin:/c/Program Files/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/110/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/ManagementStudio/:/c/Tools/WebDriver:/c/Program Files (x86)/Microsoft SDKs/TypeScript/1.4/:/c/Program Files (x86)/Microsoft Visual Studio 12.0/Common7/IDE/PrivateAssemblies/:/c/Program Files (x86)/Microsoft SDKs/Azure/CLI/wbin:/c/Ruby193/bin:/c/Tools/NUnit/bin:/c/Tools/xUnit:/c/Tools/MSpec:/c/Tools/Coverity/bin:/c/Program Files (x86)/CMake/bin:/c/go/bin:/c/Program Files/Java/jdk1.8.0/bin:/c/Python27:/c/Program Files/nodejs:/c/Program Files (x86)/iojs:/c/Program Files/iojs:/c/Users/appveyor/AppData/Roaming/npm:/c/Program Files/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/MSBuild/14.0/Bin:/c/Tools/NuGet:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/CommonExtensions/Microsoft/TestWindow:/c/Program Files/Microsoft DNX/Dnvm:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/110/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Apache/Maven/bin:/c/Python27/Scripts:/c/Tools/NUnit3:/c/Program Files/Mercurial/:/c/Program Files/LLVM/bin:/c/Program Files/dotnet/:/c/Tools/curl/bin:/c/Program Files/Amazon/AWSCLI/:/c/Program Files (x86)/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/Extensions/Microsoft/SQLDB/DAC/140:/c/Tools/vcpkg:/c/Program Files (x86)/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files/PowerShell/6.0.0/:/c/Program Files/erl9.2/bin:/c/Program Files (x86)/nodejs/:/c/Program Files/Git/cmd:/c/Program Files/Git/usr/bin:/c/Program Files (x86)/Yarn/bin/:/c/Program Files (x86)/NSIS:/c/Tools/Octopus:/c/Program Files/Microsoft Service Fabric/bin/Fabric/Fabric.Code:/c/Program Files/Microsoft SDKs/Service Fabric/Tools/ServiceFabricLocalClusterManager:/c/ProgramData/chocolatey/bin:/c/Users/appveyor/AppData/Roaming/npm:/c/Users/appveyor/AppData/Local/Yarn/bin:/c/Program Files/AppVeyor/BuildAgent/:/usr/texbin'
+ R_BUILD_ARGS=--no-manual
+ R_CHECK_ARGS=--no-manual
+ R_USE_BIOC_CMDS='source('\''http://bioconductor.org/biocLite.R'\''); tryCatch(useDevel(TRUE), error=function(e) {if (!grepl('\''already in use'\'', e)) {e}}); options(repos=biocinstallRepos());'
+ COMMAND=r_install
+ echo 'Running command: r_install'
Running command: r_install
+ shift
+ case $COMMAND in
+ RInstall nanotime
+ [[ '' == \n\a\n\o\t\i\m\e ]]
+ echo 'Installing R package(s): nanotime'
Installing R package(s): nanotime
+ Rscript -e 'install.packages(commandArgs(TRUE), repos="http://cloud.r-project.org/", INSTALL_opts="", type="both")' nanotime
Installing package into 'c:/RLibrary'
(as 'lib' is unspecified)
also installing the dependencies 'Rcpp', 'RcppCCTZ'
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/Rcpp_0.12.16.zip'
Content type 'application/zip' length 4504406 bytes (4.3 MB)
==================================================
downloaded 4.3 MB
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/RcppCCTZ_0.2.3.zip'
Content type 'application/zip' length 737064 bytes (719 KB)
==================================================
downloaded 719 KB
trying URL 'http://cloud.r-project.org/bin/windows/contrib/3.6/nanotime_0.2.0.zip'
Content type 'application/zip' length 114037 bytes (111 KB)
==================================================
downloaded 111 KB
package 'Rcpp' successfully unpacked and MD5 sums checked
package 'RcppCCTZ' successfully unpacked and MD5 sums checked
package 'nanotime' successfully unpacked and MD5 sums checked
The downloaded binary packages are in
	C:\Users\appveyor\AppData\Local\Temp\1\Rtmpcd9ieQ\downloaded_packages
travis-tool.sh run_tests
+ CRAN=http://cloud.r-project.org/
+ BIOC=http://bioconductor.org/biocLite.R
+ PKGTYPE=both
+ BIOC_USE_DEVEL=TRUE
++ uname -s
+ OS=MSYS_NT-6.3-WOW
+ PANDOC_VERSION=1.13.1
+ PANDOC_DIR=/opt/pandoc
+ PANDOC_URL=https://s3.amazonaws.com/rstudio-buildtools/pandoc-1.13.1.zip
+ PATH='/c/Rtools/bin:/c/Rtools/MinGW/bin:/c/Rtools/mingw_64/bin:/c/R/bin/x64:/c/Rtools/mingw_64/bin:/usr/bin:/c/Program Files (x86)/Git/bin:/c/Perl/site/bin:/c/Perl/bin:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0/:/c/Program Files/7-Zip:/c/Program Files/Microsoft/Web Platform Installer/:/c/Tools/GitVersion:/c/Tools/PsTools:/c/Program Files/Git LFS:/c/Program Files (x86)/Subversion/bin:/c/Program Files/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/110/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/:/c/Program Files/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/Tools/Binn/ManagementStudio/:/c/Tools/WebDriver:/c/Program Files (x86)/Microsoft SDKs/TypeScript/1.4/:/c/Program Files (x86)/Microsoft Visual Studio 12.0/Common7/IDE/PrivateAssemblies/:/c/Program Files (x86)/Microsoft SDKs/Azure/CLI/wbin:/c/Ruby193/bin:/c/Tools/NUnit/bin:/c/Tools/xUnit:/c/Tools/MSpec:/c/Tools/Coverity/bin:/c/Program Files (x86)/CMake/bin:/c/go/bin:/c/Program Files/Java/jdk1.8.0/bin:/c/Python27:/c/Program Files/nodejs:/c/Program Files (x86)/iojs:/c/Program Files/iojs:/c/Users/appveyor/AppData/Roaming/npm:/c/Program Files/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/MSBuild/14.0/Bin:/c/Tools/NuGet:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/CommonExtensions/Microsoft/TestWindow:/c/Program Files/Microsoft DNX/Dnvm:/c/Program Files/Microsoft SQL Server/Client SDK/ODBC/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/Tools/Binn/:/c/Program Files (x86)/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files/Microsoft SQL Server/130/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/110/DTS/Binn/:/c/Program Files (x86)/Microsoft SQL Server/120/DTS/Binn/:/c/Program Files (x86)/Apache/Maven/bin:/c/Python27/Scripts:/c/Tools/NUnit3:/c/Program Files/Mercurial/:/c/Program Files/LLVM/bin:/c/Program Files/dotnet/:/c/Tools/curl/bin:/c/Program Files/Amazon/AWSCLI/:/c/Program Files (x86)/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files (x86)/Microsoft Visual Studio 14.0/Common7/IDE/Extensions/Microsoft/SQLDB/DAC/140:/c/Tools/vcpkg:/c/Program Files (x86)/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/Tools/Binn/:/c/Program Files/Microsoft SQL Server/140/DTS/Binn/:/c/Program Files/PowerShell/6.0.0/:/c/Program Files/erl9.2/bin:/c/Program Files (x86)/nodejs/:/c/Program Files/Git/cmd:/c/Program Files/Git/usr/bin:/c/Program Files (x86)/Yarn/bin/:/c/Program Files (x86)/NSIS:/c/Tools/Octopus:/c/Program Files/Microsoft Service Fabric/bin/Fabric/Fabric.Code:/c/Program Files/Microsoft SDKs/Service Fabric/Tools/ServiceFabricLocalClusterManager:/c/ProgramData/chocolatey/bin:/c/Users/appveyor/AppData/Roaming/npm:/c/Users/appveyor/AppData/Local/Yarn/bin:/c/Program Files/AppVeyor/BuildAgent/:/usr/texbin'
+ R_BUILD_ARGS=--no-manual
+ R_CHECK_ARGS=--no-manual
+ R_USE_BIOC_CMDS='source('\''http://bioconductor.org/biocLite.R'\''); tryCatch(useDevel(TRUE), error=function(e) {if (!grepl('\''already in use'\'', e)) {e}}); options(repos=biocinstallRepos());'
+ COMMAND=run_tests
+ echo 'Running command: run_tests'
Running command: run_tests
+ shift
+ case $COMMAND in
+ RunTests
+ echo 'Building with: R CMD build --no-manual'
Building with: R CMD build --no-manual
+ [[ MSYS_ == \M\I\N\G\W ]]
+ [[ MSYS == \M\S\Y\S ]]
+ [[ -d vignettes ]]
+ rm -rf vignettes
+ Rscript -e 'd <- read.dcf('\''DESCRIPTION'\''); d[, colnames(d) == '\''VignetteBuilder'\''] <- NA; write.dcf(d, '\''DESCRIPTION'\'')'
+ R CMD build --no-manual .
* checking for file './DESCRIPTION' ... OK
* preparing 'data.table':
* checking DESCRIPTION meta-information ... OK
* cleaning src
* checking for LF line-endings in source and make files and shell scripts
* checking for empty or unneeded directories
* building 'data.table_1.11.1.tar.gz'
++ ls -1t data.table_1.11.1.tar.gz
++ head -n 1
+ FILE=data.table_1.11.1.tar.gz
+ [[ MSYS_ == \M\I\N\G\W ]]
+ [[ MSYS == \M\S\Y\S ]]
+ R_CHECK_INSTALL_ARGS=--install-args=--build
+ echo 'Testing with: R CMD check "data.table_1.11.1.tar.gz" --no-manual --install-args=--build'
Testing with: R CMD check "data.table_1.11.1.tar.gz" --no-manual --install-args=--build
+ _R_CHECK_CRAN_INCOMING_=FALSE
+ [[ FALSE == \F\A\L\S\E ]]
+ echo '(CRAN incoming checks are off)'
(CRAN incoming checks are off)
+ _R_CHECK_CRAN_INCOMING_=FALSE
+ R_QPDF=true
+ R CMD check data.table_1.11.1.tar.gz --no-manual --install-args=--build
* using log directory 'C:/projects/data-table/data.table.Rcheck'
* using R Under development (unstable) (2018-05-02 r74682)
* using platform: x86_64-w64-mingw32 (64-bit)
* using session charset: ISO8859-1
* using option '--no-manual'
* checking for file 'data.table/DESCRIPTION' ... OK
* this is package 'data.table' version '1.11.1'
* checking package namespace information ... OK
* checking package dependencies ... NOTE
Packages suggested but not available for checking:
  'curl' 'knitr' 'reshape2' 'testthat'
* checking if this is a source package ... OK
* checking if there is a namespace ... OK
* checking for executable files ... OK
* checking for hidden files and directories ... OK
* checking for portable file names ... OK
* checking whether package 'data.table' can be installed ... OK
* checking installed package size ... OK
* checking package directory ... OK
* checking DESCRIPTION meta-information ... OK
* checking top-level files ... OK
* checking for left-over files ... OK
* checking index information ... OK
* checking package subdirectories ... OK
* checking R files for non-ASCII characters ... OK
* checking R files for syntax errors ... OK
* loading checks for arch 'i386'
** checking whether the package can be loaded ... OK
** checking whether the package can be loaded with stated dependencies ... OK
** checking whether the package can be unloaded cleanly ... OK
** checking whether the namespace can be loaded with stated dependencies ... OK
** checking whether the namespace can be unloaded cleanly ... OK
** checking loading without being on the library search path ... OK
* loading checks for arch 'x64'
** checking whether the package can be loaded ... OK
** checking whether the package can be loaded with stated dependencies ... OK
** checking whether the package can be unloaded cleanly ... OK
** checking whether the namespace can be loaded with stated dependencies ... OK
** checking whether the namespace can be unloaded cleanly ... OK
** checking loading without being on the library search path ... OK
* checking dependencies in R code ... OK
* checking S3 generic/method consistency ... OK
* checking replacement functions ... OK
* checking foreign function calls ... OK
* checking R code for possible problems ... OK
* checking Rd files ... OK
* checking Rd metadata ... OK
* checking Rd cross-references ... NOTE
Package unavailable to check Rd xrefs: 'fastmatch'
* checking for missing documentation entries ... OK
* checking for code/documentation mismatches ... OK
* checking Rd \usage sections ... OK
* checking Rd contents ... OK
* checking for unstated dependencies in examples ... OK
* checking line endings in C/C++/Fortran sources/headers ... OK
* checking line endings in Makefiles ... OK
* checking compilation flags in Makevars ... OK
* checking for GNU extensions in Makefiles ... OK
* checking for portable use of $(BLAS_LIBS) and $(LAPACK_LIBS) ... OK
* checking compiled code ... OK
* checking examples ...
** running examples for arch 'i386' ... OK
** running examples for arch 'x64' ... OK
* checking for unstated dependencies in 'tests' ... OK
* checking tests ...
** running tests for arch 'i386' ...
  Running 'autoprint.R'
  Comparing 'autoprint.Rout' to 'autoprint.Rout.save' ... OK
  Running 'knitr.R'
  Comparing 'knitr.Rout' to 'knitr.Rout.save' ... OK
  Running 'main.R'
 ERROR
Running the tests in 'tests/main.R' failed.
Last 13 lines of output:
  Running test id 1253.195      
  Running test id 1253.196      
  Running test id 1253.197      
  Running test id 1253.198      
  Running test id 1253.199      
  Running test id 1253.2      
  Running test id 1253.201      
  Running test id 1253.202      
  Running test id 1253.203      
  Running test id 1253.204      
  Running test id 1253.205      
  Running test id 1253.206      
  Running test id 1253.207      Error: memory exhausted (limit reached?)
  Error: memory exhausted (limit reached?)
  Execution halted
** running tests for arch 'x64' ...
  Running 'autoprint.R'
  Comparing 'autoprint.Rout' to 'autoprint.Rout.save' ... OK
  Running 'knitr.R'
  Comparing 'knitr.Rout' to 'knitr.Rout.save' ... OK
  Running 'main.R'
 ERROR
Running the tests in 'tests/main.R' failed.
Last 13 lines of output:
  Running test id 1613.5531      
  Running test id 1613.5532      
  Running test id 1613.561      
  Running test id 1613.562      
  Running test id 1613.563      
  Running test id 1613.564      
  Running test id 1613.565      
  Running test id 1613.566      
  Running test id 1613.567      
  Running test id 1613.571      
  Running test id 1613.572      
  Running test id 1613.573      
  Running test id 1613.581      
  Running test id 1613.582      Error: memory exhausted (limit reached?)
  Execution halted
* DONE
Status: 2 ERRORs, 2 NOTEs
See
  'C:/projects/data-table/data.table.Rcheck/00check.log'
for details.
Command exited with code 1
7z a failure.zip *.Rcheck\*
7-Zip [64] 16.04 : Copyright (c) 1999-2016 Igor Pavlov : 2016-10-04
Scanning the drive:
26 folders, 462 files, 11121162 bytes (11 MiB)
Creating archive: failure.zip
Items to compress: 488
Files read from disk: 462
Archive size: 4104726 bytes (4009 KiB)
Everything is Ok
appveyor PushArtifact failure.zip
Uploading artifact failure.zip (4,104,726 bytes)...100%

This was referenced May 4, 2018
@adamaltmejd
Copy link

adamaltmejd commented May 7, 2018

Dont't know if related but I just ran into this fail during the join below that has been running fine before. The dt object is around 4gb in memory but when doing this join R memory usage in Activity Monitor increases to 16... my sessioninfo below.

dt[
    degrees[
        dt,
        max.int(SunNiva),
        on = .(id, KalenderAr < admission_year),
        by = .EACHI
    ],
    tmp.SunNiva_achieved_degree := i.V1,
    on = .(id, admission_year = KalenderAr)
]
R version 3.5.0 (2018-04-23)
Platform: x86_64-apple-darwin17.5.0 (64-bit)
Running under: macOS High Sierra 10.13.4

Matrix products: default
BLAS/LAPACK: /usr/local/Cellar/openblas/0.2.20_2/lib/libopenblas_haswellp-r0.2.20.dylib

data table: data.table 1.11.1 IN DEVELOPMENT built 2018-05-05

@mattdowle
Copy link
Member Author

@adamaltmejd Thanks for this -- great. Could you try again with master as of now please; a few memory faults fixed in the last few days. If it still fails, is there any way to generate some dummy data for us so we've got something to run?

@adamaltmejd
Copy link

Just tried reinstalling with install_github("Rdatatable/data.table", build_vignettes=FALSE), same error.

Before doing that however I noticed that also my backup script that was using dplyr to get around some other data.table issues (fread and NUL bytes) also ran into the same memory error on a dplyr operation. Maybe its actually something with my data that has changed that I can't pinpoint, or with R 3.5.0 i guess. Or its related to the data table object already in memory..

Kind of tricky to reproduce, data is confidential. But will try as soon as I have some more time.

@jangorecki jangorecki modified the milestones: 1.11.2, 1.11.4 May 9, 2018
@mattdowle mattdowle modified the milestones: 1.11.6, 1.11.4 May 9, 2018
@jangorecki
Copy link
Member

jangorecki commented May 11, 2018

@mattdowle I run memtest for windows and got the following (windows uses only gc() measures, not ps). At least something that explains hitting 2GB limit, and it also confirms the range of tests when issue starting to occur. You can reproduce yourself on w1.

# x64 win r-devel
data.table::fread("wget -q https://github.com/Rdatatable/data.table/files/1995905/memtest.csv.zip && unzip -cq memtest.csv.zip"
  )[, last_GC_used := data.table::shift(GC_used)
    ][, GC_used_diff := GC_used-last_GC_used
      ][order(-GC_used_diff), head(.SD, 10), .SDcols=c("test", "GC_used", "GC_used_diff")]
#        test GC_used GC_used_diff
#       <num>   <num>        <num>
# 1: 1848.000  7875.9        441.8
# 2: 1835.000  7405.1        316.2
# 3: 1739.400  6581.1         58.6
# 4: 1739.100  6519.8         49.6
# 5: 1158.000   100.3         48.5
# 6: 1750.800  6668.4         37.4
# 7: 1549.000  2670.7         35.4
# 8: 1542.000  2597.2         35.1
# 9: 1642.001  3661.0         33.8
#10: 1779.800  6960.8         24.2

So 1848 and 1835 seems to be contributing the most to GC_used measure. Smallest test number, so potentially first one (in this top 10) is 1158 which is causing problems described in #2854.

@HughParsonage are you able to run memtest on your R-devel to confirm below numbers? just set env var TEST_DATA_TABLE_MEMTEST=TRUE and call test.data.table. Be aware single run took ~50 minutes. Ignore ps -o warnings in output (I hope they won't stop tests, I might have fixed that already in my dev branch).

Windows R Under development (unstable) (2018-05-05 r74699)

i386

memtest.csv.zip
memtest

x64

memtest.csv.zip
memtest

Windows R version 3.5.0 (2018-04-23)

i386

memtest.csv.zip
memtest

x64

memtest.csv.zip
memtest

Linux R version 3.4.4 (2018-03-15)

memtest.csv.zip
memtest

@HughParsonage
Copy link
Member

HughParsonage commented May 11, 2018

R dev r74708 Windows 64 bit

data.table 1.11.3 2018-05-11 01:26:09 UTC

memtest.csv.txt

@jangorecki
Copy link
Member

jangorecki commented May 11, 2018

It seems to be very fast on your machine, but also confirms memory used.

tail(data.table::fread("https://github.com/Rdatatable/data.table/files/1996044/memtest.csv.txt"), 3)
#     inittime   filename  timestamp   test PS_rss GC_used GC_gc_trigger   GC_max_used
#1: 1526054564 tests.Rraw 1526054785 1894.2     NA  8129.3        8185.1         179.2
#2: 1526054564 tests.Rraw 1526054785 1894.3     NA  8130.1        8185.9         179.2
#3: 1526054564 tests.Rraw 1526054785 1894.4     NA  8130.9        8186.7         179.2

@HughParsonage
Copy link
Member

Have I done something wrong? It's a 5 year old laptop that cost about $500...

@jangorecki
Copy link
Member

Not sure. 50 min on my machine was actually R CMD check and installing some deps from source, not just test.data.table. Tests and examples for i386 and x64. How much RAM you have?

@HughParsonage
Copy link
Member

8 GB

This was referenced May 11, 2018
@adamaltmejd
Copy link

Just managed to run a version of the script referenced in my post above but with a larger data set on a proper server with 120GB RAM, and it worked, using 80Gb memory at peak. Using R 3.5.0 and CRAN version of datatable (server for confidential data so not allowed to install newer version).

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

No branches or pull requests

5 participants