Hello folks,
Been using --debug with release builds in order to collect as much backtrace information when exceptions are raised.
Take the following comparing example:
cat boom.cr
def boom
raise "BOOM!"
end
def foo
boom
end
foo
When compiled without options (crystal build boom.cr) here is the obtained backtrace of that exception:
./boom
Unhandled exception: BOOM! (Exception)
from boom.cr:6:3 in 'foo'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/once.cr:44:0 in '__crystal_main'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/main.cr:110:5 in 'main_user_code'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/main.cr:96:7 in 'main'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/main.cr:119:3 in 'main'
from __libc_start_main
from _start
from ???
This is similar to adding --debug option, but --release produces something different:
./boom
Unhandled exception: BOOM! (Exception)
from boom.cr:2:3 in 'boom'
from boom.cr:6:3 in 'foo'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/string.cr:252:13 in '__crystal_main'
from __libc_start_main
from _start
from ???
And combining both --release and --debug, produces the following:
./boom
Unhandled exception: BOOM! (Exception)
from boom.cr:2:3 in 'boom'
from boom.cr:6:3 in 'foo'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/once.cr:44:0 in '__crystal_main'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/main.cr:110:5 in 'main_user_code'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/main.cr:96:7 in 'main'
from /home/luis/.asdf/installs/crystal/1.1.1/share/crystal/src/crystal/main.cr:119:3 in 'main'
from __libc_start_main
from _start
from ???
However, while this has provided me a rich and accurate backtraces, it also introduced some performance issues.
Take the following HTTP server program:
require "http/server"
server = HTTP::Server.new do |context|
context.response.content_type = "text/plain"
context.response.print "Hello world!"
end
Signal::INT.trap do
puts "Shutdown requested."
server.close
end
server.bind_tcp "0.0.0.0", 8080
puts "Listening on:"
server.addresses.each do |addr|
puts "- #{addr}"
end
puts "Use Ctrl-C to stop"
server.listen
When compiled with just --release mode, it shows the following when performing some synthetic benchmarks:
$ plow -c 5 -d 30s http://localhost:8080/
Benchmarking http://localhost:8080/ for 30s using 5 connection(s).
@ Real-time charts is listening on http://127.0.0.1:18888/
Summary:
Elapsed 30s
Count 1064809
2xx 1064809
RPS 35492.713
Reads 3.419MB/s
Writes 1.963MB/s
Statistics Min Mean StdDev Max
Latency 18µs 136µs 96µs 11.184ms
RPS 32672.67 35492.35 787.3 36242.86
Latency Percentile:
P50 P75 P90 P95 P99 P99.9 P99.99
127µs 167µs 204µs 230µs 309µs 1.546ms 1.97ms
Latency Histogram:
120µs 868738 81.59%
184µs 165186 15.51%
249µs 24780 2.33%
407µs 4904 0.46%
1.317ms 758 0.07%
1.838ms 427 0.04%
1.989ms 13 0.00%
2.743ms 3 0.00%
Versus the exact same program build with --release --debug shows a ~30% slowdown:
$ plow -c 5 -d 30s http://localhost:8080/
Benchmarking http://localhost:8080/ for 30s using 5 connection(s).
@ Real-time charts is listening on http://127.0.0.1:18888/
Summary:
Elapsed 30s
Count 647954
2xx 647954
RPS 21597.793
Reads 2.080MB/s
Writes 1.195MB/s
Statistics Min Mean StdDev Max
Latency 33µs 223µs 104µs 3.604ms
RPS 20597.5 21597.24 345.18 22196.03
Latency Percentile:
P50 P75 P90 P95 P99 P99.9 P99.99
211µs 265µs 320µs 356µs 453µs 1.641ms 2.182ms
Latency Histogram:
204µs 518839 80.07%
260µs 83098 12.82%
325µs 35479 5.48%
417µs 9054 1.40%
789µs 1097 0.17%
1.574ms 267 0.04%
1.831ms 95 0.01%
2.17ms 25 0.00%
Only references I could find about debug symbols were around this issue and this PR associated with DWARF symbols.
Thoughts or recommendations?
Cheers,
Luis