1% File src/library/utils/man/Rprof.Rd
2% Part of the R package, https://www.R-project.org
3% Copyright 1995-2018 R Core Team
4% Distributed under GPL 2 or later
5
6\name{Rprof}
7\alias{Rprof}
8\title{Enable Profiling of R's Execution}
9\description{
10  Enable or disable profiling of the execution of \R expressions.
11}
12\usage{
13Rprof(filename = "Rprof.out", append = FALSE, interval = 0.02,
14       memory.profiling = FALSE, gc.profiling = FALSE,
15       line.profiling = FALSE, filter.callframes = FALSE,
16       numfiles = 100L, bufsize = 10000L)
17}
18\arguments{
19  \item{filename}{
20    The file to be used for recording the profiling results.
21    Set to \code{NULL} or \code{""} to disable profiling.
22  }
23  \item{append}{
24    logical: should the file be over-written or appended to?
25  }
26  \item{interval}{
27    real: time interval between samples.
28  }
29  \item{memory.profiling}{logical: write memory use information to the file?}
30  \item{gc.profiling}{logical:  record whether GC is running?}
31  \item{line.profiling}{logical:  write line locations to the file?}
32  \item{filter.callframes}{logical: filter out intervening call frames
33    of the call tree. See the filtering out call frames section.}
34  \item{numfiles, bufsize}{integers: line profiling memory allocation}
35}
36\details{
37  Enabling profiling automatically disables any existing profiling to
38  another or the same file.
39
40  Profiling works by writing out the call stack every \code{interval}
41  seconds, to the file specified.  Either the \code{\link{summaryRprof}}
42  function or the wrapper script \command{R CMD Rprof} can be used to
43  process the output file to produce a summary of the usage; use
44  \command{R CMD Rprof --help} for usage information.
45
46  How time is measured varies by platform:
47   \describe{
48     \item{On Windows:}{
49  Exactly what the time interval measures is subtle: it is time that the
50  \R process is running and executing an \R command.  It is not however just
51  CPU time, for if \code{readline()} is waiting for input, that counts
52  (on Windows, but not on a Unix-alike).
53
54  Note that the timing interval cannot be too small, for the time spent
55  in each profiling step is added to the interval.  What is feasible is
56  machine-dependent, but 10ms seemed as small as advisable on a 1GHz machine.
57    }
58    \item{On Unix-alikes}{it is the CPU
59  time of the \R process, so for example excludes time when \R is waiting
60  for input or for processes run by \code{\link{system}} to return.
61
62  Note that the timing interval cannot usefully be too small: once the
63  timer goes off, the information is not recorded until the next timing
64  click (probably in the range 1--10 ms).
65    }
66  }
67
68  Functions will only be recorded in the profile log if they put a
69  context on the call stack (see \code{\link{sys.calls}}).  Some
70  \link{primitive} functions do not do so: specifically those which are
71  of \link{type} \code{"special"} (see the \sQuote{R Internals} manual
72  for more details).
73
74  Individual statements will be recorded in the profile log if
75  \code{line.profiling} is \code{TRUE}, and if the code being executed
76  was parsed with source references.  See \code{\link{parse}} for a
77  discussion of source references.  By default the statement locations
78  are not shown in \code{\link{summaryRprof}}, but see that help page
79  for options to enable the display.
80}
81
82\section{Filtering Out Call Frames}{
83  Lazy evaluation makes the call stack more complex because intervening
84  call frames are created between the time arguments are applied to a
85  function, and the time they are effectively evaluated. When the call
86  stack is represented as a tree, these intervening frames appear as
87  sibling nodes. For instance, evaluating \code{try(EXPR)} produces the
88  following call tree, at the time \code{EXPR} gets evaluated:
89
90\preformatted{
911. +-base::try(EXPR)
922. | \-base::tryCatch(...)
933. |   \-base:::tryCatchList(expr, classes, parentenv, handlers)
944. |     \-base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
955. |       \-base:::doTryCatch(return(expr), name, parentenv, handler)
966. \-EXPR
97}
98
99  Lines 2 to 5 are intervening call frames, the last of which finally
100  triggered evaluation of \code{EXPR}. Setting \code{filter.callframes}
101  to \code{TRUE} simplifies the profiler output by removing all sibling
102  nodes of intervening frames.
103
104  The same kind of call frame filtering is applied with \code{eval()}
105  frames.  When you call \code{eval()}, two frames are pushed on the
106  stack to ensure a continuity between frames. Say we have these
107  definitions:
108
109\preformatted{
110calling <- function() evaluator(quote(called()), environment())
111evaluator <- function(expr, env) eval(expr, env)
112called <- function() EXPR()
113}
114
115  \code{calling()} calls \code{called()} in its own environment, via
116  \code{eval()}. The latter is called indirectly through
117  \code{evaluator()}. The net effect of this code is identical to just
118  calling \code{called()} directly, without the intermediaries. However,
119  the full call stack looks like this:
120
121
122\preformatted{
1231. calling()
1242. \-evaluator(quote(called()), environment())
1253.   \-base::eval(expr, env)
1264.     \-base::eval(expr, env)
1275.       \-called()
1286.         \-EXPR()
129}
130
131  When call frame filtering is turned on, the true calling environment
132  of \code{called()} is looked up, and the filtered call stack looks like
133  this:
134
135\preformatted{
1361. calling()
1375. \-called()
1386.   \-EXPR()
139}
140
141  If the calling environment is not on the stack, the function called by
142  \code{eval()} becomes a root node. Say we have:
143
144\preformatted{
145calling <- function() evaluator(quote(called()), new.env())
146}
147
148  With call frame filtering we then get the following filtered call
149  stack:
150
151\preformatted{
1525. called()
1536. \-EXPR()
154}
155
156}
157\note{
158  \describe{
159    \item{On Unix-alikes:}{
160  Profiling is not available on all platforms.  By default,
161  support for profiling is compiled in if possible -- configure \R with
162  \option{--disable-R-profiling} to change this.
163
164  As \R profiling uses the same mechanisms as C profiling, the two
165  cannot be used together, so do not use \code{Rprof} in an executable
166  built for C-level profiling.
167    }
168    \item{On Windows:}{
169  \code{filename} can be a UTF-8-encoded filepath that cannot be translated to
170  the current locale.
171    }
172  }
173
174The profiler interrupts R asynchronously, and it cannot allocate
175memory to store results as it runs.  This affects line profiling,
176which needs to store an unknown number of file pathnames.  The
177\code{numfiles} and \code{bufsize} arguments control the size of
178pre-allocated buffers to hold these results:  the former counts the
179maximum number of paths, the latter counts the numbers of bytes in
180them.  If the profiler runs out of space it will skip recording the
181line information for new files, and issue a warning when
182\code{Rprof(NULL)} is called to finish profiling.
183}
184\seealso{
185  The chapter on \dQuote{Tidying and profiling R code} in
186  \sQuote{Writing R Extensions} (see the \file{doc/manual} subdirectory
187  of the \R source tree).
188
189  \code{\link{summaryRprof}} to analyse the output file.
190
191  \code{\link{tracemem}}, \code{\link{Rprofmem}} for other ways to track
192  memory use.
193}
194\examples{
195\dontrun{Rprof()
196## some code to be profiled
197Rprof(NULL)
198## some code NOT to be profiled
199Rprof(append = TRUE)
200## some code to be profiled
201Rprof(NULL)
202## ...
203## Now post-process the output as described in Details
204}}
205\keyword{utilities}
206