Bug 15288 - summaryRProf times seem to be incorrect when Rprof is called with line.profiling=T
summaryRProf times seem to be incorrect when Rprof is called with line.profil...
Status: CLOSED FIXED
Product: R
Classification: Unclassified
Component: Misc
R 3.0.0
x86_64/x64/amd64 (64-bit) Windows 64-bit
: P5 normal
Assigned To: R-core
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2013-04-23 16:27 UTC by David Teller
Modified: 2013-04-25 18:34 UTC (History)
1 user (show)

See Also:


Attachments
Test Function to be profiled (139 bytes, text/plain)
2013-04-23 16:28 UTC, David Teller
Details
Example Code (420 bytes, text/plain)
2013-04-23 16:28 UTC, David Teller
Details
Output with line profiling on (3.24 KB, text/plain)
2013-04-25 17:15 UTC, David Teller
Details
Output with line profiling on 4-17-2013 dev version (3.24 KB, text/plain)
2013-04-25 17:16 UTC, David Teller
Details
Output with line profiling off (2.63 KB, text/plain)
2013-04-25 17:16 UTC, David Teller
Details

Note You need to log in before you can comment on or make changes to this bug.
Description David Teller 2013-04-23 16:27:36 UTC
When Rprof is called with line.profiling=F, the times reported by summaryRProf match (more or less) the time reported by system.time() for the operations profiled.

When Rprof is called with line.profiling=T and summaryRprof is called with lines="both", the times reported by summaryRProf go up to ~ 99.98 regardless of how long the operations profiled actually took.

The test function being profiled is attached as fTest.r.

The code that does the profiling is below:
# pTest.r
setwd("D:\\Regressions\\TestProfile")
source("fTest.r", keep.source=T)
line.profiling=T

pFile <- "pTest.out"
if (version$major == 3) {
  Rprof(pFile, line.profiling=line.profiling)
} else {
  Rprof(pFile)
}

t1 <- system.time(fTest(1500))

Rprof(NULL)

t1
# Prints (line.profiling=T)
#    user  system elapsed 
# 142.13    1.28  144.24 

# Prints (line.profiling=F)
#   user  system elapsed 
# 144.40    1.39  146.60 

p1 <- summaryRprof(pFile)
p1

# Prints (line.profiling=T)
#$by.self
#        self.time self.pct total.time total.pct
#"rnorm"     99.96    99.98      99.96     99.98
#"gc"         0.02     0.02       0.02      0.02
#
#$by.total
#              total.time total.pct self.time self.pct
#"system.time"      99.98    100.00      0.00     0.00
#"rnorm"            99.96     99.98     99.96    99.98
#"fTest"            99.96     99.98      0.00     0.00
#"gc"                0.02      0.02      0.02     0.02
#
#$sample.interval
#[1] 0.02
#
#$sampling.time
#[1] 99.98

# Prints (line.profiling=F)
#$by.self
#        self.time self.pct total.time total.pct
#"rnorm"    146.60    99.99     146.60     99.99
#"gc"         0.02     0.01       0.02      0.01
#
#$by.total
#              total.time total.pct self.time self.pct
#"system.time"     146.62    100.00      0.00     0.00
#"rnorm"           146.60     99.99    146.60    99.99
#"fTest"           146.60     99.99      0.00     0.00
#"gc"                0.02      0.01      0.02     0.01

#$sample.interval
#[1] 0.02
#
#$sampling.time
#[1] 146.62

if (version$major == 3 && line.profiling) {
  p2 <- summaryRprof(pFile, lines="both"))
  p2
# Prints (line.profiling=T)
#$by.self
#        self.time self.pct total.time total.pct
#"rnorm"     99.96    99.98      99.96     99.98
#"gc"         0.02     0.02       0.02      0.02
#
#$by.total
#              total.time total.pct self.time self.pct
#"system.time"      99.98    100.00      0.00     0.00
#"rnorm"            99.96     99.98     99.96    99.98
#"fTest"            99.96     99.98      0.00     0.00
#fTest.r#7          43.28     43.29      0.00     0.00
#fTest.r#6          28.66     28.67      0.00     0.00
#fTest.r#5          14.36     14.36      0.00     0.00
#fTest.r#8          13.66     13.66      0.00     0.00
#"gc"                0.02      0.02      0.02     0.02
#
#$sample.interval
#[1] 0.02
#
#$sampling.time
#[1] 99.98

}

Thanks

Dave Teller
Comment 1 David Teller 2013-04-23 16:28:23 UTC
Created attachment 1431 [details]
Test Function to be profiled
Comment 2 David Teller 2013-04-23 16:28:46 UTC
Created attachment 1432 [details]
Example Code
Comment 3 Duncan Murdoch 2013-04-23 18:24:01 UTC
I don't see this.  There have been bug fixes to the profiling code subsequent to the 3.0.0 release; could you please try R-patched and/or R-devel and see if you still get a problem?
Comment 4 David Teller 2013-04-25 17:10:47 UTC
I can reproduce this with R devel 4-17-2013 and 4-24-2013.
I get the exact same results.
Comment 5 David Teller 2013-04-25 17:15:37 UTC
Created attachment 1438 [details]
Output with line profiling on
Comment 6 David Teller 2013-04-25 17:16:06 UTC
Created attachment 1439 [details]
Output with line profiling on 4-17-2013 dev version
Comment 7 David Teller 2013-04-25 17:16:32 UTC
Created attachment 1440 [details]
Output with line profiling off
Comment 8 David Teller 2013-04-25 17:20:16 UTC
I've attached console logs from running the test with the 4-24-2013 and 4-17-2013 dev versions.

The total time taken by the test is about 140 seconds.
When run with line profiling, $sampling time in the summaryRprof output is 99.98 as is the maximum time in $by.total and $by.self.

When run without line profiling the values time aggree with the system.time()
value pretty closely (143 or so).
Comment 9 Duncan Murdoch 2013-04-25 18:16:02 UTC
Okay, I see it now.  Shouldn't be too hard to fix.
Comment 10 Duncan Murdoch 2013-04-25 18:34:28 UTC
Will commit fixes to R-devel and R-patched after testing.