Rohit_Karake
Recently I started using logger_file_backend to log the info level logs to the file which then is getting used for Kibana through Elasticsearch.
While doing performance testing we encountered a slowness issue when we enable the logger_file_backend.
I am able to reproduce the same issue in my local with the following Logger configuration:
config :logger,
backends: [
:console,
{LoggerFileBackend, :test}
]
config :logger, :console,
format: "[$level] $message\n",
level: :info,
sync_threshold: 100,
discard_threshold: 500
config :logger, :test,
metadata: [:request_id, :user_id, :api],
path: "./log/test.log",
level: :info
I have created a simple “hello world” API to check the performance and ran it using Apache benchmarking tool : ab -k -c 500 -n 500 http://localhost:4000/api/v1/hello
In the output I can see following response time:
[info] Sent 200 in 30ms
[info] Sent 200 in 30ms
[info] Sent 200 in 30ms
[info] Sent 200 in 30ms
[info] Sent 200 in 30ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 32ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
[info] Sent 200 in 31ms
When I am disabling the LoggerFileBackend in :backends then for the same test I am getting following results:
[info] Sent 200 in 4ms
[info] Sent 200 in 5ms
[info] Sent 200 in 4ms
[info] Sent 200 in 4ms
[info] Sent 200 in 5ms
[info] Sent 200 in 5ms
[info] Sent 200 in 5ms
[info] Sent 200 in 5ms
It seems like file writing is taking more time and the messages are getting piled up in the logger queue.
I have tried out with multiple settings of :sync_threshold & :discard_threshold but nothing seems to optimize the performance.
I am using following elixir and erlang version for my demo phoenix application:
elixir 1.13.4-otp-23 erlang 23.2.1
Can anyone tell how we can optimize this to even save the :debug level logs in the file as we do not want to loose the logs?
Please also suggest any other alternate way to do the same without sacrificing performance if possible.
Trending in Questions
Other Trending Topics
Categories:
Sub Categories:
Forums
Popular Tags
- #ecto
- #liveview
- #troubleshooting
- #learning-elixir
- #library
- #deployment
- #erlang
- #testing
- #genserver
- #mix
- #absinthe
- #remote-other
- #otp
- #plug
- #how-to-question
- #macros
- #postgres
- #elixirconf
- #channels
- #exunit
- #discussion
- #code-sync
- #podcasts
- #javascript
- #onsite
- #dialyzer
- #docker
- #authentication
- #umbrella
- #full-time-contract
- #podcasts-by-brainlid
- #ecto-query
- #elixirconf-us
- #ai
- #blog-post
- #elixir-ls
- #phoenix_html
- #iex
- #graphql
- #genstage
- #websockets
- #supervisor
- #advent-of-code
- #distillery
- #processes
- #api
- #forms
- #elixirconf-eu
- #metaprogramming
- #hex










Showing Posts 1 to 10- Show Best Posts
- Show All (oldest first)
- Show All (newest first)
LostKobrakai
Those settings are not for performance optimization. They exist to make sure your app doesn’t fall over when there’s to many logs to be handled. It does so by first making sure logs are written synchronously (app waits on logs to be written, making it write less logs) and if that doesn’t help by not writing logs at all (even less than before). Under normal operations you don’t want to hit those thresholds.
Not having a performance hit is not possible. Writing to disk is by definition slower than not needing to interact with the disk. I can’t speak for if the performance you’re seeing is reasonable or not, but it’s for sure expected to exist.
You can look into other ways to handle logs, which don’t require writing to disk. You might need to consider your constraints in terms of durability of logs though.
dimitarvp
Not necessarily but I haven’t looked under the covers of Erlang’s or Elixir’s logging. I authored a small Golang logging wrapper some months ago (for sending log events to OpenObserve.AI) and I just had it spawn a background goroutine (== Elixir process) and a logger call was just sending message to its channel, and that data was sent to the network on arrival of that channel.
There are ways to do this better and I would be somewhat puzzled if Erlang / Elixir haven’t went about it the same way. I should probably go check the code.
LostKobrakai
Was this golang library writing to disk? It doesn’t sound like it did.
dimitarvp
No, but sending to network can be even slower. Point is, the I/O was relegated to a background worker and was never happening in-place at the time of the logger calls.
LostKobrakai
That’s what the logger does by default as well as far as I know. But it switches to be synchronous or dropping logs when the backend gets overloaded.
dimitarvp
That makes sense. Do you think that is what is happening to OP? Does not seem to be the case but who knows, we don’t know the entire story.
josevalim
If you can update your Elixir and OTP versions, Elixir v1.15 comes with built-in support for file logging: Logger — Logger v1.20.2
derek-zhou
How much log are we talking about, 1MB per second, 10MB per second, or 100MB per second?
I only log to console and use a logging daemon such as svlogd, which should be faster than the built-in file logger, but at very high logging throughput, you may need some custom solution.
Rohit_Karake
Yes, that is the case happening with my application. The log traffic is huge which is getting piled up in Logger queue and after a sync_threshold its going into synchronous mode. I tried playing with the sync_threshold and discard_threshold settings but its not helping much after enabling file logging.
Rohit_Karake
Thanks for the quick reply @josevalim. I tried upgrading the Elixir version to v1.15 and setting the deafult handler config as mentioned in the doc:
I agree that it gives the inbuilt functionality to log it into the file and removes the dependency of using
logger_file_backendbut its behaviour is almost similar to thelogger_file_backendie. it has overload protection.Is there any way where we can keep this Logger constantly in
:asyncmode. And what will be the consequences of doing it so?Regards