CODEWITHSUNDEEP
crystal-langkemal
Sergey Makridenkov
Sergey Makridenkov

Reputation: 624

Slow exception report in Kemal

I use crystal 32.1 and Kemal. In case I have runtime exception it take 21 seconds to print backtrace. Any idea why it take so long?

500 GET /chats/by_sale/1 21280.52ms

Backtrace:

web_1     | I, [2020-02-07 17:57:33 +00:00 #1]  INFO -- : [1]
web_1     | Exception: Expected string for object name (JSON::Error)
web_1     |   from /usr/share/crystal/src/json/builder.cr:308:16 in 'start_scalar'
web_1     |   from /usr/share/crystal/src/json/builder.cr:295:11 in 'start_scalar'
web_1     |   from /usr/share/crystal/src/json/builder.cr:194:5 in 'start_object'
web_1     |   from src/service/json.cr:220:5 in 'object'
web_1     |   from src/controller/chat.cr:37:5 in '->'
web_1     |   from lib/kemal/src/kemal/route.cr:255:3 in '->'
web_1     |   from lib/kemal/src/kemal/route_handler.cr:255:3 in 'process_request'
web_1     |   from lib/kemal/src/kemal/route_handler.cr:17:7 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from lib/kemal/src/kemal/websocket_handler.cr:13:14 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from lib/kemal/src/kemal/filter_handler.cr:21:7 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from src/middleware/authenticate.cr:17:7 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from lib/kemal/src/kemal/static_file_handler.cr:68:9 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from lib/kemal/src/kemal/log_handler.cr:8:37 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
web_1     |   from lib/kemal/src/kemal/init_handler.cr:12:7 in 'call'
web_1     |   from /usr/share/crystal/src/http/server/request_processor.cr:48:11 in 'process'
web_1     |   from /usr/share/crystal/src/http/server/request_processor.cr:22:3 in 'process'
web_1     |   from /usr/share/crystal/src/http/server.cr:497:5 in 'handle_client'
web_1     |   from /usr/share/crystal/src/http/server.cr:463:13 in '->'
web_1     |   from /usr/share/crystal/src/fiber.cr:255:3 in 'run'
web_1     |   from /usr/share/crystal/src/fiber.cr:47:34 in '->'
web_1     |   from ???
web_1     |
web_1     | 2020-02-07 17:57:54 UTC 500 GET /chats/by_sale/1 21280.52ms

Upvotes: 1

Views: 74

Answers (1)

rogerdpack
rogerdpack

Reputation: 66851

Large for a comment so making it an answer.

How I'd handle this is by running your server in gdb, then in the "middle of the 21 second pause" you hit ctrl+c in your server. It'll drop you into gdb. Then run gdb backtrace command and see if it tells you anything. Another option might be to run a profiler on it, there are a few mentioned here: or even the gdb "poor man's profiler" which also works for crystal (in OS X the sample command does something similar FWIW), and run it during the slowdown in question.

Upvotes: 1

Related Questions