[Rd] Rprof loses all system() time

[Gabor Grothendieck]

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
>