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

profmem can't always parse output returned by (some) parallelized calls #14

Open
fabian-s opened this issue Oct 6, 2019 · 4 comments
Open

Comments

@fabian-s
Copy link

fabian-s commented Oct 6, 2019

this is stochastic, the failing examples below sometimes work for smaller jobs with fewer calls.

  • seems to affect fork-ed computations, mainly, but not consistently (cf. future.lapply, which never failed me so far)
  • suspect that if multiple jobs write into the same logfile simultaneously, that outfile gets corrupted.
  • errors are triggered from:
> bench::mark(parallel::mclapply(seq_len(1e3), keep_busy))
Error in parse(text = trace) : <text>:1:88: unexpected symbol
1: c("qnorm", "FUN", "lapply", "doTryCatch", "tryCatchOne", "tryCatchList", "tryCat2048 :"seq.default
                                                                                         ^

Enter a frame number, or 0 to exit   

1: bench::mark(parallel::mclapply(seq_len(1000), keep_busy))
2: eval_one(exprs[[i]])
3: parse_allocations(f)
4: profmem::readRprofmem(filename)
5: lapply(bfr, FUN = function(x) {
    bytes <- gsub(pattern, "\\1", x)
    wh
6: FUN(X[[i]], ...)
7: eval(parse(text = trace))
8: parse(text = trace)

reprex:

keep_busy <- function(n = 1e3) {
  r <- rnorm(n)
  p <- pnorm(r)
  q <- qnorm(p)
  o <- order(q)
}
bench::mark(parallel::mclapply(seq_len(1e3), keep_busy))
#> Error in parse(text = trace): <text>:1:158: unexpected symbol
#> 1: c("rnorm", "FUN", "lapply", "doTryCatch", "tryCatchOne", "tryCatchList", "tryCatch", "try", "sendMaster", "FUN", "lapply", "<Anonymous>", "eval", "eval", " "tryCatchOne
#>                                                                                                                                                                  ^

bench::mark(parallel::parLapply(seq_len(1e3), keep_busy,
                                cl = parallel::makeCluster(3)))
#> # A tibble: 1 x 6
#> # … with 6 more variables: expression <bch:expr>, min <bch:tm>,
#> #   median <bch:tm>, `itr/sec` <dbl>, mem_alloc <bch:byt>, `gc/sec` <dbl>

library(foreach)
library(doParallel); registerDoParallel(cores = 3)
#> Loading required package: iterators
#> Loading required package: parallel
bench::mark({foreach(x = seq_len(1e3)) %dopar% keep_busy})
#> Error in parse(text = trace): <text>:1:255: unexpected symbol
#> 1: lize", "sendMaster", "FUN", "lapply", "mclapply", "<Anonymous>", "%dopar%", "eval", "eval", "eval_one", "<Anonymous>", "eval", "eval", "withVisible", "withCallingHandlers", "doTryCatch", "tryC
#>                                                                                                                                                                                                                                                                   ^

future::plan("multicore")
bench::mark(future.apply::future_lapply(seq_len(1e3), keep_busy))
#> # A tibble: 1 x 6
#>   expression                                              min median
#>   <bch:expr>                                            <bch> <bch:>
#> 1 future.apply::future_lapply(seq_len(1000), keep_busy) 107ms  107ms
#> # … with 3 more variables: `itr/sec` <dbl>, mem_alloc <bch:byt>,
#> #   `gc/sec` <dbl>

future::plan("multisession")
bench::mark(future.apply::future_lapply(seq_len(1e3), keep_busy))
#> Warning: Some expressions had a GC in every iteration; so filtering is
#> disabled.
#> # A tibble: 1 x 6
#>   expression                                              min median
#>   <bch:expr>                                            <bch> <bch:>
#> 1 future.apply::future_lapply(seq_len(1000), keep_busy) 552ms  552ms
#> # … with 3 more variables: `itr/sec` <dbl>, mem_alloc <bch:byt>,
#> #   `gc/sec` <dbl>

future::plan("sequential")
bench::mark(future.apply::future_lapply(seq_len(1e3), keep_busy))
#> # A tibble: 1 x 6
#>   expression                                              min median
#>   <bch:expr>                                            <bch> <bch:>
#> 1 future.apply::future_lapply(seq_len(1000), keep_busy) 113ms  113ms
#> # … with 3 more variables: `itr/sec` <dbl>, mem_alloc <bch:byt>,
#> #   `gc/sec` <dbl>

Created on 2019-10-06 by the reprex package (v0.3.0)

Session info
devtools::session_info()
#> ─ Session info ──────────────────────────────────────────────────────────
#>  setting  value                       
#>  version  R version 3.6.1 (2019-07-05)
#>  os       Linux Mint 19.2             
#>  system   x86_64, linux-gnu           
#>  ui       X11                         
#>  language en_US                       
#>  collate  en_US.UTF-8                 
#>  ctype    en_US.UTF-8                 
#>  tz       Europe/Berlin               
#>  date     2019-10-06                  
#> 
#> ─ Packages ──────────────────────────────────────────────────────────────
#>  package      * version date       lib source        
#>  assertthat     0.2.1   2019-03-21 [1] CRAN (R 3.6.1)
#>  backports      1.1.4   2019-04-10 [1] CRAN (R 3.6.1)
#>  bench          1.0.4   2019-09-06 [1] CRAN (R 3.6.1)
#>  callr          3.3.1   2019-07-18 [1] CRAN (R 3.6.1)
#>  cli            1.1.0   2019-03-19 [1] CRAN (R 3.6.1)
#>  codetools      0.2-16  2018-12-24 [4] CRAN (R 3.5.2)
#>  crayon         1.3.4   2017-09-16 [1] CRAN (R 3.6.1)
#>  desc           1.2.0   2018-05-01 [1] CRAN (R 3.6.1)
#>  devtools       2.1.0   2019-07-06 [1] CRAN (R 3.6.1)
#>  digest         0.6.20  2019-07-04 [1] CRAN (R 3.6.1)
#>  doParallel   * 1.0.15  2019-08-02 [1] CRAN (R 3.6.1)
#>  doSNOW       * 1.0.18  2019-07-27 [1] CRAN (R 3.6.1)
#>  evaluate       0.14    2019-05-28 [1] CRAN (R 3.6.1)
#>  fansi          0.4.0   2018-10-05 [1] CRAN (R 3.6.1)
#>  foreach      * 1.4.7   2019-07-27 [1] CRAN (R 3.6.1)
#>  fs             1.3.1   2019-05-06 [1] CRAN (R 3.6.1)
#>  future         1.14.0  2019-07-02 [1] CRAN (R 3.6.1)
#>  future.apply   1.3.0   2019-06-18 [1] CRAN (R 3.6.1)
#>  globals        0.12.4  2018-10-11 [1] CRAN (R 3.6.1)
#>  glue           1.3.1   2019-03-12 [1] CRAN (R 3.6.1)
#>  highr          0.8     2019-03-20 [1] CRAN (R 3.6.1)
#>  htmltools      0.3.6   2017-04-28 [1] CRAN (R 3.6.1)
#>  iterators    * 1.0.12  2019-07-26 [1] CRAN (R 3.6.1)
#>  knitr          1.24    2019-08-08 [1] CRAN (R 3.6.1)
#>  listenv        0.7.0   2018-01-21 [1] CRAN (R 3.6.1)
#>  magrittr       1.5     2014-11-22 [1] CRAN (R 3.6.1)
#>  memoise        1.1.0   2017-04-21 [1] CRAN (R 3.6.1)
#>  pillar         1.4.2   2019-06-29 [1] CRAN (R 3.6.1)
#>  pkgbuild       1.0.4   2019-08-05 [1] CRAN (R 3.6.1)
#>  pkgconfig      2.0.2   2018-08-16 [1] CRAN (R 3.6.1)
#>  pkgload        1.0.2   2018-10-29 [1] CRAN (R 3.6.1)
#>  prettyunits    1.0.2   2015-07-13 [1] CRAN (R 3.6.1)
#>  processx       3.4.1   2019-07-18 [1] CRAN (R 3.6.1)
#>  profmem        0.5.0   2018-01-30 [1] CRAN (R 3.6.1)
#>  ps             1.3.0   2018-12-21 [1] CRAN (R 3.6.1)
#>  R6             2.4.0   2019-02-14 [1] CRAN (R 3.6.1)
#>  Rcpp           1.0.2   2019-07-25 [1] CRAN (R 3.6.1)
#>  remotes        2.1.0   2019-06-24 [1] CRAN (R 3.6.1)
#>  rlang          0.4.0   2019-06-25 [1] CRAN (R 3.6.1)
#>  rmarkdown      1.15    2019-08-21 [1] CRAN (R 3.6.1)
#>  rprojroot      1.3-2   2018-01-03 [1] CRAN (R 3.6.1)
#>  sessioninfo    1.1.1   2018-11-05 [1] CRAN (R 3.6.1)
#>  snow         * 0.4-3   2018-09-14 [1] CRAN (R 3.6.1)
#>  stringi        1.4.3   2019-03-12 [1] CRAN (R 3.6.1)
#>  stringr        1.4.0   2019-02-10 [1] CRAN (R 3.6.1)
#>  testthat       2.2.1   2019-07-25 [1] CRAN (R 3.6.1)
#>  tibble         2.1.3   2019-06-06 [1] CRAN (R 3.6.1)
#>  usethis        1.5.1   2019-07-04 [1] CRAN (R 3.6.1)
#>  utf8           1.1.4   2018-05-24 [1] CRAN (R 3.6.1)
#>  vctrs          0.2.0   2019-07-05 [1] CRAN (R 3.6.1)
#>  withr          2.1.2   2018-03-15 [1] CRAN (R 3.6.1)
#>  xfun           0.9     2019-08-21 [1] CRAN (R 3.6.1)
#>  yaml           2.2.0   2018-07-25 [1] CRAN (R 3.6.1)
#>  zeallot        0.1.0   2018-01-28 [1] CRAN (R 3.6.1)
#> 
#> [1] /home/fabian-s/R/x86_64-pc-linux-gnu-library/3.6
#> [2] /usr/local/lib/R/site-library
#> [3] /usr/lib/R/site-library
#> [4] /usr/lib/R/library
@HenrikBengtsson
Copy link
Owner

Thanks for reporting. Yes, it's likely that there's a race condition for updating the internal Rprofmem file. This file is unique per R session;

profmem/R/profmem.R

Lines 202 to 209 in 46f63f0

profmem_pathname <- local({
pathname <- NULL
function() {
if (!is.null(pathname)) return(pathname)
pathname <<- tempfile(pattern = "profmem.", fileext = ".Rprofmem.out")
pathname
}
})

but it is shared across forked R processes as when using mclapply() or plan(multicore).

It shouldn't be too hard to make it unique to each forked child process. I'll add it to the todo list for the next release.

@HenrikBengtsson HenrikBengtsson added this to the Next release milestone Oct 8, 2019
@HenrikBengtsson
Copy link
Owner

Forgot to say, fixing this in the 'profmem' package will not fix the closely-related problem in bench::mark(). The 'bench' package uses 'profmem' only for parsing an Rprofile file (profmem::readRprofmem()) - it does not rely on the other parts of profmem.

@HenrikBengtsson
Copy link
Owner

HenrikBengtsson commented Dec 17, 2019

Follow up/for the record: This problem can be reproduced as:

> p <- profmem::profmem(y <- parallel::mclapply(1:10, rnorm))
Error in parse(text = trace) : <text>:1:103: unexpected symbol
1: c("FUN", "lapply", "doTryCatch", "tryCatchOne", "tryCatchList", "tryCatch", "try", "sendMaster", "FUN"chList
                                                                                                          ^
> traceback()
8: parse(text = trace)
7: eval(parse(text = trace), enclos = baseenv())
6: FUN(X[[i]], ...)
5: lapply(bfr, FUN = function(x) {
       bytes <- gsub(pattern, "\\1", x)
       what <- rep("alloc", times = length(x))
       idxs <- which(bytes == "new page")
       if (length(idxs) > 0) {
           what[idxs] <- "new page"
           bytes[idxs] <- ""
       }
       bytes <- as.numeric(bytes)
       trace <- gsub(pattern, "\\2", x)
       trace <- gsub("\" \"", "\", \"", trace, fixed = TRUE)
       trace <- sprintf("c(%s)", trace)
       trace <- eval(parse(text = trace), enclos = baseenv())
       trace <- trace[seq_len(max(0L, length(trace) - drop))]
       list(what = what, bytes = bytes, trace = trace)
   })
4: readRprofmem(pathname, drop = drop)
3: profmem_suspend()
2: profmem_begin(threshold = threshold)
1: profmem::profmem(y <- parallel::mclapply(1:10, rnorm))

Not surprisingly, it can also be reproduced with plain utils::Rprofmem():

> pf <- tempfile()
> local({ utils::Rprofmem(pf); on.exit(utils::Rprofmem("")); y <- parallel::mclapply(1:10, FUN = function(ii) integer(1e6)) })
> p <- profmem::readRprofmem(pf)
Error in parse(text = trace) : <text>:1:18: unexpected symbol
1: c("FUN", "l272 :"get0
                     ^
> traceback()
5: parse(text = trace)
4: eval(parse(text = trace), enclos = baseenv())
3: FUN(X[[i]], ...)
2: lapply(bfr, FUN = function(x) {
       bytes <- gsub(pattern, "\\1", x)
       what <- rep("alloc", times = length(x))
       idxs <- which(bytes == "new page")
       if (length(idxs) > 0) {
           what[idxs] <- "new page"
           bytes[idxs] <- ""
       }
       bytes <- as.numeric(bytes)
       trace <- gsub(pattern, "\\2", x)
       trace <- gsub("\" \"", "\", \"", trace, fixed = TRUE)
       trace <- sprintf("c(%s)", trace)
       trace <- eval(parse(text = trace), enclos = baseenv())
       trace <- trace[seq_len(max(0L, length(trace) - drop))]
       list(what = what, bytes = bytes, trace = trace)
   })
1: profmem::readRprofmem(pf)

As OP says, this is because forked parallel processing is used. This is because R's internal do_Rprofmem() and more precisely R_InitMemReporting()/R_EndMemReporting() are not fork safe; all forked child processes will write to the exact same Rprofmem file as the parent process.

Actions: I'm not sure there is much that can be done in the profmem package. I don't think it's possible to protect against using Rprofmem() in forked processing. Maybe one could give a more informative error message, e.g. "Error: ... Was memory profiling run with forked processing? If so, that is unfortunately not safe".

@HenrikBengtsson
Copy link
Owner

Here's an example of intertwined Rprofmem output from multiple forked processes:

192 :"FUN" "lapply" "<Anonymous>" "<Anonymous>" 
328 :"FUN" "lapply" "<Anonymous>" "<Anonymous>" 
192 :"FUN" "lapply" "<Anonynew page:"tolower" ".check_ncores" "<Anonymous>" "<Anonymous>" 
new page:"seq.default" "seq" "FUN" "lapply" "<Anonymous>" "<Anonymous>" 
new page:"seq.default" "seq" "FUN" "lapply" "<Anonymous>" "<Anonymous>" 

Note that line with '... "<Anonynew page:"tolower" ...'. This gives:

Error in parse(text = trace) : <text>:1:37: unexpected symbol
1: c("FUN", "lapply", "<Anonynew page:"tolower

One option could be the replace non-parsable entries with a <non-parsable> result and produce a warning that the captured and parsed Rprofmem results might not be correct. One could also give more control to the user on what should happen via an onParseError=c("error", "warning", "ignore") argument to readRprofmem().

@HenrikBengtsson HenrikBengtsson modified the milestones: 0.6.0, Next release Dec 13, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants