R devel - Jun 2009 - Rprof loses all system() time

Rprof seems to ignore all time spent inside system() calls.  E.g.,
this simple example actually takes about 10 seconds, but Rprof thinks
the total time is only 0.12 seconds:
> Rprof("sleep-system.out") ;
system.time(system(command="sleep 10")) ; Rprof(NULL)
   user  system elapsed
  0.000   0.004  10.015
> summaryRprof("sleep-system.out")$by.total
              total.time total.pct self.time self.pct
"gc"                0.12       100      0.12      100
"system.time"       0.12       100      0.00       
0
>
I assume that what's going on here, is that anytime R blocks waiting
for data from a child process, the profiler stops running entirley,
and it then loses track of all that time spend blocking.

This Rprof behavior is frustrating, because I use a database access
layer which essentially works by having R call system() to run a shell
script.  So, if I write a really slow query that takes 10 minutes to
run, as for as Rprof is concerned, those 10 minutes never happened,
the query consumed zero time.  In complicated code, this makes it much
harder to figure out what parts are slow due to slow R code vs. slow
SQL queries.

Why does Rprof behave this way?  Is there something I can do to
work-around or alleviate this?  What do you think it would take to fix
Rprof to track the time spent waiting for system() to finish, and
where in the R source should I look to attempt that?

Thanks!

-- 
Andrew Piskorski <atp at piskorski.com>
http://www.piskorski.com/

You could run proc.time() before and after each system call.

x <- proc.time()
# do something
y <- proc.time()
y - x


On Fri, Jun 12, 2009 at 5:31 PM, Andrew Piskorski<atp at piskorski.com>
wrote:
> Rprof seems to ignore all time spent inside system() calls. ?E.g.,
> this simple example actually takes about 10 seconds, but Rprof thinks
> the total time is only 0.12 seconds:
>
>> Rprof("sleep-system.out") ;
system.time(system(command="sleep 10")) ; Rprof(NULL)
> ? user ?system elapsed
> ?0.000 ? 0.004 ?10.015
>> summaryRprof("sleep-system.out")$by.total
> ? ? ? ? ? ? ?total.time total.pct self.time self.pct
> "gc" ? ? ? ? ? ? ? ?0.12 ? ? ? 100 ? ? ?0.12 ? ? ?100
> "system.time" ? ? ? 0.12 ? ? ? 100 ? ? ?0.00 ? ? ? ?0
>>
>
> I assume that what's going on here, is that anytime R blocks waiting
> for data from a child process, the profiler stops running entirley,
> and it then loses track of all that time spend blocking.
>
> This Rprof behavior is frustrating, because I use a database access
> layer which essentially works by having R call system() to run a shell
> script. ?So, if I write a really slow query that takes 10 minutes to
> run, as for as Rprof is concerned, those 10 minutes never happened,
> the query consumed zero time. ?In complicated code, this makes it much
> harder to figure out what parts are slow due to slow R code vs. slow
> SQL queries.
>
> Why does Rprof behave this way? ?Is there something I can do to
> work-around or alleviate this? ?What do you think it would take to fix
> Rprof to track the time spent waiting for system() to finish, and
> where in the R source should I look to attempt that?
>
> Thanks!
>
> --
> Andrew Piskorski <atp at piskorski.com>
> http://www.piskorski.com/
>
> ______________________________________________
> R-devel at r-project.org mailing list
> https://stat.ethz.ch/mailman/listinfo/r-devel
>