Rohit_Karake

Rohit_Karake

Slowness issue due to logger_file_backend

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.

Most Liked

adw632

adw632

If your average traffic rate exceeds the average disk IO rate that you can flush logs to disk then you will never catch up and logs will backup in memory (unless you are discarding) until you get an out of memory error.

The back pressure from transitioning to sync mode exists because the disk IO rate is insufficient and the only relief is to push back against the source of the overload lest you consume all memory and crash.

It sounds like you need additional disk IO throughput. Consider changing the disk type to a higher performance class or adding additional additional disks to your instance and striping your filesystem. Depending on the IOops your VM is currently pushing vs it’s nominal capacity you may need to consider using an instance type with higher IO throughput.

Fundamentally the IO is not keeping up, it’s not CPU bound and it’s not memory bound, so fix the root cause.

LostKobrakai

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.

LostKobrakai

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.

Where Next?

Popular in Questions Top

pgiesin
This should be a simple problem but I just can’t seem to figure it out. I have a standalone Elixir app that won’t find the database. Dep...
New
fireproofsocks
I’m working on defining a simple Ecto schema for a table (in PostGres), but I don’t see where I can define a column as NOT NULL. Conside...
New
sacepums
Hey guys. I'm new to elixir and im really stocked about it. But I ran into a bit of problem - I need to convert a date sting, for examp...
New
script
If I have a string “1000 cfu/ml” . I want to remove the characters and / and space . So the string is like this "1000" What is the ...
New
minhajuddin
I have seen a lot of code which picks the first element from a list using Enum.at(0) instead of List.first. Is there a reason why people ...
New
alice
Hey, Just curious what are the main benefits of Elixir compared to Clojure? When is Elixir more useful than Clojure and vice versa? Th...
New
vonH
When I run the Plug and I recompile I wind up having to use Ctrl C to quit iex and start again. Witht the help of rlwrap I can use the cu...
New
baxterw3b
Hi guys, i’m new in the Elixir world, and i have to say, that i love it! i’m having some problem to understand anonymous functions with ...
New
jc00ke
Expanding on this topic: https://forum.elixirforum.net/t/map-typespec-question/19217 Let’s say I have a map with required and optional k...
New
jay1
Why is it that the mnesia database isn’t the most preferred database for use in Elixir/Phoenix?
New

Other popular topics Top

chrismccord
Phoenix 1.4.0 released Phoenix 1.4 is out! This release ships with exciting new features, most notably with HTTP2 support, improved deve...
688 30048 115
New
peerreynders
Manning 2016 Halloween weekend sale via Deal of the Day Friday, October 28 - Half off all MEAPs - code WM102816LT Saturday, October 29 ...
326 29600 154
New
grych
Hi folks, Few months ago I have announced the proof-of-concept of the library to manipulate the browsers DOM objects directly from Elixi...
639 49522 488
New
freewebwithme
Using vs code and installed ElixirLS: support and debugger. And I got an error popped up on start up says Failed to run ‘elixir’ comma...
New
mcarvalho
What is the difference between System.get_env and Application.get_env? For example, what are best practices to use one versus another.
New
mgjohns61585
Could someone help me? I'm making my first elixir program, number guessing game. I can't figure out how to convert the user's guess from ...
New
ashish173
I am using Ecto timestamps with postgres, I can see the timestamps() use the :naive_dateime but for my use case I wanted to store the ti...
New
electic
Hi, I am new to Elixir. I am trying to use the DateTime component to insert a date into MySQL however the there seems to be no way to fo...
New
siddhant3030
Hi, I have to write a raw query for one of my project. But till now I have used ecto queries and don’t have much experience writing raw ...
New
magnetic
Hey :wave:t3: Elixir community, I’ve been learning Elixir, and working on some side projects. My editor of choice is VSCode, and althoug...
New

We're in Beta

About us Mission Statement