alloc profile: print percentage of allocs missed #15

vilterp · 2022-01-10T21:04:43Z

merges into #42768

Print out the number of allocs missed by the profile, to give us a handle on how big of a problem JuliaLang#43688 is.

Uses the same counters used by @time. Multiplies the number of sampled allocs by the sample rate to see how many the alloc profiler would have seen, if the sample rate was 1.

Q: I did this entirely in Julia-land, but it may be cleaner to do on the existing structs in C++-land, to avoid introducing more global variables. Not sure.

stdlib/Profile/src/Allocs.jl

NHDaly

Cool, yeah! This idea looks great. I left comments on how to do this without having to call fetch() multiple times, which should help with your TODO. :)

LGTM other than that - i'll have another look when that's done! 😊

vilterp · 2022-01-11T01:15:31Z

K, should be good to go now

Co-Authored-By: [email protected]

NHDaly · 2022-01-11T15:50:01Z

stdlib/Profile/src/Allocs.jl

+    @show(length(decoded_results.allocs))
+    @show(_g_expected_sampled_allocs[])


Remove these before merge?

NHDaly

Looks great. Can you show an example of how it looks?

vilterp · 2022-01-11T19:09:43Z

Here's an example:

julia> prof = Profile.Allocs.fetch()
┌ Warning: The allocation profiler is not fully implemented, and missed 28% (1222 / 4328) of allocs in the last run. For more info see https://github.com/JuliaLang/julia/issues/43688
└ @ Main.Profile.Allocs ~/code/julia/stdlib/Profile/src/Allocs.jl:124
Main.Profile.Allocs.AllocResults(...)

should we stick it in the doc string or something? 🤔 🤷‍♂️

When calling `jl_error()` or `jl_errorf()`, we must check to see if we are so early in the bringup process that it is dangerous to attempt to construct a backtrace because the data structures used to provide line information are not properly setup. This can be easily triggered by running: ``` julia -C invalid ``` On an `i686-linux-gnu` build, this will hit the "Invalid CPU Name" branch in `jitlayers.cpp`, which calls `jl_errorf()`. This in turn calls `jl_throw()`, which will eventually call `jl_DI_for_fptr` as part of the backtrace printing process, which fails as the object maps are not fully initialized. See the below `gdb` stacktrace for details: ``` $ gdb -batch -ex 'r' -ex 'bt' --args ./julia -C invalid ... fatal: error thrown and no exception handler available. ErrorException("Invalid CPU name "invalid".") Thread 1 "julia" received signal SIGSEGV, Segmentation fault. 0xf75bd665 in std::_Rb_tree<unsigned int, std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo>, std::_Select1st<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> >, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__k=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h:1277 1277 /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h: No such file or directory. #0 0xf75bd665 in std::_Rb_tree<unsigned int, std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo>, std::_Select1st<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> >, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__k=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h:1277 #1 std::map<unsigned int, JITDebugInfoRegistry::ObjectInfo, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__x=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_map.h:1258 #2 jl_DI_for_fptr (fptr=4155049385, symsize=symsize@entry=0xffffcfa8, slide=slide@entry=0xffffcfa0, Section=Section@entry=0xffffcfb8, context=context@entry=0xffffcf94) at /cache/build/default-amdci5-4/julialang/julia-master/src/debuginfo.cpp:1181 #3 0xf75c056a in jl_getFunctionInfo_impl (frames_out=0xffffd03c, pointer=4155049385, skipC=0, noInline=0) at /cache/build/default-amdci5-4/julialang/julia-master/src/debuginfo.cpp:1210 #4 0xf7a6ca98 in jl_print_native_codeloc (ip=4155049385) at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:636 #5 0xf7a6cd54 in jl_print_bt_entry_codeloc (bt_entry=0xf0798018) at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:657 #6 jlbacktrace () at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:1090 #7 0xf7a3cd2b in ijl_no_exc_handler (e=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:605 #8 0xf7a3d10a in throw_internal (ct=ct@entry=0xf070c010, exception=<optimized out>, exception@entry=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:638 #9 0xf7a3d330 in ijl_throw (e=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:654 #10 0xf7a905aa in ijl_errorf (fmt=fmt@entry=0xf7647cd4 "Invalid CPU name \"%s\".") at /cache/build/default-amdci5-4/julialang/julia-master/src/rtutils.c:77 #11 0xf75a4b22 in (anonymous namespace)::createTargetMachine () at /cache/build/default-amdci5-4/julialang/julia-master/src/jitlayers.cpp:823 #12 JuliaOJIT::JuliaOJIT (this=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/jitlayers.cpp:1044 #13 0xf7531793 in jl_init_llvm () at /cache/build/default-amdci5-4/julialang/julia-master/src/codegen.cpp:8585 #14 0xf75318a8 in jl_init_codegen_impl () at /cache/build/default-amdci5-4/julialang/julia-master/src/codegen.cpp:8648 #15 0xf7a51a52 in jl_restore_system_image_from_stream (f=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2131 #16 0xf7a55c03 in ijl_restore_system_image_data (buf=0xe859c1c0 <jl_system_image_data> "8'\031\003", len=125161105) at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2184 #17 0xf7a55cf9 in jl_load_sysimg_so () at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:424 #18 ijl_restore_system_image (fname=0x80a0900 "/build/bk_download/julia-d78fdad601/lib/julia/sys.so") at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2157 #19 0xf7a3bdfc in _finish_julia_init (rel=rel@entry=JL_IMAGE_JULIA_HOME, ct=<optimized out>, ptls=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/init.c:741 #20 0xf7a3c8ac in julia_init (rel=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/init.c:728 #21 0xf7a7f61d in jl_repl_entrypoint (argc=<optimized out>, argv=0xffffddf4) at /cache/build/default-amdci5-4/julialang/julia-master/src/jlapi.c:705 #22 0x080490a7 in main (argc=3, argv=0xffffddf4) at /cache/build/default-amdci5-4/julialang/julia-master/cli/loader_exe.c:59 ``` To prevent this, we simply avoid calling `jl_errorf` this early in the process, punting the problem to a later PR that can update guard conditions within `jl_error*`.

When calling `jl_error()` or `jl_errorf()`, we must check to see if we are so early in the bringup process that it is dangerous to attempt to construct a backtrace because the data structures used to provide line information are not properly setup. This can be easily triggered by running: ``` julia -C invalid ``` On an `i686-linux-gnu` build, this will hit the "Invalid CPU Name" branch in `jitlayers.cpp`, which calls `jl_errorf()`. This in turn calls `jl_throw()`, which will eventually call `jl_DI_for_fptr` as part of the backtrace printing process, which fails as the object maps are not fully initialized. See the below `gdb` stacktrace for details: ``` $ gdb -batch -ex 'r' -ex 'bt' --args ./julia -C invalid ... fatal: error thrown and no exception handler available. ErrorException("Invalid CPU name "invalid".") Thread 1 "julia" received signal SIGSEGV, Segmentation fault. 0xf75bd665 in std::_Rb_tree<unsigned int, std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo>, std::_Select1st<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> >, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__k=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h:1277 1277 /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h: No such file or directory. #0 0xf75bd665 in std::_Rb_tree<unsigned int, std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo>, std::_Select1st<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> >, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__k=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_tree.h:1277 #1 std::map<unsigned int, JITDebugInfoRegistry::ObjectInfo, std::greater<unsigned int>, std::allocator<std::pair<unsigned int const, JITDebugInfoRegistry::ObjectInfo> > >::lower_bound (__x=<optimized out>, this=0x248) at /usr/local/i686-linux-gnu/include/c++/9.1.0/bits/stl_map.h:1258 #2 jl_DI_for_fptr (fptr=4155049385, symsize=symsize@entry=0xffffcfa8, slide=slide@entry=0xffffcfa0, Section=Section@entry=0xffffcfb8, context=context@entry=0xffffcf94) at /cache/build/default-amdci5-4/julialang/julia-master/src/debuginfo.cpp:1181 #3 0xf75c056a in jl_getFunctionInfo_impl (frames_out=0xffffd03c, pointer=4155049385, skipC=0, noInline=0) at /cache/build/default-amdci5-4/julialang/julia-master/src/debuginfo.cpp:1210 #4 0xf7a6ca98 in jl_print_native_codeloc (ip=4155049385) at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:636 #5 0xf7a6cd54 in jl_print_bt_entry_codeloc (bt_entry=0xf0798018) at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:657 #6 jlbacktrace () at /cache/build/default-amdci5-4/julialang/julia-master/src/stackwalk.c:1090 #7 0xf7a3cd2b in ijl_no_exc_handler (e=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:605 #8 0xf7a3d10a in throw_internal (ct=ct@entry=0xf070c010, exception=<optimized out>, exception@entry=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:638 #9 0xf7a3d330 in ijl_throw (e=0xf0794010) at /cache/build/default-amdci5-4/julialang/julia-master/src/task.c:654 #10 0xf7a905aa in ijl_errorf (fmt=fmt@entry=0xf7647cd4 "Invalid CPU name \"%s\".") at /cache/build/default-amdci5-4/julialang/julia-master/src/rtutils.c:77 #11 0xf75a4b22 in (anonymous namespace)::createTargetMachine () at /cache/build/default-amdci5-4/julialang/julia-master/src/jitlayers.cpp:823 #12 JuliaOJIT::JuliaOJIT (this=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/jitlayers.cpp:1044 #13 0xf7531793 in jl_init_llvm () at /cache/build/default-amdci5-4/julialang/julia-master/src/codegen.cpp:8585 #14 0xf75318a8 in jl_init_codegen_impl () at /cache/build/default-amdci5-4/julialang/julia-master/src/codegen.cpp:8648 #15 0xf7a51a52 in jl_restore_system_image_from_stream (f=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2131 #16 0xf7a55c03 in ijl_restore_system_image_data (buf=0xe859c1c0 <jl_system_image_data> "8'\031\003", len=125161105) at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2184 #17 0xf7a55cf9 in jl_load_sysimg_so () at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:424 #18 ijl_restore_system_image (fname=0x80a0900 "/build/bk_download/julia-d78fdad601/lib/julia/sys.so") at /cache/build/default-amdci5-4/julialang/julia-master/src/staticdata.c:2157 #19 0xf7a3bdfc in _finish_julia_init (rel=rel@entry=JL_IMAGE_JULIA_HOME, ct=<optimized out>, ptls=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/init.c:741 #20 0xf7a3c8ac in julia_init (rel=<optimized out>) at /cache/build/default-amdci5-4/julialang/julia-master/src/init.c:728 #21 0xf7a7f61d in jl_repl_entrypoint (argc=<optimized out>, argv=0xffffddf4) at /cache/build/default-amdci5-4/julialang/julia-master/src/jlapi.c:705 #22 0x080490a7 in main (argc=3, argv=0xffffddf4) at /cache/build/default-amdci5-4/julialang/julia-master/cli/loader_exe.c:59 ``` To prevent this, we simply avoid calling `jl_errorf` this early in the process, punting the problem to a later PR that can update guard conditions within `jl_error*`. (cherry picked from commit 21ab24e)

vilterp requested a review from NHDaly January 10, 2022 21:04

vilterp commented Jan 10, 2022

View reviewed changes

stdlib/Profile/src/Allocs.jl Outdated Show resolved Hide resolved

NHDaly reviewed Jan 10, 2022

View reviewed changes

stdlib/Profile/src/Allocs.jl Outdated Show resolved Hide resolved

NHDaly reviewed Jan 10, 2022

View reviewed changes

stdlib/Profile/src/Allocs.jl Outdated Show resolved Hide resolved

NHDaly reviewed Jan 10, 2022

View reviewed changes

stdlib/Profile/src/Allocs.jl Outdated Show resolved Hide resolved

NHDaly reviewed Jan 10, 2022

View reviewed changes

vilterp force-pushed the pv-alloc-profile-allocs-missed branch 2 times, most recently from 991912c to 4328436 Compare January 11, 2022 01:05

vilterp added 4 commits January 10, 2022 20:39

print out percentage of allocs missed

e98589b

remove some debug printlns

107ece0

PR feedback

c4bebea

Co-Authored-By: [email protected]

more PR feedback: _ before global names

f4f1a62

vilterp force-pushed the pv-alloc-profile-allocs-missed branch from 154458e to f4f1a62 Compare January 11, 2022 01:39

NHDaly reviewed Jan 11, 2022

View reviewed changes

NHDaly approved these changes Jan 11, 2022

View reviewed changes

remove @shows

3f219c7

vilterp merged commit b25005a into pv-alloc-profile-flat-stacks Jan 11, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

alloc profile: print percentage of allocs missed #15

alloc profile: print percentage of allocs missed #15

vilterp commented Jan 10, 2022 •

edited

Loading

NHDaly left a comment

vilterp commented Jan 11, 2022

NHDaly Jan 11, 2022

NHDaly left a comment

vilterp commented Jan 11, 2022

		@show(length(decoded_results.allocs))
		@show(_g_expected_sampled_allocs[])

alloc profile: print percentage of allocs missed #15

alloc profile: print percentage of allocs missed #15

Conversation

vilterp commented Jan 10, 2022 • edited Loading

NHDaly left a comment

Choose a reason for hiding this comment

vilterp commented Jan 11, 2022

NHDaly Jan 11, 2022

Choose a reason for hiding this comment

NHDaly left a comment

Choose a reason for hiding this comment

vilterp commented Jan 11, 2022

vilterp commented Jan 10, 2022 •

edited

Loading