Reports of large memory usage on workers

[wlandau]

The following reprex reports large memory usage on the workers. Does it really go up to 2541405.0 Mb?

packageVersion("clustermq")
#> [1] '0.8.95.1'
options(clustermq.scheduler = "multiprocess")
f <- function(x) 2 * x
o <- clustermq::Q(f, x = 1:2, n_jobs = 2)
#> Starting 2 processes ...
#> Running 2 calculations (0 objs/0 Mb common; 1 calls/chunk) ...
#> Master: [0.8s 13.1% CPU]; Worker: [avg 60.6% CPU, max 2541405.0 Mb]

^{Created on 2021-03-24 by the reprex package (v1.0.0)}

Session info

sessioninfo::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value                       
#>  version  R version 4.0.3 (2020-10-10)
#>  os       macOS Catalina 10.15.7      
#>  system   x86_64, darwin17.0          
#>  ui       X11                         
#>  language (EN)                        
#>  collate  en_US.UTF-8                 
#>  ctype    en_US.UTF-8                 
#>  tz       America/New_York            
#>  date     2021-03-24                  
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version  date       lib source        
#>  assertthat    0.2.1    2019-03-21 [1] CRAN (R 4.0.0)
#>  backports     1.2.1    2020-12-09 [1] CRAN (R 4.0.2)
#>  callr         3.5.1    2020-10-13 [1] CRAN (R 4.0.2)
#>  cli           2.3.1    2021-02-23 [1] CRAN (R 4.0.2)
#>  clustermq     0.8.95.1 2020-07-13 [1] CRAN (R 4.0.2)
#>  codetools     0.2-18   2020-11-04 [1] CRAN (R 4.0.2)
#>  crayon        1.4.1    2021-02-08 [1] CRAN (R 4.0.2)
#>  debugme       1.1.0    2017-10-22 [1] CRAN (R 4.0.2)
#>  digest        0.6.27   2020-10-24 [1] CRAN (R 4.0.2)
#>  ellipsis      0.3.1    2020-05-15 [1] CRAN (R 4.0.0)
#>  evaluate      0.14     2019-05-28 [1] CRAN (R 4.0.0)
#>  fansi         0.4.2    2021-01-15 [1] CRAN (R 4.0.2)
#>  fs            1.5.0    2020-07-31 [1] CRAN (R 4.0.2)
#>  glue          1.4.2    2020-08-27 [1] CRAN (R 4.0.2)
#>  highr         0.8      2019-03-20 [1] CRAN (R 4.0.0)
#>  hms           1.0.0    2021-01-13 [1] CRAN (R 4.0.2)
#>  htmltools     0.5.1.1  2021-01-22 [1] CRAN (R 4.0.2)
#>  knitr         1.31     2021-01-27 [1] CRAN (R 4.0.2)
#>  lifecycle     1.0.0    2021-02-15 [1] CRAN (R 4.0.3)
#>  magrittr      2.0.1    2020-11-17 [1] CRAN (R 4.0.2)
#>  pillar        1.5.1    2021-03-05 [1] CRAN (R 4.0.2)
#>  pkgconfig     2.0.3    2019-09-22 [1] CRAN (R 4.0.0)
#>  prettyunits   1.1.1    2020-01-24 [1] CRAN (R 4.0.0)
#>  processx      3.4.5    2020-11-30 [1] CRAN (R 4.0.2)
#>  progress      1.2.2    2019-05-16 [1] CRAN (R 4.0.0)
#>  ps            1.6.0    2021-02-28 [1] CRAN (R 4.0.3)
#>  purrr         0.3.4    2020-04-17 [1] CRAN (R 4.0.0)
#>  R6            2.5.0    2020-10-28 [1] CRAN (R 4.0.2)
#>  Rcpp          1.0.6    2021-01-15 [1] CRAN (R 4.0.2)
#>  reprex        1.0.0    2021-01-27 [1] CRAN (R 4.0.2)
#>  rlang         0.4.10   2020-12-30 [1] CRAN (R 4.0.2)
#>  rmarkdown     2.7      2021-02-19 [1] CRAN (R 4.0.3)
#>  sessioninfo   1.1.1    2018-11-05 [1] CRAN (R 4.0.0)
#>  stringi       1.5.3    2020-09-09 [1] CRAN (R 4.0.2)
#>  stringr       1.4.0    2019-02-10 [1] CRAN (R 4.0.0)
#>  styler        1.3.2    2020-02-23 [1] CRAN (R 4.0.2)
#>  tibble        3.1.0    2021-02-25 [1] CRAN (R 4.0.3)
#>  utf8          1.2.1    2021-03-12 [1] CRAN (R 4.0.2)
#>  vctrs         0.3.6    2020-12-17 [1] CRAN (R 4.0.2)
#>  withr         2.4.1    2021-01-26 [1] CRAN (R 4.0.2)
#>  xfun          0.21     2021-02-10 [1] CRAN (R 4.0.2)
#>  yaml          2.2.1    2020-02-01 [1] CRAN (R 4.0.0)
#> 
#> [1] /Library/Frameworks/R.framework/Versions/4.0/Resources/library

[mschubert]

This happens sometimes, but I haven't tracked it down yet.

Can you show me your output of gc()?

[wlandau]

Sure, here is the same reprex with gc() at the end:

packageVersion("clustermq")
#> [1] '0.8.95.1'
options(clustermq.scheduler = "multiprocess")
f <- function(x) 2 * x
o <- clustermq::Q(f, x = 1:2, n_jobs = 2)
#> Starting 2 processes ...
#> Running 2 calculations (0 objs/0 Mb common; 1 calls/chunk) ...
#> Master: [0.7s 13.6% CPU]; Worker: [avg 60.0% CPU, max 2541187.0 Mb]
gc()
#>           used (Mb) gc trigger (Mb) limit (Mb) max used (Mb)
#> Ncells  780210 41.7    1446692 77.3         NA  1446692 77.3
#> Vcells 1446396 11.1    8388608 64.0      16384  2464813 18.9

^{Created on 2021-03-25 by the reprex package (v1.0.0)}

[mschubert]

Ok, the reason for this is that I try to use the (Mb) column after max used (column 6) for the maximum Mb used during the time the worker was running.

For me, gc() looks like this:

          used (Mb) gc trigger (Mb) max used (Mb)
Ncells  688430 36.8    1248045 66.7  1248045 66.7
Vcells 1268353  9.7    8388608 64.0  2350433 18.0

and here column 6 is correct. It does look, however, that this is not always column 6.

A better way to get this would be:

--- a/R/worker.r
+++ b/R/worker.r
@@ -125,10 +125,12 @@ worker = function(master, timeout=getOption("clustermq.worker.timeout", 600),
     run_time = proc.time() - start_time

     message("shutting down worker")
+    gc = gc()
+    max_mb = which(colnames(gc) == "max used") + 1
     zmq$send(list(
         id = "WORKER_DONE",
         time = run_time,
-        mem = sum(gc()[,6]),
+        mem = sum(gc[,max_mb]),
         calls = counter,
         auth = auth
     ))

[wlandau]

Confirmed fixed, thanks!

packageVersion("clustermq")
#> [1] '0.8.95.1'
options(clustermq.scheduler = "multiprocess")
f <- function(x) 2 * x
o <- clustermq::Q(f, x = 1:2, n_jobs = 2)
#> Starting 2 processes ...
#> Running 2 calculations (0 objs/0 Mb common; 1 calls/chunk) ...
#> Master: [0.9s 12.6% CPU]; Worker: [avg 58.3% CPU, max 250.7 Mb]

^{Created on 2021-03-25 by the reprex package (v1.0.0)}

By the way, are you still using the develop branch? I noticed that commit is on master but not develop.

[mschubert]

Thanks for confirming!

I've got a couple of commits lined up for develop, but they are part of a larger change so I haven't pushed them yet.