CRAN Windows crash/hang in checks

[mattdowle]

Still happening with 1.14.4. So #5421 didn't fix it.
I'll ask Uwe if he can provide any more insight about where the problem is occurring. Hopefully there are some more logs that he can look at or send that are not displayed on CRAN.

using R Under development (unstable) (2022-10-11 r83083 ucrt)
using platform: x86_64-w64-mingw32 (64-bit)
using session charset: UTF-8
checking for file 'data.table/DESCRIPTION' ... OK
this is package 'data.table' version '1.14.4'
checking package namespace information ... OK
checking package dependencies ... OK
checking if this is a source package ... OK
checking if there is a namespace ... 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 'build' 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
checking whether the package can be loaded ... [1s] OK
checking whether the package can be loaded with stated dependencies ... [1s] OK
checking whether the package can be unloaded cleanly ... [1s] OK
checking whether the namespace can be loaded with stated dependencies ... [1s] OK
checking whether the namespace can be unloaded cleanly ... [1s] OK
checking loading without being on the library search path ... [1s] OK
checking use of S3 registration ... 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 ... [25s] OK
checking Rd files ... [5s] OK
checking Rd metadata ... OK
checking Rd cross-references ... OK
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 shell scripts ... 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 use of PKG_*FLAGS in Makefiles ... OK
checking include directives in Makefiles ... OK
checking pragmas in C/C++ headers and code ... OK
checking compiled code ... OK
checking installed files from 'inst/doc' ... OK
checking files in 'vignettes' ... OK
checking examples ... [9s] OK
checking for unstated dependencies in 'tests' ... OK
checking tests ...
Check process probably crashed or hung up for 20 minutes ... killed
Most likely this happened in the example checks (?),
if not, ignore the following last lines of example output:
>
> ### Name: update_dev_pkg
> ### Title: Perform update of development version of a package
> ### Aliases: update_dev_pkg
> ### Keywords: data
>
> ### ** Examples
>
> ## Don't show:
> # using if(FALSE) because \dontrun could still be run by --run-dontrun; #5421
> ## End(Don't show)
> if (FALSE) data.table::update_dev_pkg()
>
>
>
> ### * <FOOTER>
> ###
> cleanEx()
> options(digits = 7L)
> base::cat("Time elapsed: ", proc.time() - base::get("ptime", pos = 'CheckExEnv'),"\n")
Time elapsed: 7.5 0.15 9.06 NA NA
> grDevices::dev.off()
null device
          1
> ###
> ### Local variables: ***
> ### mode: outline-minor ***
> ### outline-regexp: "\\(> \\)?### [*]+" ***
> ### End: ***
> quit('no')
======== End of example output (where/before crash/hang up occured ?) ========

[mattdowle]

From Matt
To Uwe and CRAN

---

Thanks Uwe. I can now see data.table 1.14.4 displaying check results
on CRAN for Windows.

Still FAIL.

I asked Uwe on Jan 26th and Jan 31st for full logs but didn't hear from Uwe.

So I did the best I could to guess and fix what I could. But my
attempt in 1.14.4 did not work. I didn't think it was anything to do
with update.dev.pkg.Rd but I did what I could just in case.

That time has been lost and I now absolutely need data.table.Rcheck to
be sent to me please.

I explained in January why. Perhaps the email was too long. So then I
sent a shorter follow up in January but still no reply.

Failed attempt: #5421
New issue: #5507

I am not asking for anything from Uwe other than for him to just send
me the entire contents of data.table.Rcheck. Or if there's a way I can
find that online, I don't know it.

On Mon, Jan 31, 2022 at 5:04 PM Matt Dowle wrote:

Uwe,
If you could send me the logs (e.g. the data.table.Rcheck directory)
then I can have a look to see what might be taking so long on Windows
and perhaps address it in the next data.table update.
I see that r-devel-windows-x86_64-new-UL is currently in FAIL status
after 20 mins.
Longer email below.
Best, Matt

On Wed, Jan 26, 2022 at 12:14 PM Matt Dowle wrote:

Hi Uwe,

Hope you're well. Happy new year!

I noticed check times on Windows CRAN are higher for data.table than
on the other non-Windows CRAN machines; e.g. 1560 seconds for
r-devel-windows-x86_64-new-UL.

I realize Windows runs twice: for 32bit and 64 bit, but even so, it
still appears high. I noticed it has sometimes failed recently with
runtime too high message, although it appears ok now after an
automatic rerun I guess.

I can try to address this in the next data.table update. But I'm a
little unclear on where to focus. At the end of
data.table.Rcheck/tests/main.Rout it shows me locally the following :

10 longest running tests took 14s (38% of 38s)
ID time nTest
1: 2155 2.170 5
2: 1438 1.886 738
3: 1648 1.600 91
4: 1848 1.552 2
5: 1888 1.503 9
6: 1652 1.442 91
7: 1650 1.428 91
8: 1912 1.054 2
9: 1437 1.045 36
10: 1874 1.038 5
All 10957 tests (last 2236.45) in tests/tests.Rraw completed ok in 38.4s elapsed
(51.7s cpu)

But I don't have access to that output on CRAN. And since this is
under 1 minute total for me locally, this might not be the right place
for me to focus. For example, perhaps the bigger time is in the
vignettes, and there is a vignette that springs to mind I could look
at.

I realize you also check other packages in parallel, however
data.table should only be using 2 threads as per CRAN policy. Even so,
maybe something is taking longer on Windows to do with
multi-threading, or the way data.table is interacting with other
package tests (e.g. memory usage) happening at the same time.

Could you send me the entire data.table.Rcheck directory so I can look
through the detailed logs so I can try to see what is taking so long?

Also, do you have any guess where it might be getting stuck? I'm
happy to work on a hunch from you if you have one.

Best, Matt

[mattdowle]

Currently CRAN Windows is showing OK so we have some clues. The Ttotal is very long: 22m devel and 17m release and that's mostly in main.R tests: 14m and 9min. If the past repeats itself, the FAIL status will return in a few days or weeks. Haven't heard from Uwe but I wonder if he's done anything manual to make it run this time. My best guess is that the Windows machine is overloaded with package checks running in parallel; e.g. even just installing is significantly slower than the linux and mac CRAN machines. So much so that some tests in tests.Rraw which use more memory cause the machine to swap. Hence the slow down and then kill. It would be very useful to have the full logs from Uwe, in particular the final table I showed above containing the longest running tests. But without those logs, using local stats to tackle and reduce longest and most-RAM-using tests, is one way forward. At least we know now that it's likely tests.Rraw and not a different test file or a vignette.

using R Under development (unstable) (2022-10-11 r83083 ucrt)
using platform: x86_64-w64-mingw32 (64-bit)
using session charset: UTF-8
checking for file 'data.table/DESCRIPTION' ... OK
this is package 'data.table' version '1.14.4'
checking package namespace information ... OK
checking package dependencies ... OK
checking if this is a source package ... OK
checking if there is a namespace ... 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 'build' 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
checking whether the package can be loaded ... [1s] OK
checking whether the package can be loaded with stated dependencies ... [1s] OK
checking whether the package can be unloaded cleanly ... [1s] OK
checking whether the namespace can be loaded with stated dependencies ... [1s] OK
checking whether the namespace can be unloaded cleanly ... [1s] OK
checking loading without being on the library search path ... [1s] OK
checking use of S3 registration ... 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 ... [25s] OK
checking Rd files ... [4s] OK
checking Rd metadata ... OK
checking Rd cross-references ... OK
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 shell scripts ... 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 use of PKG_*FLAGS in Makefiles ... OK
checking include directives in Makefiles ... OK
checking pragmas in C/C++ headers and code ... OK
checking compiled code ... OK
checking installed files from 'inst/doc' ... OK
checking files in 'vignettes' ... OK
checking examples ... [9s] OK
checking for unstated dependencies in 'tests' ... OK
checking tests ... [15m] OK
  Running 'autoprint.R' [1s]
  Comparing 'autoprint.Rout' to 'autoprint.Rout.save' ... OK
  Running 'froll.R' [28s]
  Running 'knitr.R' [1s]
  Comparing 'knitr.Rout' to 'knitr.Rout.save' ... OK
  Running 'main.R' [14m]
  Running 'nafill.R' [2s]
  Running 'other.R' [1s]
  Running 'types.R' [1s]
checking for unstated dependencies in vignettes ... OK
checking package vignettes in 'inst/doc' ... OK
checking re-building of vignette outputs ... [62s] OK
checking PDF version of manual ... [32s] OK
checking HTML version of manual ... [18s] OK
DONE
Status: OK

using R version 4.2.2 (2022-10-31 ucrt)
using platform: x86_64-w64-mingw32 (64-bit)
using session charset: UTF-8
checking for file 'data.table/DESCRIPTION' ... OK
this is package 'data.table' version '1.14.4'
checking package namespace information ... OK
checking package dependencies ... OK
checking if this is a source package ... OK
checking if there is a namespace ... 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 'build' 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
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 use of S3 registration ... 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 ... [25s] OK
checking Rd files ... [7s] OK
checking Rd metadata ... OK
checking Rd cross-references ... OK
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 shell scripts ... 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 use of PKG_*FLAGS in Makefiles ... OK
checking include directives in Makefiles ... OK
checking pragmas in C/C++ headers and code ... OK
checking compiled code ... OK
checking installed files from 'inst/doc' ... OK
checking files in 'vignettes' ... OK
checking examples ... [9s] OK
checking for unstated dependencies in 'tests' ... OK
checking tests ... [566s] OK
  Running 'autoprint.R' [1s]
  Comparing 'autoprint.Rout' to 'autoprint.Rout.save' ... OK
  Running 'froll.R' [25s]
  Running 'knitr.R' [1s]
  Comparing 'knitr.Rout' to 'knitr.Rout.save' ... OK
  Running 'main.R' [535s]
  Running 'nafill.R' [2s]
  Running 'other.R' [1s]
  Running 'types.R' [1s]
checking for unstated dependencies in vignettes ... OK
checking package vignettes in 'inst/doc' ... OK
checking re-building of vignette outputs ... [62s] OK
checking PDF version of manual ... OK
checking HTML version of manual ... OK
DONE
Status: OK

[mattdowle]

From Matt
To Uwe and CRAN

---

Uwe,

I can see data.table 1.14.4 is OK now on CRAN Windows, but barely.

https://cran.r-project.org/web/checks/check_results_data.table.html

Just Tinstall is 215 and 308 on r-devel and r-release respectively,
which is much higher than expected and much higher than Linux shows.
It takes longer to just install on Windows than Mac takes to install
and run all checks too! (Mac doesn't show Tinstall so I compared to
Ttotal.)

I see similar very long CRAN Windows timings for other packages I
glanced at too.

Are the Windows servers severely overloaded?

I'm expecting data.table to fail again on Windows soon, as it has
before, due to the kill at 20 mins. What to do?

This email added to issue tracker here: #5507

Best, Matt

[mattdowle]

Current status of CRAN Windows :

• Tinstall over 5 mins vs 42s on Linux. Similar slowness for Tinstall for other packages; e.g. package boot 54s Windows vs 6s on Linux, and survival 274s vs 71s.
• Tcheck 0.00 despite check output being displayed; perhaps that output is just from the last run. There is no timestamp included in the log displayed otherwise we'd be able to know that. I added a timestamp into our output years ago but it doesn't get that far.
• Ttotal == Tinstall so it seems like it isn't getting past installation.
• Tinstall different figures to last image pasted in comment above; so it does seem to have installed again at least, perhaps.

Maybe after it is killed, it is put in a hold state. That would make sense, in general, to not keep checking packages which are known to have been killed. However, it seems that the machine is so severely overloaded that even Tinstall is taking so much longer for many packages, not just data.table. I doubt it's Windows per se; rather that server and how many tasks are running on it concurrently.

Version: 1.14.4
Check: tests
Result: FAIL
    Check process probably crashed or hung up for 20 minutes ... killed
    Most likely this happened in the example checks (?),
    if not, ignore the following last lines of example output:
    >
    > ### Name: update_dev_pkg
    > ### Title: Perform update of development version of a package
    > ### Aliases: update_dev_pkg
    > ### Keywords: data
    >
    > ### ** Examples
    >
    > ## Don't show:
    > # using if(FALSE) because \dontrun could still be run by --run-dontrun; #5421
    > ## End(Don't show)
    > if (FALSE) data.table::update_dev_pkg()
    >
    >
    >
    > ### * <FOOTER>
    > ###
    > cleanEx()
    > options(digits = 7L)
    > base::cat("Time elapsed: ", proc.time() - base::get("ptime", pos = 'CheckExEnv'),"\n")
    Time elapsed: 8.86 0.2 10.09 NA NA
    > grDevices::dev.off()
    null device
     1
    > ###
    > ### Local variables: ***
    > ### mode: outline-minor ***
    > ### outline-regexp: "\\(> \\)?### [*]+" ***
    > ### End: ***
    > quit('no')
    ======== End of example output (where/before crash/hang up occured ?) ========
Flavor: [r-devel-windows-x86_64](https://www.r-project.org/nosvn/R.check/r-devel-windows-x86_64/data.table-00check.html)

Version: 1.14.4
Check: tests
Result: FAIL
    Check process probably crashed or hung up for 20 minutes ... killed
    Most likely this happened in the example checks (?),
    if not, ignore the following last lines of example output:
    >
    > ### Name: update_dev_pkg
    > ### Title: Perform update of development version of a package
    > ### Aliases: update_dev_pkg
    > ### Keywords: data
    >
    > ### ** Examples
    >
    > ## Don't show:
    > # using if(FALSE) because \dontrun could still be run by --run-dontrun; #5421
    > ## End(Don't show)
    > if (FALSE) data.table::update_dev_pkg()
    >
    >
    >
    > ### * <FOOTER>
    > ###
    > cleanEx()
    > options(digits = 7L)
    > base::cat("Time elapsed: ", proc.time() - base::get("ptime", pos = 'CheckExEnv'),"\n")
    Time elapsed: 7.97 0.22 9.28 NA NA
    > grDevices::dev.off()
    null device
     1
    > ###
    > ### Local variables: ***
    > ### mode: outline-minor ***
    > ### outline-regexp: "\\(> \\)?### [*]+" ***
    > ### End: ***
    > quit('no')
    ======== End of example output (where/before crash/hang up occured ?) ========
Flavor: [r-release-windows-x86_64](https://www.r-project.org/nosvn/R.check/r-release-windows-x86_64/data.table-00check.html)

[mattdowle]

1.14.6 has run on r-devel-windows. At least it completed but Tinstall (just install no tests) is way too high vs other CRAN machines and locally.

16m in main.R is crazy high. That's 30s for me locally and under 2 mins on CRAN Linux and CRAN Mac. It's because CRAN's Windows server is so overloaded that it's wasting the majority of its time context switching, L2 cache churn, or could even be swapping.

using R Under development (unstable) (2022-10-11 r83083 ucrt)
using platform: x86_64-w64-mingw32 (64-bit)
using session charset: UTF-8
checking for file 'data.table/DESCRIPTION' ... OK
this is package 'data.table' version '1.14.6'
checking package namespace information ... OK
checking package dependencies ... OK
checking if this is a source package ... OK
checking if there is a namespace ... 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 'build' 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
checking whether the package can be loaded ... [1s] OK
checking whether the package can be loaded with stated dependencies ... [1s] OK
checking whether the package can be unloaded cleanly ... [1s] OK
checking whether the namespace can be loaded with stated dependencies ... [1s] OK
checking whether the namespace can be unloaded cleanly ... [1s] OK
checking loading without being on the library search path ... [1s] OK
checking use of S3 registration ... 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 ... [25s] OK
checking Rd files ... [7s] OK
checking Rd metadata ... OK
checking Rd cross-references ... OK
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 shell scripts ... 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 use of PKG_*FLAGS in Makefiles ... OK
checking include directives in Makefiles ... OK
checking pragmas in C/C++ headers and code ... OK
checking compiled code ... OK
checking installed files from 'inst/doc' ... OK
checking files in 'vignettes' ... OK
checking examples ... [10s] OK
checking for unstated dependencies in 'tests' ... OK
checking tests ... [17m] OK
  Running 'autoprint.R' [1s]
  Comparing 'autoprint.Rout' to 'autoprint.Rout.save' ... OK
  Running 'froll.R' [31s]
  Running 'knitr.R' [1s]
  Comparing 'knitr.Rout' to 'knitr.Rout.save' ... OK
  Running 'main.R' [16m]
  Running 'nafill.R' [1s]
  Running 'other.R' [0s]
  Running 'types.R' [0s]
checking for unstated dependencies in vignettes ... OK
checking package vignettes in 'inst/doc' ... OK
checking re-building of vignette outputs ... [33s] OK
checking PDF version of manual ... [18s] OK
checking HTML version of manual ... [15s] OK
DONE
Status: OK

---

From Matt to Uwe cc CRAN

Uwe,

2 week follow up. (This time as plain text.)

Your Windows server has too many tasks running on it concurrently. It
is wasting its time context switching and in L2 cache churn.

You can complete the same work, on the same server, in less time, by
reducing the number of tasks that run concurrently. So for example if
you run 4 packages at a time in R-release, and 4 packages at a time in
R-devel, then you could reduce to 2 packages at a time in R-release
and 2 packages at a time in R-devel.

Again: I'm looking at Tinstall time, comparing to CRAN Mac and CRAN
Linux, for other packages too. Tinstall is merely installing the
package. Unless perhaps if you have install setup to also rebuild
vignettes.

Again: I don't think it's Windows per se. It's that you are asking it
to run too many tasks concurrently. It is not just number of cpus but
the size of L2 cache that is shared by the tasks.

Best, Matt

[mattdowle]

We might not see a FAIL on CRAN Windows for some months, but if so that'll just be because our memory usage reduction of tests tipped it under the threshold. That just kicked the can down the road. The root cause is the CRAN Windows server itself which is out of our hands.
Hence closing.

[MichaelChirico]

FWIW, just came across this summary table CRAN provides:

https://cran.r-project.org/web/checks/check_timings.html

We can see that on average installation (Tinstall) is ~3x longer on Windows. One has to assume there's a difference for packages with/without compiled code, and that compilation likely makes the gap wider, so data.table's 5x gap may be roughly typical for packages with compiled code.

[mattdowle]

Nice find. Not seen that before. All the 'Details' links are broken sadly, and it doesn't say over what time period. Good find also that package lintr exhibits the same problem as data.table, and even more severely; I commented over there: r-lib/lintr#1775 (comment)

[mattdowle]

I wonder if r-release and r-devel checks run on the same server, but r-oldrel runs on a different one. That's what it feels like to me. Btw, the r-oldrel checks include both 32bit and 64bit tests just because that's what r-oldrel did before 32bit support was removed. But despite running tests twice, r-oldrel is still faster because that server, although still overloaded, is not as overloaded as the r-release+r-devel one. Guessing.

[mattdowle]

From Matt to Uwe cc CRAN
Mode: Plain text not HTML
Subject: Very high Tinstall times on CRAN Windows; 5 prior emails no response

Dear Uwe,

I will keep sending these emails monthly until you or someone on the
CRAN team replies.

Tinstall is very high for CRAN Windows.
So high in fact that it indicates that something is wrong; e.g. too
many tasks running, virus scanner running for weeks, swapping.
Tinstall does not include running tests: it's just installing the package.
Tinstall is very high for a lot of packages indicating that it is not
related to particular packages.

Prior emails no response: Nov 18th, Nov 4th, Oct 31, Jan 31, Jan 26

I made a detailed suggestion to reduce the number of tasks running
concurrently which is just a config change. That can get the same work
done on the same server in less time.

It would help if someone from the CRAN team could reply to confirm
that the CRAN team is aware that there is a problem.

Best, Matt