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

New
Tee
can someone please explain to me how Enum.reduce works with maps
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
lastday4you
I wanted to check elixir version in phoenix because i found that my elixir is 1.5 but when i use Enum.chunk_by it said the function is un...
New
skosch
To my knowledge, put_in, Map.update etc. all have the one limitation of not automatically creating intermediate keys when needed (for exa...
New
beno
I will often find my self writing things similar to: case some_value do nil -> something() "" -> something() _ -> somethi...
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
fayddelight
I tried installing elixir 1.11.2 erlang 23.3.4 via asdf in my zsh shell. Enabled the versions locally and globally. When I list them ...
New
romenigld
I am trying to run a deploy with docker and I successfully runned with this command: docker build -t romenigld/blog-prod . but when I t...
New
Brian
What is the proper way to load a module from a file in to IEX? In the python world, doing something like this pretty standard: from ....
New

Other popular topics Top

malloryerik
Hi, this is for people who, like me, have had some friction using .html.heex templates in VSCode. The solution seems to be, in a hyphena...
New
WestKeys
Currently suffering from paralysis by [HTTP client] analysis. This is rather unusual in Elixirland as there tends to be consensus on the ...
New
shahryarjb
Hello, I have map which I want to convert it to string like this: the map: %{last_name: "tavakkoli", name: "shahryar"} the string I ne...
New
Fl4m3Ph03n1x
About me? ( if you have nothing better to do than reading about some random guy in the internet :stuck_out_tongue: ) Hello all, this is ...
New
saif
Hello everyone, Long time lurker first time poster here. I’ve recently begun working on Elixir full-time again! :raised_hands: It’s been...
New
rms.mrcs
Hi, I need to transform a list of numbers into a map where the keys are the indexes and the values are the original values of the list. ...
New
shijith.k
I am trying to start a new phoenix project with elixir 1.9, but mix phx.new does not work. It says that ** (Mix) The task "phx.new" could...
New
AstonJ
We’ve put together this wiki for Phoenix LiveView - please feel free to add any info you feel is worth including. What is Phoenix LiveV...
New
joaquinalcerro
Hi there, I am working with Ecto-Postgresql and I need to call all of the records from a specific table but the table has 40,000 records...
New
hariharasudhan94
Lets say I have map like this fetching from my database %{"_id" => #BSON.ObjectId<58eb1a7a9ad169198c3dXXXX>, "email" => ...
New

Latest on Elixir Forum

Elixir Forum

We're in Beta

About us Mission Statement