From ggrothendieck at gmail.com  Fri Jun 12 23:41:28 2009
From: ggrothendieck at gmail.com (Gabor Grothendieck)
Date: Fri, 12 Jun 2009 17:41:28 -0400
Subject: [Rd] Rprof loses all system() time
In-Reply-To: <20090612213148.GA97896@piskorski.com>
References: <20090612213148.GA97896@piskorski.com>
Message-ID: <971536df0906121441j5a2ce5ddm334f6cdebe72378@mail.gmail.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
>



[Rd] Rprof loses all system() time
Gabor Grothendieck