Unclear how to enable profiling

thijsc commented 5 years ago

I'm trying to get jemalloc to do heap profiling by configuring it in the environment:

export MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17

Profiling is enabled:

[dependencies.jemallocator]
version = "*"
features = ["profiling"]

I do not see the expected output as described here. Is this expected to work when using this crate?

gnzlbg commented 5 years ago

Is this expected to work when using this crate?

That's the expected output.

thijsc commented 5 years ago

Right, so something like this should be written to stdout?

<jemalloc>: Leak summary: 267184 bytes, 473 objects, 20 contexts
<jemalloc>: Run jeprof on "jeprof.19678.0.f.heap" for leak detail

gnzlbg commented 5 years ago

That's correct.

sfackler commented 5 years ago

By default jemalloc is built with a prefix, which I think the environment variable includes.

thijsc commented 5 years ago

By default jemalloc is built with a prefix, which I think the environment variable includes.

After reading build.rs file seems like the default prefix is _rjem_. I can indeed see something happening if I do this:

✗ export _RJEM_MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17
✗ cargo run
   Compiling app v0.1.0 (~)
<jemalloc>: Invalid conf pair: prof:true
<jemalloc>: Invalid conf pair: lg_prof_interval:30
<jemalloc>: Invalid conf pair: lg_prof_sample:17

Do you mean that the runtime env var will also change if you use a prefix? Or only the one that's passed in when compiling in build.rs?

sfackler commented 5 years ago

That output looks like it may be from rustc's own jemalloc. Try running your binary directly.

thijsc commented 5 years ago

Got it work, the trick is indeed to use _RJEM_MALLOC_CONF if the default prefix is used.

thijsc commented 5 years ago

One more thing I'm running into: the output is showing hex addresses and no readable names. Debug symbols are present. Maybe this is out of scope for this crate: But does anybody have pointers on how to get useful names?

I'd love to find a way to make this easily usable and will submit a pull with at least some doc updates after I figure this out.

gnzlbg commented 5 years ago

We should definitely document this in jemalloc-sys CI, and maybe add an example that we run on CI.

I'm going to leave this issue open to track that. @thijsc which platform (target triple) are you on?

thijsc commented 5 years ago

I'm currently testing on Mac, but intend to run it on our staging environment that runs Linux as well. I feel like I'm getting pretty close to this working. Two things are still not:

According to the docs it should print an overview if profiling is on. It currently only generates a heap dump but does not print anything to stdout.
The pdf generator cannot look up function names, only hex codes are shown in the output.

Screenshot 2019-03-21 at 10 27 44

I'm reading the jemalloc docs but haven't found hints on how to fix these two, debugging some more atm.

gnzlbg commented 5 years ago

Note that profiling is not supported on macos x: https://github.com/jemalloc/jemalloc/issues/26

I'd guess we could be more proactive in jemallocator by failing to build, but there is a bug in jemalloc where enabling profiling does not fail to build on mac :/

ChrisMacNaughton commented 5 years ago

On my Linux machine, I have profiling and such, but there are no symbol names, just as @thijsc is experiencing

thijsc commented 5 years ago

Well it does generate heap dump files, so some of it works at least.

gnzlbg commented 5 years ago

It might be interesting to find out whether this is a jemalloc-sys/jemallocator bug or a bug on jemalloc. Can you reproduce this using C ?

ChrisMacNaughton commented 5 years ago

I have managed to get the summary that @thijsc is looking for on my linux box with:

_RJEM_MALLOC_CONF=prof_leak:true,lg_prof_sample:0,prof_final:true target/release/scratch 
<jemalloc>: Leak approximation summary: ~8002685 bytes, ~1000336 objects, >= 1 context
<jemalloc>: Run jeprof on "jeprof.20215.0.f.heap" for leak detail

This is for a tiny Rust project entirely to validate leak detection works:

#[global_allocator]
static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc;

use std::mem;

fn main() {
    for i in 0..1_000_000i64 {
        let b = Box::new("bla".to_owned());
        mem::forget(b);
    }
}

This program gives me a heap file like:

heap_v2/1
  t*: 1000000: 8000000 [0: 0]
  t0: 1000000: 8000000 [0: 0]
@ 0x557d6c2e6755 0x557d6c29ba37 0x557d6c2947cd 0x557d6c294893 0x557d6c317273 0x557d6c31917a 0x557d6c317d76 0x557d6c294888 0x7fbf0797009b 0x557d6c29449a
  t*: 1000000: 8000000 [0: 0]
  t0: 1000000: 8000000 [0: 0]

MAPPED_LIBRARIES:
557d6c28c000-557d6c294000 r--p 00000000 fd:01 7620473                    /home/chris/code/personal/scratch/target/release/scratch
557d6c294000-557d6c32e000 r-xp 00008000 fd:01 7620473                    /home/chris/code/personal/scratch/target/release/scratch
...

As we can see, the function addresses are just that, opaque addresses. If there's some C that we would like tested in a similar way, I'm happy to oblige.

ChrisMacNaughton commented 5 years ago

It looks like the unclean symbols may be more of a jemalloc issue, as using the one shipped with Ubuntu Cosmic (18.10) shows the same issue with this C program:

#include <stdlib.h>
#include <string.h>

int main(int argc, char **argv)
{
    int i;
    for (i = 0; i < 1000000; i++) {
        char *test = (char*) malloc(12*sizeof(char));
        strcpy(test, "testingonly");
        // free(test);
    }
}

As above, my heap file looks like:

heap_v2/1
  t*: 1000001: 16081920 [0: 0]
  t0: 1000001: 16081920 [0: 0]
@ 0x7ff372fc9442 0x7ff372f7324d 0x7ff372acc416 0x7ff37343598a 0x7ff373435a89 0x7ff3734260ca
  t*: 1: 81920 [0: 0]
  t0: 1: 81920 [0: 0]
@ 0x7ff372fc9442 0x7ff372f7324d 0x562520fab072 0x7ff372d7809b 0x562520fab0ba
  t*: 1000000: 16000000 [0: 0]
  t0: 1000000: 16000000 [0: 0]

MAPPED_LIBRARIES:
562520faa000-562520fab000 r--p 00000000 fd:01 4503729                    /home/chris/code/personal/scratch-c/main
562520fab000-562520fac000 r-xp 00001000 fd:01 4503729                    /home/chris/code/personal/scratch-c/main
562520fac000-562520fad000 r--p 00002000 fd:01 4503729                    /home/chris/code/personal/scratch-c/main
562520fad000-562520fae000 r--p 00002000 fd:01 4503729                    /home/chris/code/personal/scratch-c/main
562520fae000-562520faf000 rw-p 00003000 fd:01 4503729                    /home/chris/code/personal/scratch-c/main
7fede8200000-7ff346c00000 rw-p 00000000 00:00 0 
7ff346d00000-7ff372800000 rw-p 00000000 00:00 0 
7ff3729f4000-7ff3729fa000 rw-p 00000000 00:00 0 
7ff3729fa000-7ff3729fd000 r--p 00000000 fd:01 13374006                   /lib/x86_64-linux-gnu/libgcc_s.so.1
7ff3729fd000-7ff372a0e000 r-xp 00003000 fd:01 13374006                   /lib/x86_64-linux-gnu/libgcc_s.so.1
...

ChrisMacNaughton commented 5 years ago

The above main was run like: MALLOC_CONF=prof_leak:true,lg_prof_sample:0,prof_final:true LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.2 ./main

gnzlbg commented 5 years ago

@ChrisMacNaughton are you running jemalloc's jeprof script on the profile ?

jemalloc's heap profile output files are a functional superset of those created by gperftools, so the gperftools heap profiler documentation is relevant reading. You will need to use the jeprof Perl script that comes with jemalloc rather than the pprof Perl script that is part of the gperftools distribution, because jemalloc uses an incompatible file format to output per thread heap profile data, whereas pprof only understands global heap profile data.

ChrisMacNaughton commented 5 years ago

I was using jemalloc's jeprof script

gnzlbg commented 5 years ago

I think it would be best if you could fill your C example as a jemalloc issue, and cross-link it with this one.

ChrisMacNaughton commented 5 years ago

Interestingly, the heap file being unclear doesn't seem to translate to the C example being rough - attached is a PRF generated from jeprof that seems to actually list some names c-heap.pdf compared to the rust-heap.pdf

gnzlbg commented 5 years ago

@ChrisMacNaughton interesting, can you check whether your jemalloc is being compiled with libgcc or libunwind ? If its using libgcc, could you try whether enabling --enable-prof-libunwind when configuring jemalloc (e.g. by adding that to the build.rs of jemalloc-sys) fixes the issue ?

ChrisMacNaughton commented 5 years ago

After adding:

diff --git a/jemalloc-sys/build.rs b/jemalloc-sys/build.rs
index 3801619..efd2664 100644
--- a/jemalloc-sys/build.rs
+++ b/jemalloc-sys/build.rs
@@ -257,6 +257,7 @@ fn main() {
         info!("--with-lg-vaddr={}", lg_vaddr);
         cmd.arg(format!("--with-lg-vaddr={}", lg_vaddr));
     }
+    cmd.arg("--enable-prof-libunwind");

     let mut use_prefix =
         env::var("CARGO_FEATURE_UNPREFIXED_MALLOC_ON_SUPPORTED_PLATFORMS").is_err();

my generated PDF still doesn't have usable call sites: heap2.pdf

gnzlbg commented 5 years ago

Can you upload the output of a verbose build (showing jemalloc's configure) somewhere (e.g. a github gist) ?

ChrisMacNaughton commented 5 years ago

https://gist.github.com/ChrisMacNaughton/a4e3bcc87eecc5175bb12df6bcd477f4

ChrisMacNaughton commented 5 years ago

Also, I just discovered that you can find that output for any build in target/debug/$crate_name-$hash/output

gnzlbg commented 5 years ago

@ChrisMacNaughton so for some reason enabling libunwind did not work out properly in your case, e.g., see https://gist.github.com/ChrisMacNaughton/a4e3bcc87eecc5175bb12df6bcd477f4#file-jemalloc-sys-output-L113 and https://gist.github.com/ChrisMacNaughton/a4e3bcc87eecc5175bb12df6bcd477f4#file-jemalloc-sys-output-L241

prof-libunwind     : 0
prof-libgcc        : 1

This (https://gist.github.com/ChrisMacNaughton/a4e3bcc87eecc5175bb12df6bcd477f4#file-jemalloc-sys-output-L105) shows that libunwind might not be available in your system (you might need to put it in the include path).

libunwind is jemalloc's preferred way of obtaining backtraces, and since the only things that appears to be missing from your profiles are function names, which are obtaining from backtraces, I hope that using libunwind and configuring jemalloc with it solves your problem.

EDIT: It also might be worth checking whether the C example was using a jemalloc version that uses libunwind or not - it might be that there is an error in the build.rs script that prevents it from getting picked.

ChrisMacNaughton commented 5 years ago

so, cool stuff - on my local copy that asks for libunwind, after I install libunwind-dev I get a stacktrace on building -

error: linking with `cc` failed: exit code: 1
  |
  = note: "cc" "-Wl,--as-needed" "-Wl,-z,noexecstack" "-m64" "-L" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.1dhd743xevaptqxl.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.1oauyhi5w56l2myy.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.1qq4g6y55of98yqm.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.1rn2lv02e1g66mtt.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.1rp4hgkfqq2k8v36.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.1wtqk70y3t0m0l9c.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.25b1ss4h4qsqoosn.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.2a4e3ezg7rv53lhh.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.2ey1n4o1vs5v2itc.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.2x4bjcsdiu7lm4wv.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.37tt8l8xk96kb4m9.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.397honbhcvj2ual0.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3cq70iicihmt5gpb.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3l609jl23a666n03.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3oeoev384fisf2xd.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3ppqn3a07e77mqu4.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3qh91fwzwyjr383r.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3yte41c8lbfvid1u.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3z45wgmhuczb4had.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.3z8lmz3jc99ykcfa.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.429codphhwxv9oeh.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.46ol83fcz68yxh0s.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.4dz1lzhbcge50wm1.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.4q4z2jeb52knvlon.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.4qt15eadl7flcwxl.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.4shw2jhq1mo7ycnq.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.4zbe8va8fix4ctdy.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.51t3zi686gr3ouom.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.5aj60j2zi0234gx4.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.5b4oyxgxf7avupua.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.5dlyu8ooret60bct.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.5ghsgkjufl26p5ig.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.qpdp5fm4v5jk0aj.rcgu.o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.t5oea9b5jm6i6hl.rcgu.o" "-o" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062" "/home/chris/code/personal/scratch/target/debug/deps/scratch-29080862a122c062.306vv9zjk9sd86k6.rcgu.o" "-Wl,--gc-sections" "-pie" "-Wl,-zrelro" "-Wl,-znow" "-nodefaultlibs" "-L" "/home/chris/code/personal/scratch/target/debug/deps" "-L" "/home/chris/code/personal/scratch/target/debug/build/jemalloc-sys-54f81408e0ea65bd/out/build/lib" "-L" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib" "-Wl,-Bstatic" "/home/chris/code/personal/scratch/target/debug/deps/libjemallocator-6b168eda01c167fd.rlib" "/home/chris/code/personal/scratch/target/debug/deps/libjemalloc_sys-244346456322387f.rlib" "/home/chris/code/personal/scratch/target/debug/deps/liblibc-bc45ba49c0ba2f4e.rlib" "-Wl,--start-group" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/libstd-e39317eb74365d3c.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/libpanic_unwind-4d55a38564aae54a.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/libbacktrace_sys-f8521075e248b627.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/libunwind-7c91ffdc8da860d3.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/librustc_demangle-0ad27b9879d551d3.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/liblibc-588f18eae3ea58be.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/liballoc-4ebf5caee903d98f.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/librustc_std_workspace_core-8895b32baedb08c6.rlib" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/libcore-6a9d233d01acc350.rlib" "-Wl,--end-group" "/home/chris/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/x86_64-unknown-linux-gnu/lib/libcompiler_builtins-851bb3b5f6c4db49.rlib" "-Wl,-Bdynamic" "-lpthread" "-lc" "-lm" "-lrt" "-lpthread" "-lutil" "-lutil" "-ldl" "-lrt" "-lpthread" "-lgcc_s" "-lc" "-lm" "-lrt" "-lpthread" "-lutil" "-lutil"
  = note: /usr/bin/ld: /home/chris/code/personal/scratch/target/debug/deps/libjemalloc_sys-244346456322387f.rlib(prof.pic.o): in function `_rjem_je_prof_backtrace':
          /home/chris/code/personal/scratch/target/debug/build/jemalloc-sys-54f81408e0ea65bd/out/build/../jemalloc/src/prof.c:327: undefined reference to `unw_backtrace'

gnzlbg commented 5 years ago

IIRC there were some linking errors with libunwind that were fixed upstream some time ago.

I've just opened a PR with a branch that let's you JEMALLOC_SYS_GIT_DEV_BRANCH=1 cargo build ... to automatically fetch the last upstream version and test with it: https://github.com/gnzlbg/jemallocator/pull/118

ChrisMacNaughton commented 5 years ago

well, slightly painful with your PR + my above diff: https://gist.github.com/ChrisMacNaughton/22dff39d5739ce1bd51b502ebeb17270

in essence:

$ JEMALLOC_SYS_GIT_DEV_BRANCH=1 cargo build
   Compiling jemalloc-sys v0.3.0 (/home/chris/code/personal/jemallocator/jemalloc-sys)
error: failed to run custom build command for `jemalloc-sys v0.3.0 (/home/chris/code/personal/jemallocator/jemalloc-sys)`
process didn't exit successfully: `/home/chris/code/personal/scratch/target/debug/build/jemalloc-sys-9d074e908b41813b/build-script-build` (exit code: 101)
<SNIP>
Cloning into '/home/chris/code/personal/scratch/target/debug/build/jemalloc-sys-54f81408e0ea65bd/out/jemalloc_repo'...
make: *** No rule to make target '../jemalloc/include/jemalloc/internal/hooks.h', needed by 'src/jemalloc.sym.o'.  Stop.
thread 'main' panicked at 'command did not execute successfully: "make" "srcroot=../jemalloc/" "-j" "8"
expected success, got: exit code: 2', /home/chris/code/personal/jemallocator/jemalloc-sys/build.rs:393:9
note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.

ordian commented 4 years ago

Here is a list of steps that worked for me on GNU/Linux: https://gist.github.com/ordian/928dc2bd45022cddd547528f64db9174

I hope future readers will find it useful.

esemeniuc commented 1 year ago

Note: make sure to check your executable directory is writeable (eg if you are running a systemd service, the working dir would be / by default)

You can see output like

Apr 20 15:03:05 hostname1 demo-app[3048129]: <jemalloc>: failed to open "jeprof.out.3048129.2.i2.heap"

This can be fixed using setting your envvar to be something like:

Environment=_RJEM_MALLOC_CONF=prof:true,prof_final:true,prof_leak:true,prof_gdump:true,lg_prof_interval:32,prof_prefix:/tmp/jeprof

The final created file would be like /tmp/jeprof.3084145.111.u111.heap

Make sure to also build your binary with debug symbols, for example adding this to cargo.toml:

[profile.release]
debug = true

View the graph with jeprof --web target/release/mybin $(ls -S1 /tmp/*.heap | head -n 1).

Make sure to run jeprof on the same system that the binary is built on, else you may get errors like this:

Using local file ~/jeprof.3085546.9823.i24.heap.
/usr/bin/objdump: '/usr/lib64/libpcre.so.1.2.12': No such file
/usr/bin/objdump: '/usr/lib64/libselinux.so.1': No such file
/usr/bin/objdump: '/usr/lib64/librt-2.33.so': No such file
/usr/bin/objdump: '/usr/lib64/libnss_usrfiles.so.2': No such file
/usr/bin/objdump: '/usr/lib64/libnss_files-2.33.so': No such file
/usr/bin/objdump: '/usr/lib64/libc-2.33.so': No such file
/usr/bin/objdump: '/usr/lib64/libm-2.33.so': No such file
/usr/bin/objdump: '/usr/lib64/libpthread-2.33.so': No such file
/usr/bin/objdump: '/usr/lib64/libdl-2.33.so': No such file
/usr/bin/objdump: '/usr/lib64/ld-2.33.so': No such file
/usr/bin/addr2line: '/usr/lib64/libpthread-2.33.so': No such file
/usr/bin/addr2line: '/usr/lib64/libc-2.33.so': No such file

gnzlbg / jemallocator

Unclear how to enable profiling #115