# Memory profiling
**URL:** https://forum.crystal-lang.org/t/memory-profiling/4888
**Category:** Crystal Contrib
**Created:** [August 25, 2022, 8:50pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888 "2022-08-25T20:50:03Z")
**Posts on this page:** 17
**Page:** 1
### Author:  [@asterite](https://forum.crystal-lang.org/u/asterite)
#### Post date: [August 25, 2022, 8:50pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/1 "2022-08-25T20:50:03Z")
To optimize a program’s memory usage, which might also impact its speed (allocating memory is slow compared to other things) I had this idea: what if there’s a callback of some sort any time an object is created? Then we can build code around that callback to gather stats.
Here’s a diff to the compiler’s source code that enables that:
```diff
--- a/src/compiler/crystal/semantic/new.cr
+++ b/src/compiler/crystal/semantic/new.cr
@@ -215,6 +215,9 @@ module Crystal
exps << init
exps << If.new(RespondsTo.new(obj.clone, "finalize").at(self),
Call.new(Path.global("GC").at(self), "add_finalizer", obj.clone).at(self))
+ {% if env("TRACE_NEW") == "1" %}
+ exps << Call.new(nil, "__trace_new", args: [Var.new("self").at(self)] of ASTNode, global
+ {% end %}
exps << obj
# Forward block argument if any
@@ -244,6 +247,9 @@ module Crystal
exps = Array(ASTNode).new(3)
exps << assign
exps << If.new(RespondsTo.new(var.clone, "finalize").at(loc), call).at(loc)
+ {% if env("TRACE_NEW") == "1" %}
+ exps << Call.new(nil, "__trace_new", args: [Var.new("self").at(loc)] of ASTNode, global:
+ {% end %}
exps << var.clone
a_def = Def.new("new", body: exps).at(loc)
```
That’s the simplest thing I came up with, but it could be a compiler flag or something.
With that, every `initialize` method that expands into a `new` class method will have a call to a global `__trace_new` method (this could be done differently.)
Of course that `__trace_new` method doesn’t exist, but we can create it!
Let’s try it…
```crystal
def __trace_new(type : T.class) forall T
LibC.printf("%s\n", T.name)
end
puts "Hello world!"
```
Now if you run that program with a compiler build with the above patch (and compiled with TRACE\_NEW=1) you’ll see this output:
```auto
Array(Pointer(Bool))
Crystal::OnceState
Array(String)
Path
Iterator::Stop
Deque(Pointer(Void))
Thread::Mutex
Fiber::StackPool
Slice(T)
Slice(T)
Slice(UInt8)
(... and a lot more)
```
Those are all the objects being created!
But that’s not very useful as an output.
We can put the names into a hash and count them!
```crystal
module Tracing
class_property? running = false
class_property(stats : Hash(String, Int32)) do
Hash(String, Int32).new(0)
end
at_exit do
Tracing.stats.to_a.sort_by(&.[1]).each do |type, count|
puts "# #{type} #{count}"
end
end
end
def __trace_new(type : T.class) forall T
return if Tracing.running?
Tracing.running = true
Tracing.stats[T.name] += 1
Tracing.running = false
end
```
Now we get this output (I’ll show just the last bits):
```auto
Hash(Thread, Deque(Fiber)) 8
Crystal::ThreadLocalValue(Deque(Fiber)) 8
Hash(Thread, Crystal::Event) 8
Crystal::ThreadLocalValue(Crystal::Event) 8
Crystal::SpinLock 19
```
I had no idea the empty Crystal program created 19 spin locks!
Well, tracing memory allocation of structs doesn’t make sense, so we can stick a `{% if T.class? %}` there. Here’s the result:
```auto
IO::FileDescriptor 4
Hash(Thread, Deque(Fiber)) 8
Hash(Thread, Crystal::Event) 8
Crystal::SpinLock 19
```
(notice the ThreadLocalValue is gone, because it’s a struct)
That’s a bit more useful, but where are all those spinlocks being created?
So I came up with a tracing that has two modes. In the default mode it will show the above output. Then you can specify a target, in this case `Crystal::SpinLock` and it will tell you the most frequent callstacks where this happens.
Here’s the code for that:
```crystal
module Tracing
class_property(target : String) do
ENV["TRACE_TARGET"]? || ""
end
BACKTRACE_LIMIT = ENV["TRACE_BACKTRACE_LIMIT"]?.try(&.to_i) || 6
MIN_COUNT = ENV["TRACE_MIN_COUNT"]?.try(&.to_i)
class_property? running = false
class_property(stats : Hash(String, Int32)) do
Hash(String, Int32).new(0)
end
class_property(callstacks : Array(Exception::CallStack)) do
Array(Exception::CallStack).new
end
at_exit do
Tracing.running = true
if Tracing.target.empty?
Tracing.show_stats
else
Tracing.show_callstacks
end
end
def self.show_callstacks
puts "Done!"
puts "All callstacks: #{Tracing.callstacks.size}"
puts "Gathering callstack..."
callstack_to_backtrace = Hash(Exception::CallStack, Array(String)).new do |h, k|
h[k] = k.printable_backtrace(Tracing::BACKTRACE_LIMIT)
end
backtraces = Tracing.callstacks.map_with_index do |callstack, i|
LibC.printf("%d\n", i) if i.divisible_by?(10_000)
callstack_to_backtrace[callstack]
end
sorted_backtraces =
backtraces
.tally
.to_a
.sort_by { |backtrace, count| -count }
min_count = Tracing::MIN_COUNT
if min_count
sorted_backtraces.reject! do |backtrace, count|
count < min_count
end
end
sorted_backtraces
.each do |backtrace, count|
puts "#{count} times:"
puts "=" * 40
backtrace.each do |frame|
puts frame
end
end
end
def self.show_stats
Tracing.stats.to_a.sort_by(&.[1]).each do |k, v|
puts "#{k}: #{v}"
end
end
end
def __trace_new(type : T.class) forall T
return if Tracing.running?
Tracing.running = true
target = Tracing.target
if target.empty?
{% if T.class? %}
Tracing.stats[T.name] += 1
{% end %}
else
if T.name == target
Tracing.callstacks << Exception::CallStack.new
end
end
Tracing.running = false
end
```
Now we can compile that program. Let’s call it `bar.cr`:
```auto
crystal build bar.cr
```
Now if we run it we get the same output as before.
But then we can run it like this:
```auto
TRACE_TARGET=Crystal::SpinLock ./bar
```
And we get this output:
```auto
Done!
All callstacks: 23
Gathering callstack...
0
2 times:
========================================
bar.cr:83:29 in '__trace_new'
src/primitives.cr:36:1 in 'new'
src/crystal/thread_local_value.cr:4:12 in 'new'
src/io/evented.cr:12:14 in 'new'
src/crystal/system/unix/file_descriptor.cr:187:5 in 'from_stdio'
src/io/file_descriptor.cr:35:5 in 'from_stdio'
2 times:
========================================
bar.cr:83:29 in '__trace_new'
src/primitives.cr:36:1 in 'new'
src/crystal/thread_local_value.cr:4:12 in 'new'
src/io/evented.cr:13:14 in 'new'
src/crystal/system/unix/file_descriptor.cr:187:5 in 'from_stdio'
src/io/file_descriptor.cr:35:5 in 'from_stdio'
2 times:
========================================
bar.cr:83:29 in '__trace_new'
src/primitives.cr:36:1 in 'new'
src/crystal/thread_local_value.cr:4:12 in 'new'
src/io/evented.cr:15:17 in 'new'
src/crystal/system/unix/file_descriptor.cr:187:5 in 'from_stdio'
src/io/file_descriptor.cr:35:5 in 'from_stdio'
(...and a lot more...)
```
You can control how many callstack frames to take into account. The default is 6 but maybe that’s too much. Let’s change it to 3.
```auto
$ TRACE_TARGET=Crystal::SpinLock TRACE_BACKTRACE_LIMIT=3 ./bar
Done!
All callstacks: 23
Gathering callstack...
0
20 times:
========================================
bar.cr:83:29 in '__trace_new'
src/primitives.cr:36:1 in 'new'
src/crystal/thread_local_value.cr:4:12 in 'new'
2 times:
========================================
bar.cr:83:29 in '__trace_new'
src/primitives.cr:36:1 in 'new'
src/mutex.cr:24:11 in 'new'
1 times:
========================================
bar.cr:83:29 in '__trace_new'
src/primitives.cr:36:1 in 'new'
src/crystal/scheduler.cr:73:11 in 'new'
```
Now we can quickly see that the most usual allocation of it happens in ThreadLocalValue.
The nicest thing about this is that **how** memory is tracked and profiled is entirely up to the user. Maybe the standard library can provide a default one, like the above. But it’s completely customizable, and entirely in Crystal.
I’m actually starting to use that to profile the compiler, to reduce memory allocations (it seems we are allocating a lot of arrays of ASTNode!)
Do you think this can be helpful to have? Did you wanted something like this in the past?
---
### Author:  [@bararchy](https://forum.crystal-lang.org/u/bararchy)
#### Post date: [August 25, 2022, 9:04pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/2 "2022-08-25T21:04:27Z")
This is amazing! Many times I needed to try and use perf and callgrind but there is no good trace to show where it was called. with this it seems like a very easy way to find and reduce overly generated objects! this is very very cool!
---
### Author:  [@HertzDevil](https://forum.crystal-lang.org/u/HertzDevil)
#### Post date: [August 25, 2022, 9:10pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/3 "2022-08-25T21:10:42Z")
I am a bit hesitant about making this a regular call. For this particular kind of profiling we should only ever need to call `__trace_new` from the `allocate` primitive.
---
### Author:  [@asterite](https://forum.crystal-lang.org/u/asterite)
#### Post date: [August 25, 2022, 9:22pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/4 "2022-08-25T21:22:12Z")
> [@HertzDevil](#):
>
> For this particular kind of profiling we should only ever need to call `__trace_new` from the `allocate` primitive
It’s a great observation! I actually initially wanted to do it for the `allocate` primitive. The problem is that the primitive would have to somehow do the call, typechecking it. So maybe the `allocate` method that’s on every object should call the primtiive and something else before that. But at that point I realized, for the proof of concept, I only needed to patch the `new` method.
That said, maybe `new` is a good place, because this is called once the object is fully complete. Maybe you’d like to do some stats on specific objects, no idea.
---
### Author:  [@HertzDevil](https://forum.crystal-lang.org/u/HertzDevil)
#### Post date: [August 25, 2022, 9:29pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/5 "2022-08-25T21:29:52Z")
My idea is we could simply inject a _fun_ call `__trace_new(T.crystal_instance_type_id)` in the codegen phase which avoids much of the type inference, since the compiler code generating the tracing calls should itself be fast. For a tracer to be useful we also need similar funs to to go from a type ID to a C string of the corresponding type, or vice versa. (This idea came up when I was working on the GDB / LLDB pretty-printers, since a union variable also needs this capability to get the correct run-time type.)
---
### Author:  [@yxhuvud](https://forum.crystal-lang.org/u/yxhuvud)
#### Post date: [August 26, 2022, 4:47pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/6 "2022-08-26T16:47:16Z")
This sounds very useful.
> Do you think this can be helpful to have?
Yes, at least in some form.
> Did you wanted something like this in the past?
Yes. I’ve been playing around with `valgrind --tool=dhat` which provides something very similar (looking at the output is highly recommended and may give ideas for improvement) . Unfortunately the valgrind tools doesn’t recognize the allocating functions crystal uses, so both the `dhat` and `massif`only see what linked libraries make use of. So when using `dhat` on the compiler then it only shows a couple of code generation places and a couple of thousand invokations to `getcwd` (which call malloc down in `libc`. Being able to find such places in crystal code would be great.
Hmm, i wonder what valgrind actually does and if it is extensible. Or how hard it is to output the same format valgrind does - having a prebuilt tool to navigate tries of allocating stack traces would be pretty nice.
---
### Author:  [@wontruefree](https://forum.crystal-lang.org/u/wontruefree)
#### Post date: [August 26, 2022, 6:57pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/7 "2022-08-26T18:57:08Z")
Some profilers like `perf` write out to a file and then process the data later. Is that to keep from messing with original code the profiler is measuring? If so I wonder if that is a pattern we would want in crystal.
---
### Author:  [@hugopl](https://forum.crystal-lang.org/u/hugopl)
#### Post date: [August 30, 2022, 5:52pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/8 "2022-08-30T17:52:21Z")
> [@yxhuvud](#):
>
> Unfortunately the valgrind tools doesn’t recognize the allocating functions crystal uses, so both the `dhat` and `massif`only see what linked libraries make use of.
Thanks very much, I tried to use massif with a crystal program weeks ago, it was just showing allocations made by libyaml and I had no idea why.
---
### Author:  [@hugopl](https://forum.crystal-lang.org/u/hugopl)
#### Post date: [August 30, 2022, 5:59pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/9 "2022-08-30T17:59:24Z")
This proposal just add the call to `__trace_new` on auto-generated new method? Or does it also do that for user written `self.new` methods?
I think that a call `__trace_new` (`__trace_alloc`?) on `allocate` seems to cover these use cases where the user writes it own `self.new` to re-use some cache and avoid a call to `allocate`.
---
### Author:  [@yxhuvud](https://forum.crystal-lang.org/u/yxhuvud)
#### Post date: [August 30, 2022, 7:43pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/10 "2022-08-30T19:43:10Z")
I’d be very happy if someone figured out a way to make valgrind see the allocations.
---
### Author:  [@hugopl](https://forum.crystal-lang.org/u/hugopl)
#### Post date: [August 30, 2022, 10:25pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/11 "2022-08-30T22:25:03Z")
The way to do this is to figure out a way to let Boehm GC use `malloc` instead of `sbrk` to expand the heap… I just found an option to let it use `mmap`, that also doesn’t work with valgrind.
---
### Author:  [@rogerdpack](https://forum.crystal-lang.org/u/rogerdpack)
#### Post date: [September 15, 2022, 4:34am UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/12 "2022-09-15T04:34:42Z")
Unrelated but would it be possible to do something like this for “all function calls”? Sometimes I yearn for ruby’s -rtracer equivalent… :)
---
### Author:  [@rogerdpack](https://forum.crystal-lang.org/u/rogerdpack)
#### Post date: [October 16, 2022, 4:48am UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/13 "2022-10-16T04:48:05Z")
What are you wishing valgrind showed you in this case?
---
### Author:  [@yxhuvud](https://forum.crystal-lang.org/u/yxhuvud)
#### Post date: [October 16, 2022, 6:00pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/14 "2022-10-16T18:00:00Z")
> What are you wishing valgrind showed you in this case?
Allocations that go through LibGC. With the dhat tool that would then enable to get a good view of where things are allocated, with an easy way to adjust how much of the stacktrace that is cared about.
---
### Author:  [@rogerdpack](https://forum.crystal-lang.org/u/rogerdpack)
#### Post date: [October 19, 2022, 4:38am UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/15 "2022-10-19T04:38:10Z")
Interesting. I guess there’s bdw’s [KEEP\_BACK\_PTRS](https://github.com/ivmai/bdwgc/blob/ed627bb33576317556d64d43596dfbaa60226f17/doc/README.macros) but it seems like it’s hard to actually use? Maybe someday crystal could have an alternative GC like “reference counting” or something, for use with dhat if desired. Some people might prefer it to bdw anyway…maybe could make a naive implementation initially, that ignores circular references… :)
---
### Author:  [@HertzDevil](https://forum.crystal-lang.org/u/HertzDevil)
#### Post date: [June 20, 2023, 12:58pm UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/16 "2023-06-20T12:58:41Z")
Returning to this, if we don’t care about performance of the tracer itself, we actually don’t need to modify the compiler itself at all:
```crystal
# prelude.cr
class Reference
macro inherited
def self.allocate : self
# do something
previous_def
end
end
end
# built-in types already existing before the `Reference.inherited` hook
# (`String` doesn't use `.allocate` and will have to do something else in
# `.new(capacity : Int, &)` manually)
{% for t in {Array, Hash, Regex, Exception} %}
class {{ t }}
def self.allocate : self
# do something
previous_def
end
end
{% end %}
# all requires must go after this for the macro hook to work
```
Also there’ll need to be special provisions for `Pointer.malloc` / `GC.malloc` which matters when a program creates large `Array`s or `Hash`es.
---
### Author:  [@carlhoerberg](https://forum.crystal-lang.org/u/carlhoerberg)
#### Post date: [June 30, 2023, 7:47am UTC](https://forum.crystal-lang.org/t/memory-profiling/4888/17 "2023-06-30T07:47:05Z")
If you compile the crystal application with `-Dgc_none` then `valgrind` will pick up allocations and show the full stacktrace, as “normal” `malloc`s are then made and not using the GC (mmap). Of course no memory will ever be freed, but can help never the less while developing.