New Profile Info

[Daniel Gates]

Greetings all,

I added new profile info to my R profiling branch in the
Trials_Profiling folder. I've added both the python output and an
Rdata file with the summaryRdata() output. I've also included these
folders and the raw Rprof() output in the dropbox folder. These three
folders are all runs with the same seed, so I'll be running more runs
with new seeds to see how that varies things but the current profile
output should hopefully give some insight as to the within run time
variability.

One thing that I'm noticing on these runs that I have not seen before
is that there is a "cat" function within fitContinuous.hacked file (if
I'm reading the hierarchy correctly) that seems to be taking a large
amount of the self time (around 30% in either run). When I looked for
"cat"s in the fitContinuous.hacked file I only find two:

cat("Fitting ", model, "model:\n") # in line 57

and:

cat("WARNING: Cannot estimate a trend with an ultrametric tree; lnl
will be the same as the BM model")
# in line 388

First off, is this a correct interpretation of the output, it seems a
bit strange to me is all. Second isn't cat just a method of outputting
or printing information? If it is, then it would seem that removal of
these calls shouldn't jeopardize the run and should increase the
performance pretty dramatically.

Let me know if I'm interpreting this correctly, like I mentioned it
still seems sort of strange to me.

Cheers,
-Dan

[Derrick Zwickl]

Hi Dan,

First, go ahead and include all of the files for each run in dropbox,
i.e. including any output, the script you ran in each directory, etc.
You should probably also start any runs by invoking a shell script, not
by just typing at the command line. Even if it is a very simple
command, put it in a script in the run directory called maybe run.sh,
and start it with ./run.sh. This way we can easily see exactly how
things were invoked and what file was executed. I'm not worried about
having duplicated files in the Dropbox as long as it is organized. Let
me know if you need help with any of that.

Looking at the profiling output I agree with your interpretation about
the time taken by cat, but I don't have any explanation for it.
Previous profiling that I've done definitely doesn't show that. How
long did these entire runs take, and how often are you sampling? (these
are things that I could easily tell if you include the output files in
dropbox :-)). To get good rigorous checkpointing the runs should really
be taking a minimum of 10 minutes, probably sampling a number of times
per second. We probably want at least 100K samples. You can see how
many samples you're getting by the number of lines in file that you are
passing to the python script.

Derrick

[dga...@huskers.unl.edu]

Hi Derrick,

The profiling sampling was quite slow, it was set to sample once every 0.9 seconds (resulting in about 2,500 lines), I'll change it to 0.01 which should get it closer to the 100K mark. I haven't written too many shell scripts but this worked when I submitted it:

#!/bin/sh

nohup Rscript /Users/dangates/TreEvoExample_seed_793450.R

The only thing is that I have to change permission to execute this script with:

chmod u+x runTreEvo.sh

but that's not a major hassle,

I've started a run using that shell script and I'll get a folder with everything datafile, shell script, output, and both types of profile info in it in dropbox probably in a couple of hours and report if anything changes.

Cheers,
-Dan

________________________________________
From: treevo-...@googlegroups.com [treevo-...@googlegroups.com] on behalf of Derrick Zwickl [dzw...@gmail.com]
Sent: Thursday, May 31, 2012 3:07 PM
To: treevo-...@googlegroups.com
Subject: Re: New Profile Info

[Derrick Zwickl]

Hi Dan,

Ok, great, although it would be better to have the R file executed in
the script be generally accessible and use a relative path, rather than
an absolute one hard coded to your file system, so that we could all
potentially run it. Unless the R scripts that you are executing are
large (which they shouldn't be), go ahead and just copy them into the
directories where you are doing the runs, such that the shell script
would be

nohup Rscript TreEvoExample_seed_793450.R

Or, if you'll be using exactly the same R script for several runs, you
can just put it nearby in the directory structure and use the relative
path, i.e.

nohup Rscript ../Rscripts/TreEvoExample_seed_793450.R

and then copy only the runTreEvo.sh file into each run directory. That
way you and all of us can look at the code that was run, even if you end
up later changing something in
/Users/dangates/TreEvoExample_seed_793450.R. If you go that route, keep
that Rscripts directory on the dropbox, and regardless when when you are
done with runs just copy the whole directory there. If it is something
trivial that you are just playing with, don't feel like you need to
share it with us immediately though, and if there is a giant file,
either don't include it or compress it.

Sorry to micromanage your file layout, but I'd just like things to be
very clear if any of us look through results, without specifically
having to ask you anything. When you're working on your own projects
solo, organize however you like ;-). Optionally, you might also get in
the habit of leaving notes for yourself/us, for example putting text
files named NOTE or README in directories if there are any
irregularities or general things about the run conditions that won't be
apparent from the file/directory names.

One final thing, if you are needing to synchronize files and directory
structures between machines, for example things that you run on a
cluster and want to look at on your desktop, we can talk about rsync. I
generally like to keep the same exact structure and files on all
machines, and sync back and forth. I use git version control for that,
but that is too much to get into right now.

Talk to you in the morning,
Derrick

[Derrick Zwickl]

Hi Dan,

One final thing for today. Be sure that you are capturing the
information that would be going to the screen, detailing the progress of
the run, acceptance, etc. Otherwise we don't know what actually
happened during a run that we have profile data for. So, redirect to
file or use tee, i.e.

nohup Rscript /Users/dangates/TreEvoExample_seed_793450.R> screenOutput

If you want to see the output and save it to file at the same time, use

nohup Rscript /Users/dangates/TreEvoExample_seed_793450.R | tee screenOutput

Derrick

[Derrick Zwickl]

Ok, I lied about that being everything.  It looks like information is output to both stderr and stdout, so to capture both, amend those commands to

nohup Rscript /Users/dangates/TreEvoExample_seed_793450.R &> screenOutput

or

Rscript /Users/dangates/TreEvoExample_seed_793450.R 2>&1 | tee screenOutput

Derrick

-------- Original Message --------

Subject:	capturing screen output
Date:	Thu, 31 May 2012 16:19:20 -0700
From:	Derrick Zwickl <dzw...@gmail.com>
To:	treevo-...@googlegroups.com

Hi Dan,

One final thing for today.  Be sure that you are capturing the 
information that would be going to the screen, detailing the progress of 
the run, acceptance, etc.  Otherwise we don't know what actually 
happened during a run that we have profile data for.  So, redirect to 
file or use tee, i.e.

nohup Rscript /Users/dangates/TreEvoExample_seed_793450.R>  screenOutput

If you want to see the output and save it to file at the same time, use

Rscript /Users/dangates/TreEvoExample_seed_793450.R | tee screenOutput

Derrick

[Barb Banbury]

Doesnt the screen output get saved in the .Rout file anyway? Or is this to capture something else? 

Barb

Sent from my iPhone

[Derrick Zwickl]

I don't have such a file being created when running TreEvoExample.R from the command line.  What causes that to be output?
I did later find that sink() would be the within-R way of catching the output.

D

[dga...@huskers.unl.edu]

I'm still organizing and creating a README file for the dropbox but I just finished a run and added the input file, shell script, output screen readout, raw profile output, python profile and R profile summaries into the folder Omeara10_seed365359 in dropbox. Just letting you know, we can talk about anything that should be changed in an hour

Cheers,
-Dan

---

From: treevo-...@googlegroups.com [treevo-...@googlegroups.com] on behalf of Derrick Zwickl [dzw...@gmail.com]

Sent: Thursday, May 31, 2012 10:18 PM
To: treevo-...@googlegroups.com
Subject: Re: capturing screen output

[Derrick Zwickl]

Hi Dan,

Ok, I've added some output from a run on my laptop in
Dropbox/GSoC_TreEvo/Trials_Profiling/djz.OSX.10.7_seed793450_shell/

which not surprisingly is exactly the same conditions as your
Dropbox/GSoC_TreEvo/Trials_Profiling/Omeara10_seed793450_shell/

I just mirrored your filenames (so they have Omeara in them).  I didn't run the summaryRprof yet, but you can do it.  The Rprof output is 74 megs, so I compressed it. 

The directory organization and notes are looking good.  One thing that I do that can make things easier is to embed important information in the directory names (which you've done nicely with the seed and computer), and then use exactly the same names for the output files themselves within those directories.  This can make it easier to parse results because filenames are consistent across directories, and you don't need to check or think about what files are named.  i.e.,
grep foo */rprof.out
or the like would work.  You've embedded the seed and computer name in some of the output files as well as the directory names, which is somewhat redundant, and if I copy your run directory to one of my naming, I would now need to also edit the .R file to make make the output filenames correspond to the system that I'm running on (which I didn't do on the files I posted). 

Don't worry about making changes like that at the moment, just dig into some profiling results.  The first offhand thing that I notice from my results is that S4 stuff is accounting for a lot of time.

Ok, have fun delving into the real code!
Cheers,
Derrick

[dga...@huskers.unl.edu]

Hi Derrick,

I've added a folder in the Trials_Profiling folder called Annotated_Function_Locations with an spreadsheet with a quick look at the location of ~50 highest self-time functions. The file is the only one in there and is called doRun_fns_locations.xls. At a first glance it seems like a lot of the time consuming functions are related to s4 class, also it seems like many that aren't directly under s4 calls are associated with the "try" function. doSimulation is the most obviously accessible function to me so I'll probably start looking through that and annotating areas for a further look. If you wouldn't mind taking a look at what I have gone through in the the spreadsheet and double checking to see if I'm interpreting things right or if the level of detail is ok that would be appreciated.

Cheers,
-Dan

---

From: treevo-...@googlegroups.com [treevo-...@googlegroups.com] on behalf of Derrick Zwickl [dzw...@gmail.com]

Sent: Friday, June 01, 2012 2:58 PM

[Derrick Zwickl]

Hi Dan,

Great, glad that you've broken the profiling down and are ready to start digging into some code!

A few things to note, some of which you may be aware of.  (NOTE: The people who actually know R should correct any misunderstandings that I myself have here)

First the "try" functions are related to what is referred to as "exception handling" (a concept in many coding languages), and are wrappers more than functions in the normal sense.  You can take a look at
help(conditions)
although it is a bit confusing.  The general idea is that you call a function X within a trycatch, and then if something goes wrong somewhere down the call hierarchy from X you can "catch" the exception and deal with it somehow - outputting an error, altering the flow of your program, etc.  So, in the profiling it will look like the function "try" called another function, but really "try" can call anything that you put within it.  I think that what this means for you is that you can essentially ignore the "try" and "trycatch" in the profiling and effectively think of the function above it calling the one below it without worrying about the try in between.  Note that this isn't to say that the self time allocated to "try" that shows up in the profiling isn't correct (although I don't personally know one way or the other), as there can be a significant overhead to watching for exceptions in different languages.  Regardless, you won't be able to do anything about that in terms of optimization at the moment, although the try's could in theory be removed at some point if it is decided that they aren't necessary.

Second, the general S4 related functions like standardGeneric can probably also be thought of as non-functions.  They have to do with the behind the scenes functioning of the S4 classes, but aren't themselves directly called (i.e., when you call a method of an S4 object they automatically get called by R).  We know that there is some overhead to using S4 classes, and this may be where that extra overhead time shows up.  I'm honestly not certain of that, and not entirely certain of how you should interpret the large amount of time spend in loadMethod.  I think that like try you can essentially pretend that it doesn't exist in the call hierarchy, and any time spent there is probably unavoidable unless S4 objects aren't used.

Hopefully the R experts can verify how correct my assumptions on all this are ;-).  For the moment, starting to look at doSimulation and think about optimization sounds good.

Cheers,
Derrick

[Hilmar Lapp]

It's hard to say whether using S4 functions could be part of the bottleneck without specific cases. Are there candidates you could point me to?

-hilmar

(Sorry for the delayed response - was occupied with the Phylotastic hackathon last week.)

-- 

===========================================================

: Hilmar Lapp  -:- Durham, NC -:- informatics.nescent.org :

===========================================================

[Derrick Zwickl]

Hi Hilmar,

Thanks for your assistance.  I'm sure that the hackathon kept you busy ;-).

We don't really have any specific examples where we think S4 is causing a slowdown, we just see a lot of profiling samples being taken in loadMethod and standardGeneric, and we understand that there is some overhead to using S4.  We may be misinterpreting these results, I don't know.  Do you have any suggestions on how we might look into this, or properly interpret the profiling results?  We'd like to know, but I don't imagine that converting things away from S4 is going to be very high on our list of things to work on unless we get desperate or other optimization targets are scarce.

Another question, do you have any comments on the overhead associated with exception handling in R?  Is it worth considering the removal of unneeded trys and catches for optimization purposes?

Many thanks,
Derrick