BUG: Rprofmem() clutters up output when the call stack is empty

[HenrikBengtsson]

(Extracted from Issue #25)

When R does memory allocations internally, these are also logged with Rprofmem(). These entries have an empty call stack. Due to a bug in the code, the log of such entries lack newlines causing several entries to appear on the same line in the log file. For example,

> Rprofmem()
> x <- integer(1000)
> y <- double(1000)
> Rprofmem(NULL)
> cat(readLines("Rprofmem.out", warn=FALSE), sep="\n")
4040 :"integer"
200 :360 :360 :1064 :new page:8040 :"double"

The lack of newlines for some of the lines makes it unnecessarily hard/tricky to parse the Rprofmem log file.

Solution

Fixing this is very simple; it is just a matter of making sure there are no side effects, which it appears not to be (see below R-devel thread 'RProfmem output format').

$ svn diff src/main/memory.c 
Index: src/main/memory.c
===================================================================
--- src/main/memory.c	(revision 72746)
+++ src/main/memory.c	(working copy)
@@ -3803,7 +3803,6 @@
 
 static void R_OutputStackTrace(FILE *file)
 {
-    int newline = 0;
     RCNTXT *cptr;
 
     for (cptr = R_GlobalContext; cptr; cptr = cptr->nextcontext) {
@@ -3810,13 +3809,12 @@
 	if ((cptr->callflag & (CTXT_FUNCTION | CTXT_BUILTIN))
 	    && TYPEOF(cptr->call) == LANGSXP) {
 	    SEXP fun = CAR(cptr->call);
-	    if (!newline) newline = 1;
 	    fprintf(file, "\"%s\" ",
 		    TYPEOF(fun) == SYMSXP ? CHAR(PRINTNAME(fun)) :
 		    "<Anonymous>");
 	}
     }
-    if (newline) fprintf(file, "\n");
+    fprintf(file, "\n");
 }
 
 static void R_ReportAllocation(R_size_t size)

With the above patch, we get:

> Rprofmem()
> x <- integer(1000)
> y <- double(1000)
> Rprofmem(NULL)
> cat(readLines("Rprofmem.out", warn=FALSE), sep="\n")
4040 :"integer" 
240 :
480 :
472 :
1064 :
new page:
8040 :"double" 

See also

• This issue has been discussed previously:

• R-devel thread 'RProfmem output format', May 2011 and restarted June 2016 (https://stat.ethz.ch/pipermail/r-devel/2016-June/072809.html)
  • Follow up / solved message: https://hypatia.math.ethz.ch/pipermail/r-devel/2017-May/074364.html
• Radford Neal, R-devel thread 'Improved version of Rprofmem', 2011-08-14 (https://stat.ethz.ch/pipermail/r-devel/2011-August/061783.html).

• The profmem package is backward and forward compatible with this bug / fix.

/cc @kalibera, if you still have a few brain cycles to spare after tweaking summaryRprof() (r72743), I'm cc:ing you in the hope that you can fix also this very old bug that seems to be forgotten about over and over.

[HenrikBengtsson]

UPDATE: This has now been patched in R-devel r72747, with the difference that the newline is no longer outputted by R_OutputStackTrace() itself but the calling functions. We now get:

$ R --vanilla
R Under development (unstable) (2017-05-30 r72747) -- "Unsuffered Consequences"
Copyright (C) 2017 The R Foundation for Statistical Computing
Platform: x86_64-pc-linux-gnu (64-bit)
[...]
> Rprofmem()
> x <- integer(1000)
> y <- double(1000)
> Rprofmem(NULL)
> cat(readLines("Rprofmem.out", warn=FALSE), sep="\n")
4040 :"integer" 
240 :
480 :
472 :
1064 :
8040 :"double" 
new page:

Thanks @kalibera

[jangorecki]

@HenrikBengtsson any idea what happened to?

Radford Neal, R-devel thread 'Improved version of Rprofmem', 2011-08-14 (https://stat.ethz.ch/pipermail/r-devel/2011-August/061783.html).

[HenrikBengtsson]

Yeah, I don't much happened. It's about timing - getting the attention of R core members at the right time and their spare time. I might be worth bringing up again. Please note that I have a separate issue 'WISH: Rprofmem() overhaul' on this; #25.