Profiling with /usr/bin/perf

[Richard Larocque]

Hi chromium-dev,

I asked about this on IRC but got no answer.  I'm trying again here in the hopes more eyes will find a solution.  

There's a wiki page[1] that provides instructions on how to run Chromium under a profiler (perf), but I haven't been able to make those instructions work.  The 'perf report' tool consistently fails to find any symbols for the Chrome binary.  I have compiled with the 'linux_disable_pie' and 'profiling' gyp flags, but the report tool still can't decode the results.

I'd like to know if I'm the only one experiencing this issue.  Has anyone here successfully run Chromium under a profiler on Linux lately?

If you have managed to profile Chromium, can you recommend a set of gyp flags or a certain configuration that is known to work?  Are you using Clang, gold, etc?

Thanks,

Richard.

[1] http://code.google.com/p/chromium/wiki/LinuxProfiling

[Ojan Vafai]

Just setting profiling=1 and leaving everything else default worked for me about a month ago in profiling test_shell. Not sure if you need to do something special for multi-process. 

Notably, I did not use perf. I used pprof as per the google-perftools instructions on the same page.

--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-dev

[Evan Martin]

On Wed, Apr 11, 2012 at 11:02 AM, Richard Larocque
<rlar...@chromium.org> wrote:

> I asked about this on IRC but got no answer.  I'm trying again here in the
> hopes more eyes will find a solution.
>
> There's a wiki page[1] that provides instructions on how to run Chromium
> under a profiler (perf), but I haven't been able to make those instructions
> work.  The 'perf report' tool consistently fails to find any symbols for the
> Chrome binary.  I have compiled with the 'linux_disable_pie' and 'profiling'
> gyp flags, but the report tool still can't decode the results.
>
> I'd like to know if I'm the only one experiencing this issue.  Has anyone
> here successfully run Chromium under a profiler on Linux lately?
>
> If you have managed to profile Chromium, can you recommend a set of gyp
> flags or a certain configuration that is known to work?  Are you using
> Clang, gold, etc?

Profiling with pprof and my own tools worked for me in the last few
months, with gcc and gold.

Can you provide more details about how 'perf report' is failing?

If it's not finding any symbols, what does nm/objdump have to say
about symbols in the binary in question? Is gdb able to find symbols?

[Richard Larocque]

I wanted to use /usr/bin/perf because I was interested in one particular thread and I haven't found a way to get per-thread profiles using pprof.  

Here are the details:

GDB and nm have no problem finding symbols.

'perf report' tells me that most of my time was spent in some "unkown" object.  The remaining ~30% of the time seems to be properly tracked to the kernel or shared library calls.  Here's a simple example:

# Events: 3K cycles

#

# Overhead          Command               Shared Object                                         Symbol

# ........  ...............  ..........................  .............................................

#

    70.34%           chrome  [unknown]                   [.] 0xeba090        

     1.47%           chrome  [kernel.kallsyms]           [k] page_fault

     0.98%           chrome  [kernel.kallsyms]           [k] clear_page_c

     0.97%           chrome  [kernel.kallsyms]           [k] smp_call_function_many

     0.68%           chrome  [kernel.kallsyms]           [k] find_busiest_group

...

Here's something I found interesting.  When I trace with callstacks (-g) and report on it, I get a report that looks like this:

# Overhead          Command               Shared Object                                                                     

# ........  ...............  ..........................  ...................................................................

#

    70.54%           chrome  [unknown]                   [.] 0x2523a47       

            |

            --- 0x7ff442bfe517

               |          

               |--98.90%-- 0xb19f7b

               |          0x7e3d48

               |          |          

               |          |--97.80%-- 0x7e4015

               |          |          0x1c0f327

               |          |          0x1c0fa63

               |          |          0x1c1001d

               |          |          0x1be2cea

               |          |          0x1c0b07b

               |          |          0x1c0b1d0

               |          |          0x1c39a30

               |          |          0x1c35c0a

               |          |          0x7ff4449469ca

               |          |          

               |           --2.20%-- 0x7e3d48

               |                     0x7e4009

               |                     0x1c0f327

...

GDB tells me that 0x1c1001d and 0x1be2cea map to the functions MessageLoop::DoWork() and MessageLoop::Run(), so it looks like the profile is being gathered correctly.  I also know that symbols exist, since GDB is able to tell me what these addresses map to.  This makes me wonder if there is something unusual about the way I'm compiling that confuses the perf report tool.  

For completeness, here's a list of errors printed by perf report.  I didn't see anything in here that looked significant, so I omitted them from the previous listings.  

/usr/lib/libnss_cache.so.2.0 with build id 8202e9e70207bca4720525b8bfc688e39cc8373e not found, continuing without symbols

/usr/lib/libpulsecommon-0.9.21.so with build id 009116f8172b8a76a560e58b5d5000e9576bb908 not found, continuing without symbols

Failed to open /tmp/perf-11796.map, continuing without symbols

Failed to open /tmp/perf-11891.map, continuing without symbols

No kallsyms or vmlinux with build-id ad83094b85507adb20125773b8b1c53e635e88f1 was found

[nvidia] with build id ad83094b85507adb20125773b8b1c53e635e88f1 not found, continuing without symbols

Failed to open /usr/lib/nvidia-current/libnvidia-glcore.so.280.13, continuing without symbols

Failed to open /usr/lib/nvidia-current/libGL.so.280.13, continuing without symbols

Failed to open /usr/lib/gtk-2.0/2.10.0/immodules/im-ibus.so, continuing without symbols

Failed to open /tmp/perf-17227.map, continuing without symbols

/usr/lib/libgvfscommon.so.0.0.0 with build id 643a3771da1ef29036d6b2fde645519f522d15fe not found, continuing without symbols

[Evan Martin]

These addresses look like it's *not* ASLR at least.

> GDB tells me that 0x1c1001d and 0x1be2cea map to the functions
> MessageLoop::DoWork() and MessageLoop::Run(), so it looks like the profile
> is being gathered correctly.  I also know that symbols exist, since GDB is
> able to tell me what these addresses map to.  This makes me wonder if there
> is something unusual about the way I'm compiling that confuses the perf
> report tool.
>
> For completeness, here's a list of errors printed by perf report.  I didn't
> see anything in here that looked significant, so I omitted them from the
> previous listings.

Random guess, but perhaps the way Chrome launches itself is confusing
perf in which file (path) to look in for debug info.
I see bug reports in this area like
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/608775 and
https://lkml.org/lkml/2009/10/31/42 .

Are you running perf with a cwd containing your 'chrome' binary?
Perhaps try running 'perf report' via strace to see whether or where
it's looking for the binary (or separate debug info) to analyze.

Another approach might be to try to reduce zygote complexity via
--no-sandbox; like say maybe PID namespaces are confusing things.

I notice someone else had this same problem on the list earlier:
https://groups.google.com/a/chromium.org/group/chromium-dev/browse_thread/thread/db97f1e8c6dec825

[Tom Hudson]

I've always used perf, if I recall correctly because the docs said that pprof could only deal with the browser thread.

Starting late last October, goobuntu support for perf started to get spotty. For a while I was rebooting into 508 or committing evil hackery to get it to work.

I observed this particular failure in perf starting somewhere between March 14th and 21st. I filed  http://b/issue?id=6205294  about it, and even after undoing all my hackery we still didn't fix the problem Richard saw.

I didn't fret too much about it because I figured I could always do profiling using Code Analyst on Windows, but thanks to  http://code.google.com/p/chromium/issues/detail?id=121561 I can't even build on Windows this past week and more. I've been verifying bugs using Canary / old builds of m18, or doing development work on Linux, but the next time I need to profile I'm hosed.

Tom

[Evan Martin]

On Wed, Apr 11, 2012 at 12:04 PM, Tom Hudson <tomh...@google.com> wrote:
> I've always used perf, if I recall correctly because the docs said that
> pprof could only deal with the browser thread.

Though I've never tried it myself, I believe pprof should work with
multiple threads. (After all, it's the primary tool used for
profiling Google servers and they use multiple threads.) The docs
claim as much as well (as long as you're on Linux 2.6, heh).

[Tom Hudson]

Ah, the page Richard cited does, but https://sites.google.com/a/chromium.org/dev/developers/profiling-chromium-and-webkit says that

"Only profiling the browser process is supported. To profile the renderer running in single-process mode is recommended"

I had never before seen the page Richard linked to.

Tom

[Evan Martin]

On Wed, Apr 11, 2012 at 12:13 PM, Tom Hudson <tomh...@google.com> wrote:
> Ah, the page Richard cited does,
> but https://sites.google.com/a/chromium.org/dev/developers/profiling-chromium-and-webkit says
> that
> "Only profiling the browser process is supported. To profile the renderer
> running in single-process mode is recommended"

upthread we were talking about profiling *threads*, not processes,
which is what I was confirming is supported.

But to respond to that as well, profilling child processes with pprof
also works (it creates a different profile dump per process and you
pick which dump to analyze). You need to be sure to disable the
sandbox so that pprof can write out its dumps.

In all, it might be better long-term to get perf working, but pprof is
relatively easy to understand and works.

[Sonny Rao]

There's actually a bug in perf where if you start it up before chrome forks off it's threads you'll see this unknown symbol behavior because of the way it's not properly handling process re-names.

Luigi Semenzato has some patches out to fix this issue.  We should have them in the chromium-os version of perf though, is that what you're using?

[Sonny Rao]

Sorry, I just realized this was sent to chromium-dev not chromium-os-dev, so forget my question about if you're using the chromium-os version of perf.

One thing you can do to try to see if you're hitting this bug, is to wait until chromium is started up and running before starting perf.  That seems to cover up the problem as well.

[Richard Larocque]

On Wed, Apr 11, 2012 at 15:45, Sonny Rao <sonn...@chromium.org> wrote:

Sorry, I just realized this was sent to chromium-dev not chromium-os-dev, so forget my question about if you're using the chromium-os version of perf.

One thing you can do to try to see if you're hitting this bug, is to wait until chromium is started up and running before starting perf.  That seems to cover up the problem as well.

Thanks!  That's the work around I needed.  Fortunately I'm not debugging any startup issues, so I can attach once the program has started and still get the data I need.  

I'll update the wiki page.

[Eric Seidel]

I ran into this bug again today:

http://crbug.com/265996

After many hours of debugging (and reading perf's source code), I'm happy to report that this appears to be fixed in tip-of-tree perf, which you can download, make, make install yourself.  The profiling instructions have been updated to explain the bug and regression range a little:

https://code.google.com/p/chromium/wiki/LinuxProfiling

[Evan Martin]

If perf is confused by process renames, another option is to disable process renames in Chrome in some debug mode.  The process renaming code is pretty tricky in the first place so it's not a surprise it breaks something.

(I don't think you can just stash a perf binary somewhere -- I think it needs to be compiled against exactly the kernel you're currently running, which can vary per machine.)

[Luigi Semenzato]

"perf report" just analyzes the output of "perf record" and is
surprisingly resilient to version incompatibilities. The latter
probably is not. The former can run on any machine, the latter runs
on the target machine.

The bug was that "perf report" treated a process rename as an exec (an
exec does a rename, but a rename does not imply an exec) and threw
away the process code mappings (which map address ranges to executable
files). The fix was not to throw away the symbol table, since an exec
is followed by mmaps that provide the new mappings, which replace any
old mapping.

I am surprised you ran into this bug, it was fixed a long time ago (1 year?).