Fwd: Re: [stan-dev] profiling tools?

[Bob Carpenter]

Let me rephrase the question. (And then I hope
someone else can use the answer to help Jiqiang
with problems on autocorrelation and autocovariance
because it's blocking his progress on RStan and I'm
going out of town; if the problem's still there in
two weeks, I'll take it up again.)

Can anyone point me to step-by-step instructions
on how to do profile g++ on the Mac? Everything I've
found either (a) doesn't work (like gprof under gcc),
or (b) looks horrendously complex (like Shark
under Xcode).

Here's what I'm doing in gprof, if anyone can tell
me where I'm going wrong.

Step 1: A really simple program with a function
call (in case error was that main() was invisible,
that takes enough time it shouldn't return 0 (in case
that was the problem)):

-----------------
#include <iostream>
int foo() {
double sum;
for (size_t j = 0; j < 1000; ++j) {
for (size_t i = 0; i < 1000000; ++i) {
sum += i;
}
if (j % 100 == 0) std::cout << "sum=" << sum << std::endl;
}
}

int main() {
foo();
}
---------------

~/stan> g++ -pg -g -o simple simple.cpp

~/stan> ls gmon.out
ls: gmon.out: No such file or directory

~/stan> ./simple
sum=5e+11
sum=5.04999e+13
sum=1.005e+14
sum=1.505e+14
sum=2.005e+14
sum=2.505e+14
sum=3.005e+14
sum=3.505e+14
sum=4.005e+14
sum=4.505e+14

~/stan> ls -l gmon.out
-rw-r--r-- 1 colloquialdotcom staff 912445 Jul 25 15:54 gmon.out

~/stan> gprof simple

Nada. Nyet. Bupkis. Just a bunch of empty forms. Ditto if I just
call "gprof" as some tutorials said. Ditto if I call gprof -f foo, etc.

I get the same thing if I run autocorrelation in Stan. There
were warnings about functions that were too fast, only called library
functions, etc.

Also various threads about gprof being broken on Mac OS X since 1996.

- Bob

P.S. Yes, I realize we should do this at -O3 when we care, but I can't
even manage to get simple profiling output.

[Jiqiang Guo]

The last answer on this page http://stackoverflow.com/questions/1101545/problem-with-gprof-on-os-x-program-is-not-of-the-host-architecture

says gprof is not working on mac.  Instead, using Shark in Xcode. 

I tried gprof on linux, which seems give me some results.  I could dig in more on this issue. 

In addition, repost what I said about the effective sample size just to say that this has nothing to do with R. 

To demonstrate that, I added a fake test as follows, which needs 131138ms to finish

on my computer. 

TEST(McmcChains,effective_sample_size) {

  std::vector<std::string> names;

  std::vector<std::vector<size_t> > dimss;

  stan::mcmc::read_variables("src/test/mcmc/test_csv_files/8schools1.csv", 3,

                             names, dimss);

  stan::mcmc::chains<> c(4, names, dimss);

  add_chain(c, 0, "src/test/mcmc/test_csv_files/8schools1.csv", 3);

  add_chain(c, 1, "src/test/mcmc/test_csv_files/8schools2.csv", 3);

  add_chain(c, 2, "src/test/mcmc/test_csv_files/8schools2.csv", 3);

  add_chain(c, 3, "src/test/mcmc/test_csv_files/8schools2.csv", 3);

  size_t index = 0;

  EXPECT_NEAR(13.08, c.effective_sample_size(index), 0.01) <<

    "the first sample size should be 13.1";

}

--

Jiqiang 

[Bob Carpenter]

On 7/25/12 4:35 PM, Jiqiang Guo wrote:
> The last answer on this page
> http://stackoverflow.com/questions/1101545/problem-with-gprof-on-os-x-program-is-not-of-the-host-architecture
>
> says gprof is not working on mac. Instead, using Shark in Xcode.

Thanks. Shark was deprecated in Xcode 4 and Daniel's
been trying to get the replacement, "Instruments", working,
with no luck.

>
> I tried gprof on linux, which seems give me some results. I could dig
> in more on this issue.

We need to figure out how to profile anyway.
I'd been putting it off because I hate learning
new tools. It always seems to take days to get
them running unless you have an expert next to you.

>
> In addition, repost what I said about the effective sample size just
> to say that this has nothing to do with R.

Thanks for the sample code. That certainly shows
the issue's not with R. I forgot how much other I/O
was going on on the Stan side. The issue has to
be in read_variables or add_chain because the FFT
comps for autocorrelation are fast.

It'd be nice to see where the bottlenecks were in the
code, but it might be obvious from inspection.

We can't have ESS taking two minutes to run for 8 schools!

- Bob

P.S. Daniel's also going to work on getting the one-chain
ESS working. We just need to make sure we scold the user
with a pop-up Gelman-bot if they ever try to use it.

[Michael Betancourt]

I have to say that Instruments is a breeze to use -within- Xcode. I'm
not sure how hard it is to run on an arbitrary process, however, and,
to be honest, it is a torrent of information.

[Daniel Lee]

Jiqiang,

Can you check in those csv files?

[Jiqiang Guo]

Sure, I will do it soon and the faked test, which you could delete soon if you like to. 

Jiqiang 

[Daniel Lee]

Thanks. I'll take a look once it's up.

[Jiqiang Guo]

I attached the test and shared the samples files at http://dl.dropbox.com/u/646775/8schools.tar.gz

as they are too big (around 50,000 iterations in each of 4 chains).  The test is not checked out because 

I don't want to cause an error with Jenkins. 

It might be better to use fewer iterations as it takes order of hours for me to use gprof to profile for

these many iterations.  Here is the head of my profile results (using gprof under linux)

Each sample counts as 0.01 seconds.

  %   cumulative   self              self     total

 time   seconds   seconds    calls   s/call   s/call  name

 44.93    392.68   392.68  3848916     0.00     0.00  std::_Rb_tree<int, std::pair<int const, Eigen::internal::kiss_cpx_fft<double> >, std::_Se 32.56    677.28   284.60 2231266196     0.00     0.00  std::vector<int, std::allocator<int> >::_M_insert_aux(__gnu_cxx::__normal_iterator<int*  8.15    748.53    71.25 2235635084     0.00     0.00  Eigen::internal::kiss_cpx_fft<double>::bfly3(std::complex<double>*, unsigned long, unsi  4.60    788.69    40.16   416332     0.00     0.00  Eigen::internal::kiss_cpx_fft<double>::bfly4(std::complex<double>*, unsigned long, unsign

  3.62    820.33    31.63 4466485016     0.00     0.00  std::vector<double, std::allocator<double> >::operator[](unsigned long) const

  3.07    847.13    26.81 4466276920     0.00     0.00  std::vector<std::vector<unsigned long, std::allocator<unsigned long> >, std::allocator<

  2.46    868.60    21.47   208064     0.00     0.00  std::vector<std::string, std::allocator<std::string> >::size() const

  0.53    873.21     4.61                             void __gnu_cxx::__alloc_traits<std::allocator<int> >::construct<int>(std::allocator<int>&

  0.01    873.26     0.05  7759339     0.00     0.00  std::vector<std::string, std::allocator<std::string> >::erase(__gnu_cxx::__normal_iterato  0.00    873.30     0.04                             std::vector<unsigned long, std::allocator<unsigned long> >::~vector()

--

Jiqiang 

On Wed, Jul 25, 2012 at 4:54 PM, Jiqiang Guo <guo...@gmail.com> wrote:

[Bob Carpenter]

Thanks -- that's what we were trying to produce.

We can fix the big problems -- the time's getting sunk
in the I/O.

I'm wondering why kiss_cps_fft shows up. It sholdn't
because running 100 size 50K autocovariances is very fast.

Were these profiles generated with -O3 optimization?

- Bob

[Jiqiang Guo]

On Wed, Jul 25, 2012 at 5:28 PM, Bob Carpenter <ca...@alias-i.com> wrote:

Were these profiles generated with -O3 optimization?

No. I will report the result for -O3 when I have it. 

--

Jiqiang

[Marcus Brubaker]

Jiqiang,

I highly recommend checking out kcachegrind for the profiling under Linux.  It's pretty easy to use, doesn't require recompiling everything with -pg and is prepackaged on practically every modern Linux distro.  Also, unlike gprof, it produces line-by-line (instead of function-by-function) statistics of where time is spent and its instrumentation doesn't tend skew timing results the same way gprof does.

I can dig up more specific directions if you would like them.

Cheers,
Marcus

[Jiqiang Guo]

Thanks to Marcus.

I tried kcachegrind. I did not pay much attention on the result. Maybe
I should learn the rope from a simpler example.
It is too overwhelming now for the thing I am profiling so I got lost
from the results soon.

By the way, it seems slower for using kcachegrind as valgrind
--tool=callgrind takes longer time.

--
Jiqiang

[Bob Carpenter]

Jiqiang -- Don't worry about running with -O3.

We've recreated the issue on this side. Eigen's FFT
slows down tremendously on some size inputs.

100 instances of size 50K: 2s

100 instances of size 52012: estimated 30 minutes!

100 instances of size 65536: 2.6s

52012 was the size of inputs from Jiqiang's example.

Is it legal to pad the inputs up to a power of 2?
If not, we'll have to find an alternative to FFT.

(I haven't tried saving 50K samples in R2WinBUGs, so
I don't know how fast that would be.)

- Bob

P.S. This is just the kind of thing the Agner book said
would happen!

[Ben Goodrich]

On Wednesday, July 25, 2012 5:59:23 PM UTC-4, Bob Carpenter wrote:

Is it legal to pad the inputs up to a power of 2?
If not, we'll have to find an alternative to FFT.

Maybe try using Eigen's FFTW backend (but don't push due to license issues) to confirm whether the problem is with the KISSFFT implementation or with FFT as a concept.

Ben

[Matt Hoffman]

FFTW (which Matlab uses) absolutely does not exhibit behavior like that.

I believe there should be a way to pad to a power of 2. It may just
work, but if not, there's probably some simple (to implement, once
found) correction.

How to use Instruments under Lion:
1. Fire up Instruments.
2. Select "CPU" under "Mac OS X" on the left side, and "Time Profiler"
on the right side.
3. Start the process you want to profile.
4. Select that process from the "Target" drop down in the upper left.
5. Hit the red "Record" button.
6. After a while, hit the record button again.
7. Profit.

Matt