Garbage profiler by vilterp · Pull Request #42658 · JuliaLang/julia

vilterp · 2021-10-15T02:25:30Z

Ever seen a @time printout like this:

5091.986425 seconds (5.59 G allocations: 324.011 GiB, 57.83% gc time, 5.70% compilation time)

…and wondered what the types are of all those objects which are being allocated and collected? This PR is for you…

It generates a report of how many objects of each type are being freed during each garbage collection.

Usage

file = open("gc-profile.csv", "w")
GC.start_garbage_profile(file)

# ... the code you want to profile ...

GC.stop_garbage_profile()
flush(file) # TODO: figure out how to do this from C...

Output

A CSV file with these columns:

gc_epoch: an integer that starts at 0 and increases each time the garbage collector runs
type: type of julia object being freed
num_freed number of that type freed during that GC epoch

e.g.:

gc_epoch,type,num_freed
1,Foo,5
1,Bar,6
2,Foo,3
2,Bar,2

Output is streamed to this file as the program runs.

To aggregate this over all GC epochs, I've been using csvsql to run do a group by:

$ csvsql --query 'select type, sum(num_freed) from "gc-profile" group by type order by sum(num_freed) desc' gc-profile.csv > gc-profile-agg.csv

Notes

mimics the callback approach of Heap snapshot #42286

issues / improvements

is this threadsafe? i.e. can the allocator be called into from multiple threads, which might lead to mutating the hash map concurrently?
put a timestamp on each log line
put GC type (full vs. incremental) on each log line
enable logging & profiling with one function call? can be defined in Julia

Future work

get stack traces of allocations (especially useful to attribute generic types like Array{UInt8, 1})
maybe output as PProf memory profile format, like in this article (scroll down to see graphviz output): https://www.freecodecamp.org/news/how-i-investigated-memory-leaks-in-go-using-pprof-on-a-large-codebase-4bec4325e192/

don't seem to really be doing much

DilumAluthge · 2021-10-15T02:54:12Z

You have trailing whitespace on the following lines:

src/gc-garbage-profiler.cpp:90:}    
src/gc-garbage-profiler.cpp:146:

timholy · 2021-10-15T08:08:20Z

Some kind of memory profiling would be awesome. I assume you've seen this alternative, but if not: #33467. If we had that, would you still want this?

NHDaly · 2021-10-15T13:56:52Z

(I think this is still in Draft, so i've removed me and Jameson as reviewers. Let me know when you're ready for review Pete, and i'll add us back)

DilumAluthge · 2021-10-15T14:02:11Z

FYI, you will need to fix the analyzegc failures.

vilterp · 2021-10-22T19:05:44Z

@timholy good question. This seemed like the fastest way to get a basic handle on our garbage problem, but it does immediately beg the question of where the allocations come from. So, I would still love to get a memory profiler with stacks!

vilterp · 2021-10-23T15:50:57Z

Folded into #42768

@Profile

## Overview Record the type and stack of every allocation (or only at a given sample interval), and return as Julia objects. Alternate approach to existing alloc profiler PR: #33467 Complementary to garbage profiler PR: #42658 (maybe there's some nice way to meld them) This may be reinventing the wheel from #33467, but I'm not sure why that one needs stuff like LLVM passes. I mimicked some stuff from it, but this was my attempt to get something up and running. Could easily be missing stuff. ## Usage: ```julia using Profile.Allocs res = Allocs.@Profile sample_rate=0.001 my_func() prof = Allocs.fetch() # do something with `prof` ``` See also: JuliaPerf/PProf.jl#46 for support for visualizing these. Co-authored-by: Nathan Daly <nhdaly@gmail.com>

@Profile

## Overview Record the type and stack of every allocation (or only at a given sample interval), and return as Julia objects. Alternate approach to existing alloc profiler PR: JuliaLang#33467 Complementary to garbage profiler PR: JuliaLang#42658 (maybe there's some nice way to meld them) This may be reinventing the wheel from JuliaLang#33467, but I'm not sure why that one needs stuff like LLVM passes. I mimicked some stuff from it, but this was my attempt to get something up and running. Could easily be missing stuff. ## Usage: ```julia using Profile.Allocs res = Allocs.@Profile sample_rate=0.001 my_func() prof = Allocs.fetch() # do something with `prof` ``` See also: JuliaPerf/PProf.jl#46 for support for visualizing these. Co-authored-by: Nathan Daly <nhdaly@gmail.com>

@Profile

## Overview Record the type and stack of every allocation (or only at a given sample interval), and return as Julia objects. Alternate approach to existing alloc profiler PR: JuliaLang#33467 Complementary to garbage profiler PR: JuliaLang#42658 (maybe there's some nice way to meld them) This may be reinventing the wheel from JuliaLang#33467, but I'm not sure why that one needs stuff like LLVM passes. I mimicked some stuff from it, but this was my attempt to get something up and running. Could easily be missing stuff. ## Usage: ```julia using Profile.Allocs res = Allocs.@Profile sample_rate=0.001 my_func() prof = Allocs.fetch() # do something with `prof` ``` See also: JuliaPerf/PProf.jl#46 for support for visualizing these. Co-authored-by: Nathan Daly <nhdaly@gmail.com>

vilterp added 7 commits October 14, 2021 21:35

split out garbage profiler into its own file

6187ab2

remove dead code

e2a3310

fix call of wrong variant

919e7b1

forgot the julia wrappers

8453759

fix stuff

cf2618d

call hooks from gc.c

d7ca0df

rename for consistency

4df2868

vilterp mentioned this pull request Oct 15, 2021

Garbage Profiler vilterp/julia#2

Closed

1 task

vilterp added 2 commits October 14, 2021 22:41

add flushes

0278112

don't seem to really be doing much

fix printing of duration

feac913

vilterp added 2 commits October 14, 2021 23:08

put sorting back in

7cb9e40

remove whitespace

ae9657d

DilumAluthge requested review from NHDaly and vtjnash October 15, 2021 03:12

vilterp added 2 commits October 14, 2021 23:23

log a timestamp with each gc event

f8b8f4b

record collection type

81e8afe

NHDaly removed request for NHDaly and vtjnash October 15, 2021 13:56

vilterp mentioned this pull request Oct 22, 2021

Allocation profiler #42768

Merged

7 tasks

vilterp closed this Oct 23, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Garbage profiler#42658

Garbage profiler#42658
vilterp wants to merge 13 commits intoJuliaLang:masterfrom
vilterp:pv-garbage-profile-separate

vilterp commented Oct 15, 2021 •

edited

Loading

Uh oh!

DilumAluthge commented Oct 15, 2021

Uh oh!

timholy commented Oct 15, 2021

Uh oh!

NHDaly commented Oct 15, 2021

Uh oh!

DilumAluthge commented Oct 15, 2021 •

edited

Loading

Uh oh!

vilterp commented Oct 22, 2021

Uh oh!

vilterp commented Oct 23, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Uh oh!

Conversation

vilterp commented Oct 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Usage

Output

Notes

issues / improvements

Future work

Uh oh!

DilumAluthge commented Oct 15, 2021

Uh oh!

timholy commented Oct 15, 2021

Uh oh!

NHDaly commented Oct 15, 2021

Uh oh!

DilumAluthge commented Oct 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vilterp commented Oct 22, 2021

Uh oh!

vilterp commented Oct 23, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

vilterp commented Oct 15, 2021 •

edited

Loading

DilumAluthge commented Oct 15, 2021 •

edited

Loading