module PerfTools::MemProf

Overview

A simple in-memory memory profiler that tracks all allocations and deallocations by the garbage-collecting allocator.

Only Linux is supported at the moment.

To use the profiler, simply require this file in your project. By default, the profiler is enabled at program startup and does nothing else. MemProf.pretty_log_allocations(io : IO) should be called regularly to print a table of all allocated objects to the given IO:

require "perf_tools/mem_prof"

class Foo
end

arr = Array.new(100000) { Foo.new }
MemProf.pretty_log_allocations(STDOUT)

The above prints something like:

| Allocations | Total size | Context |
|------------:|-----------:|---------|
|       1 | 800,000 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/array.cr:122:17 in 'initialize'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/array.cr:112:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/array.cr:183:5 in '__crystal_main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'` |
| 100,000 | 400,000 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/primitives.cr:36:1 in 'new'`<br>`usr/test.cr:6:27 in '__crystal_main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:141:3 in 'main'` |

We could continue this example by truncating the array and printing the stats again:

arr.truncate(0, 1000)
MemProf.pretty_log_allocations(STDOUT)
| Allocations | Total size | Context |
|------------:|-----------:|---------|
|     1 | 800,000 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/array.cr:122:17 in 'initialize'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/array.cr:112:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/array.cr:183:5 in '__crystal_main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'` |
| 1,184 |   4,736 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/primitives.cr:36:1 in 'new'`<br>`usr/test.cr:6:27 in '__crystal_main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:141:3 in 'main'` |

Observe that most of the leaked Foos have been freed. The exact number of remaining allocations may change because the Boehm GC is non-deterministic.

MemProf.log_allocations(io : IO) could be used instead for a more machine-readable output format. Additionally, MemProf.log_object_counts(io : IO) and MemProf.log_object_sizes(io : IO) are available to tally the counts and heap sizes of all live objects of most reference types.

All logging methods in this module will automatically call GC.collect before printing.

NOTE As an in-memory profiler, MemProf will consume additional memory in the same process as the program being profiled. The amount of additional memory is proportional to the number of live allocations and MemProf::STACK_DEPTH.

Defined in:

perf_tools/mem_prof.cr

Constant Summary

MIN_BYTES = ENV["MEMPROF_MIN_BYTES"]?.try(&.to_i) || 1024

The minimum total byte size below which an allocation group is hidden for MemProf.log_allocations and MemProf.pretty_log_allocations. This can be used to hide small objects that are only allocated very few times, e.g. constants.

Configurable at run time using the MEMPROF_MIN_BYTES environment variable.

PRINT_AT_EXIT = ENV["MEMPROF_PRINT_AT_EXIT"]? == "1"

If set to 1, logs all allocations to the standard error stream upon normal program exit, via at_exit { MemProf.log_allocations(STDERR) }.

Configurable at run time using the MEMPROF_PRINT_AT_EXIT environment variable.

REF_LEVEL = (ENV["MEMPROF_REF_LEVEL"]? || "5").to_i

The maximum number of indirections to track MemProf.pretty_log_object_graph. 0 is "unlimited". Defaults to 5.

Configurable at run time using the MEMPROF_REF_LEVEL environment variable.

REF_LIMIT = (ENV["MEMPROF_REF_LIMIT"]? || "10").to_i

The maximum number of objects to track in MemProf.pretty_log_object_graph. 0 is "unlimited". Defaults to 10.

Configurable at run time using the MEMPROF_REF_LIMIT environment variable.

STACK_DEPTH = 5

The maximum number of stack frames shown for MemProf.log_allocations and MemProf.pretty_log_allocations.

Configurable at build time using the MEMPROF_STACK_DEPTH environment variable.

STACK_SKIP = 5

When obtaining a call stack, the top of the call stack will always be the profiling functions themselves, followed by the allocation functions themselves. These provide little useful information, so they are skipped by default. This constant controls the number of stack frames to skip; there is usually no reason to alter this.

Configurable at build time using the MEMPROF_STACK_SKIP environment variable.

Class Method Summary

Class Method Detail

def self.log_allocations(io : IO) : Nil #

Logs the total sizes of known live allocations, aggregated by their call stacks, to the given io.

The behavior of this method can be controlled by the STACK_DEPTH, STACK_SKIP, and MIN_BYTES constants.

The first line contains the number of lines that follow. After that, each line includes the allocation count, the total byte size of the allocations, then the call stack, separated by \ts. The lines do not assume any particular order. Example output: (MIN_BYTES == 150)

7
1       256     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:191:5 in 'from_stdio'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:40:5 in 'from_stdio' /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:25:10 in '~STDOUT:init' /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:25:1 in '__crystal_main'
1       256     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:191:5 in 'from_stdio'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:40:5 in 'from_stdio' /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:42:10 in '~STDERR:init' /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/once.cr:25:54 in 'once'
1       152     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/fiber.cr:88:3 in 'new'     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/concurrent.cr:61:3 in 'spawn:name'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:558:1 in '__crystal_main'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code' /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'
1       152     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/fiber.cr:125:3 in 'new'    /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/pthread.cr:42:19 in 'initialize'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/pthread.cr:39:3 in 'new'       /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/pthread.cr:62:3 in 'current'  /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/scheduler.cr:26:5 in 'enqueue'
1       152     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/fiber.cr:88:3 in 'new'     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/concurrent.cr:61:3 in 'spawn:name'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:60:5 in 'start_loop' /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:163:5 in 'setup_default_handlers'   /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:558:1 in '__crystal_main'
1       256     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:158:9 in 'pipe'    /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:141:5 in 'pipe'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:15:12 in '~Crystal::System::Signal::pipe:init'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/once.cr:25:54 in 'once'
1       256     /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'        /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:159:9 in 'pipe'    /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:141:5 in 'pipe'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:15:12 in '~Crystal::System::Signal::pipe:init'      /opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/once.cr:25:54 in 'once'

[View source]
def self.log_object_counts(io : IO) : Nil #

Logs the numbers of known live reference objects, aggregated by their types, to the given io.

The first line contains the number of lines that follow. After that, each line includes the object count, then a \t, then the type name for those objects. The lines do not assume any particular order. Example output:

19
4       IO::FileDescriptor
8       Hash(Thread, Deque(Fiber))
20      Crystal::SpinLock
8       Hash(Thread, Crystal::EventLoop::Event)
3       Fiber
1       Thread::LinkedList(Fiber)
1       Thread
1       Thread::LinkedList(Thread)
1       Crystal::Scheduler
1       Crystal::LibEvent::EventLoop
3       Deque(Fiber)
2       Mutex
1       Hash(Signal, Proc(Signal, Nil))
1       Hash(Tuple(UInt64, Symbol), Bool)
1       Hash(UInt64, UInt64)
1       Hash(Thread, Pointer(LibPCRE2::JITStack))
1       Hash(Int32, Int32)
1       Hash(Int32, Channel(Int32))
1       Hash(String, NamedTuple(time: Time, location: Time::Location))

[View source]
def self.log_object_sizes(io : IO) : Nil #

Logs the total sizes of known live reference objects, aggregated by their types, to the given io.

The "size" of an object includes the space it occupies on the heap. If the object was not allocated using GC.malloc_atomic, then its "size" also includes, recursively, the "sizes" of its reference-type instance variables, except that the same space is never counted more than once.

The "total size" of a reference type is then the total "sizes" of all of its live objects, except again that the same heap space is never counted more than once. Alternatively it is the total number of heap bytes transitively reachable from all live objects via pointers.

The first line contains the number of lines that follow. After that, each line includes the total size, then a \t, then the type name for those objects. The lines do not assume any particular order. Example output:

26
4       (class 88)
216     (class 131)
80      Crystal::SpinLock
16      (class 87)
24      (class 20)
72      (class 4)
24      (class 137)
24      (class 157)
1984    IO::FileDescriptor
448     Hash(Thread, Deque(Fiber))
448     Hash(Thread, Crystal::EventLoop::Event)
600     Fiber
704     Thread::LinkedList(Fiber)
600     Thread
400     Thread::LinkedList(Thread)
652     Crystal::Scheduler
24      Crystal::LibEvent::EventLoop
560     Deque(Fiber)
168     Mutex
152     Hash(Signal, Proc(Signal, Nil))
56      Hash(Tuple(UInt64, Symbol), Bool)
56      Hash(UInt64, UInt64)
56      Hash(Thread, Pointer(LibPCRE2::JITStack))
56      Hash(Int32, Int32)
56      Hash(Int32, Channel(Int32))
56      Hash(String, NamedTuple(time: Time, location: Time::Location))

NOTE Some classes do not have their names known. This affects only a small number of types in the standard library runtime.


[View source]
def self.object_size(object : Reference) : UInt64 #

Returns the total number of heap bytes occupied by object.

This is the same per-object "size" defined in .log_object_sizes.

Returns zero for string literals, as they are never allocated on the heap. Might also return zero for certain constants which are initialized before MemProf is activated.


[View source]
def self.pretty_log_allocations(io : IO) : Nil #

Logs the total sizes of known live allocations, aggregated by their call stacks, to the given io as a Markdown table.

The behavior of this method can be controlled by the STACK_DEPTH, STACK_SKIP, and MIN_BYTES constants.

The rows are sorted by each group's total size, then by allocation count, and finally by the call stacks. Example output: (MIN_BYTES == 150)

| Allocations | Total size | Context |
|------------:|-----------:|---------|
| 1 | 256 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:191:5 in 'from_stdio'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:40:5 in 'from_stdio'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:25:10 in '~STDOUT:init'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:25:1 in '__crystal_main'` |
| 1 | 256 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:191:5 in 'from_stdio'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:40:5 in 'from_stdio'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:42:10 in '~STDERR:init'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/once.cr:25:54 in 'once'` |
| 1 | 256 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:158:9 in 'pipe'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:141:5 in 'pipe'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:15:12 in '~Crystal::System::Signal::pipe:init'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/once.cr:25:54 in 'once'` |
| 1 | 256 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io/file_descriptor.cr:21:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/file_descriptor.cr:159:9 in 'pipe'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/io.cr:141:5 in 'pipe'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:15:12 in '~Crystal::System::Signal::pipe:init'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/once.cr:25:54 in 'once'` |
| 1 | 152 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/fiber.cr:125:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/pthread.cr:42:19 in 'initialize'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/pthread.cr:39:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/pthread.cr:62:3 in 'current'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/scheduler.cr:26:5 in 'enqueue'` |
| 1 | 152 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/fiber.cr:88:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/concurrent.cr:61:3 in 'spawn:name'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:558:1 in '__crystal_main'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:129:5 in 'main_user_code'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/main.cr:115:7 in 'main'` |
| 1 | 152 | `/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/fiber.cr:88:3 in 'new'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/concurrent.cr:61:3 in 'spawn:name'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:60:5 in 'start_loop'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/crystal/system/unix/signal.cr:163:5 in 'setup_default_handlers'`<br>`/opt/homebrew/Cellar/crystal/1.9.2/share/crystal/src/kernel.cr:558:1 in '__crystal_main'` |

[View source]
def self.pretty_log_object_graph(io : IO, type : T.class) : Nil forall T #

Logs the objects that are transitively reachable to a given type of objects, outputing a mermaid graph to the given io. The graph contains an indication of the field that links an object, or its index if the field is not known.

Example:

class A
  @bs = Array(B).new

  def add(b : B)
    @bs << b
  end
end

class B
  @c : C

  def initialize(@c : C)
  end
end

class C; end

a = A.new
a.add(B.new C.new)
a.add(B.new C.new)

PerfTools::MemProf.pretty_log_object_graph STDOUT, C

produces the following graph:

graph LR
  0x109736e80["0x109736e80 C"]
  0x109736e70["0x109736e70 C"]
  0x10972fe40["0x10972fe40 B"] --@c,0--> 0x109736e80
  0x10972fe20["0x10972fe20 (class 0)"] --@(field 0),1--> 0x10972fe40
  0x10972fe60["0x10972fe60 Array(B)"] --@(field 16),2--> 0x10972fe20
  0x10972fe80["0x10972fe80 A"] --@bs,3--> 0x10972fe60
  0x10972fe00["0x10972fe00 B"] --@c,0--> 0x109736e70
  0x10972fe20["0x10972fe20 (class 0)"] --@(field 8),1--> 0x10972fe00

(class 0) is the buffer of the array. The number next to the field is the level of indirection, counting as 0 for the objects that direct links to an object of the given type, 1 for the objects that have a direct link to an object of the given type, and so on.

The graph is limited to REF_LIMIT objects and REF_LEVEL levels of indirection.


[View source]