Fluentd's flush thread seems to have died

[zxhdaniel]

Describe the bug

I am running Fluentd version1.14.6 with the Prometheus plugin enabled to collect data. However, I noticed that the data suddenly stopped being sent. Upon running 'top -H -p', I discovered that the flush thread appears to have crashed.

Here is my dashboard and expr
Fluentd output buffer queue：fluentd_output_status_buffer_queue_length{type="http"}
Fluentd output retry count：fluentd_output_status_retry_count{type="http"}
Current total size of stage and queue buffers：fluentd_output_status_buffer_total_bytes{type="http"}
output rate：rate(fluentd_output_status_write_count{type="http"}[1m])
The output rate chart shows t shows that the output rate has dropped to zero.

To Reproduce

run it base on the docker image: fluent/fluentd-kubernetes-daemonset:v1.14-debian-kafka2-1

Expected behavior

normal operation

Your Environment

- Fluentd version:1.14.6
- TD Agent version:
- Operating system: Debian GNU/Linux 11 (bullseye)
- Kernel version: 3.10.0-1160.83.1.el7.x86_64

Your Configuration

<source>
  @type tail
  path  /disk1/log/query.log
  path_key __path__
  pos_file /var/log/fluentd/query.pos
  tag query-log
  read_lines_limit 50
  open_on_every_update true

  <parse>
    @type regexp
    expression /^\[(?<logTime>[^]]+)]\s\[\S+-\w+-\d+]\s\w+\s+\S+\s-\slogType=(?<logType>\S+)\sclientInfo=(?<processId>\S+)\sdiagCode=(?<diagCode>[^=]+)\sdiagMsg=\["(?<diagMsg>.+)"]\srawJson=(?<rawJson>.+)$/
    time_key logTime
    keep_time_key true
  </parse>
</source>

<match query-log>
  <buffer tag>
    @type file
    path /var/log/fluentd/buffer

    # Buffering Parameters
    chunk_limit_size 2M
    queue_limit_length 1024
    overflow_action drop_oldest_chunk
    queued_chunks_limit_size 10

    # Flushing Parameters
    flush_mode interval
    flush_thread_count 20
    flush_interval 0.01

    # Retries Parameters
    retry_max_interval 30
  </buffer> 

  @type http
  @id output-http
  endpoint {my_endpoint}
  tls_ca_cert_path /fluentd/etc/cert/CA_ROOT.crt
  tls_verify_mode none
  tls_version TLSv1_2
  http_method post
  json_array true
  open_timeout 2
  read_timeout 10
  headers_from_placeholders {"x-tag":"${tag}"}
  <format>
    @type json
  </format>
</match>

Your Error Log

no error log

Additional context

No response

[daipom]

Please follow the contributing guidelines.

To Reproduce

run it base on the docker image: fluent/fluentd-kubernetes-daemonset:v1.14-debian-kafka2-1

With this information, we are unable to reproduce this issue and cannot judge if it is a bug or not.

Please report bugs only after you have confirmed some degree of reproducibility.
Otherwise, please use discussions.

[zxhdaniel]

I resolved it after rebooting. But if I can only solve the problem by rebooting, will it be inconvenient for me to use it?

[daipom]

If this occurs repeatedly, please share that information.
For example, how often it occurs and if there is any reproducibility.

[zxhdaniel]

Next time it happens again, I'll see if I can provide more detailed information.

[daipom]

Thanks!
We welcome such information.
If we can find out anything about regularity or reproducibility, we may be able to assist you in some way.

[zxhdaniel]

It happens again

[zxhdaniel]

It happens again，my system log level is error, i found the message may be relevant

the text:
2023-03-23 21:41:22 +0800 [error]: #0 [output-http] found broken chunk file during resume. Deleted corresponding files: path="/var/log/fluentd/buffer/buffer.b5f7916e96c692a2c74b024423aaaa9ca.log" mode=:staged err_msg="staged file chunk is empty"
2023-03-23 21:43:04 +0800 [error]: Worker 0 finished unexpectedly with signal SIGKILL
2023-03-23 21:43:05 +0800 [error]: #0 [output-http] found broken chunk file during resume. Deleted corresponding files: path="/var/log/fluentd/buffer/buffer.b5f79174ae08d0af80ceebbd78c5f3d69.log" mode=:staged err_msg="staged file chunk is empty"

By the way, my process is killed frequently cause of oom, I'm not sure if there's a memory leak here.

[daipom]

I am concerned about the increase in retry counts.
Is it possible that out_http is failing to send data?

You should probably also check system-wide memory status.

If memory exhaustion is occurring, please consider reducing data to read and adjusting Fluentd settings such as flush_thread_count.

[zxhdaniel]

I am sure that out_http is good, because other fluentd instances were able to send data successfully at that time. My fluentd is running in a separate docker container, so the system memory should not affect it. As for my configuration, I have set the flush thread to20, but when I observe it using 'top -H' and combine it with the output rate chart, it seems that only3-6 threads are actually working. I am feeling very confused.

[zxhdaniel]

However, I think it is possible that this is due to frequent oomkill. My docker container limits the memory to384MiB, the file generation speed is about1MiB/s, and the files are matched with regular expressions and output to out_http. Currently, the container is often killed. This afternoon, I used ObjectSpace to dump all the objects for analysis, but the total size of the dumped objects was only50MiB. I am now a little hopeless. Why does fluentd consume so much memory?

[zxhdaniel]

Another issue is that my program uses file buffer. When this happens, the file buffer accumulates, but when I restart the application, the file buffer is cleared. This means that all the accumulated data is lost. Is this normal behavior or did I misconfigure something?

[daipom]

2023-03-23 21:41:22 +0800 [error]: #0 [output-http] found broken chunk file during resume. Deleted corresponding files: path="/var/log/fluentd/buffer/buffer.b5f7916e96c692a2c74b024423aaaa9ca.log" mode=:staged err_msg="staged file chunk is empty"

This log means the buffer file is broken.
It sometimes occurs when the system power down forcibly.
I don't know, but it could be caused by a process kill.

If the file is broken, that data has no choice but to be discarded.
We need to prevent forced termination that would corrupt files.

[zxhdaniel]

I have several points of confusion at the moment:

1. For a 1MiB/s file parsed by regex and sent to out_http, what is the recommended memory setting? I currently have it set to 384MiB, but still experience OOM issues. I understand that I have used file buffer, so it shouldn't take up that much memory.
2. When the buffer is full and fluentd is restarted, will all files in the buffer directory be cleared?
3. Is flush_thread responsible for sending data to out_http? I have set flush_thread_count to 20 and flush_interval to 0.1, but it doesn't seem to speed up the sending process.
4. What is enqueue_thread for? Does the chunk only get read from the file into memory when it is ready to be sent to out_http?
   Can you please help me clarify these questions? I am getting frustrated with trying to figure them out.

[zxhdaniel]

@daipom Can you please help me clarify these questions? I am getting frustrated with trying to figure them out.

[daipom]

Why does fluentd consume so much memory?

I am getting frustrated with trying to figure them out.

PELASE follow the rules! : code of conduct.

• https://github.com/cncf/foundation/blob/main/code-of-conduct.md?plain=1#L48

  Giving constructive feedback

Fluentd is open-source software. We all need to work together to make it better.
Please do not make negative comments, even if you are frustrated.

1. For a 1MiB/s file parsed by regex and sent to out_http, what is the recommended memory setting? I currently have it set to 384MiB, but still experience OOM issues. I understand that I have used file buffer, so it shouldn't take up that much memory.

Even if you use file buffer, memory is consumed depending on the size of the data when data read in one time is written to a buffer or data in a buffer is sent to an output destination.
This means that memory is consumed depending on the throughput even if you use file buffer.

All I can recommend is that if you want to solve this problem without increasing more memory, you have to reduce the data to be collected or adjust the settings.

read_lines_limit 50 is a good setting for Memory, This should limit the amount of data processed at one time, leading to lower memory consumption.

It may be possible that parsing using regular expressions is consuming a large amount of memory.
Once you try different parsers you may be able to tell if the regular expression is the cause or not.

Example:

  <parse>
    @type none
  </parse>

In addition, you can adjust the following settings for lower memory consumption.

• Reduce flush_thread_count: Ex. flush_thread_count 2
• Increase flush_interval: Ex. flush_interval 10
• Remove queued_chunks_limit_size setting to set this to default value 1
• Remove queue_limit_length setting since this setting is deprecated.

2. When the buffer is full and fluentd is restarted, will all files in the buffer directory be cleared?

When Fluentd restarts, it first tries to send all remaining buffers.

3. Is flush_thread responsible for sending data to out_http? I have set flush_thread_count to 20 and flush_interval to 0.1, but it doesn't seem to speed up the sending process.

You should speed DOWN the sending process for lower memory consumption.

4. What is enqueue_thread for? Does the chunk only get read from the file into memory when it is ready to be sent to out_http?
   Can you please help me clarify these questions? I am getting frustrated with trying to figure them out.

Yes. There are two points about memory consumption.

• when Input plugin read data and writes it to a chunk file
• when Output plugin reads from a chunk file and sends it

[daipom]

Please refer to this document for details.

https://docs.fluentd.org/configuration/buffer-section#buffering-parameters

[zxhdaniel]

Sorry for my negative attitude earlier, and thank you very much for your professional advice.
I will try to adjust my configuration again. I also have some questions:

Remove queue_limit_length setting since this setting is deprecated.

1. Should I remove the queue_limit_length configuration and use total_limit_size instead? Currently, the logic in the code is that if queue_limit_length is specified, then total_limit_size = queue_limit_length * chunk_limit_size. So, I understand that there is no problem using queue_limit_length currently.

When Fluentd restarts, it first tries to send all remaining buffers.

2. If I try to send all the data in the buffer during a restart, could this also lead to oom if there are too many buffered data? Is the sending rate slow or will all the data in the buffer be loaded into memory at once?

3. I also encountered a situation where the flush thread suddenly stopped working. Do you have any ideas on this issue?

4. Is the buffer_stage_byte_size printed in the monitor_agent plugin referring to the data that has not been flushed and is still in memory? I have set the flush interval to 0.1, but why is it still in memory instead of being written to the buffer? What triggers the flushing of chunks to the file buffer? Is it when a chunk reaches the chunk_limit_size or when the chunk has been generated for the duration of the flush interval?
   

5. Does the work of the flush thread include flushing stage chunks to file buffer, and then synchronously reading the chunks into memory and sending them to out_http?

I apologize for the many questions, but I hope to have a deeper understanding and contribute to the community in the future.

[daipom]

Remove queue_limit_length setting since this setting is deprecated.

1. Should I remove the queue_limit_length configuration and use total_limit_size instead? Currently, the logic in the code is that if queue_limit_length is specified, then total_limit_size = queue_limit_length * chunk_limit_size. So, I understand that there is no problem using queue_limit_length currently.

If you understand the code, there is no problem for now.
But I recommend using total_limit_size since this option may not be available in the future.

When Fluentd restarts, it first tries to send all remaining buffers.

2. If I try to send all the data in the buffer during a restart, could this also lead to oom if there are too many buffered data? Is the sending rate slow or will all the data in the buffer be loaded into memory at once?

Certainly, perhaps we should be concerned about that.

Fluentd queues all remaining chunks when it resumes, but only the file descriptor is consumed at that time.
So it will not read all the data into memory.

• https://github.com/fluent/fluentd/blob/v1.14.6/lib/fluent/plugin/buf_file.rb#L139-L186

But Output plugin trys to flush all the queued chunks every flush_thread_interval.
(Note that this is a different setting from flush_interval.
flush_interval is the interval until a chunk is queued.
flush_thread_interval is the interval until a flush-thread flushed the next already queued chunk.)

So if a large amount of buffer remains, some load is expected.
For example, a large flush_thread_count would result in a large load on memory.

3. I also encountered a situation where the flush thread suddenly stopped working. Do you have any ideas on this issue?

Sorry, I have never heard of any other such situation.

Was memory low at this time too?
If so, fixing the memory problem could perhaps fix this as well.

4. Is the buffer_stage_byte_size printed in the monitor_agent plugin referring to the data that has not been flushed

Yes. After queued, the size will be subtracted.

• https://github.com/fluent/fluentd/blob/v1.14.6/lib/fluent/plugin/buffer.rb#L496

and is still in memory?

No. It is in the chunk files, not in memory.
However, the large size of this means that there is a risk of consuming a large amount of memory when flushing.
It could be reduced by keeping the value of flush_thread_count small.

I have set the flush interval to 0.1, but why is it still in memory instead of being written to the buffer?

flush_interval is the interval until a chunk is queued.
After queued, it will be flushed soon by Output plugin, unless there is another already queued chunks waiting flush.

So, this value has little to do with memory consumption.
If this value is too small, it will create a large number of chunks waiting to be flushed, which will be burdensome, so a reasonably large value is recommended.
(So, I recommended flush_interval 10.)

What triggers the flushing of chunks to the file buffer?

The meaning of flush is different.

flush of Fluentd means that Fluentd output the already queued chunks by Output plugins.
(Note: The chunks will be queued when they satisfy some conditions.)

Input plugins read data and write/append it into a suitable chunk file.

Is it when a chunk reaches the chunk_limit_size or when the chunk has been generated for the duration of the flush interval?

Yes.
If a chunk reaches the chunk_limit_size * chunk_full_threshold, then that chunk will be queued and flushed.
If flush_interval has elapsed since the chunk was generated, it will be queued and flushed (if flush_mode is interval).
There may be other conditions. There are many buffer settings.

5. Does the work of the flush thread include flushing stage chunks to file buffer, and then synchronously reading the chunks into memory and sending them to out_http?

The meaning of flush is different. Please see some previous explanations about what flush is.

This area is difficult to explain exactly.
Here is a brief explanation.

Flush-thread flushes every flush_thread_interval.
It has nothing to do with writing data to chunk files.
(Note: Chunk files means buffer files. Each of the files that constitute the buffer is a chunk, so we call it a chunk file too.)

• How flush-thread working: https://github.com/fluent/fluentd/blob/v1.14.6/lib/fluent/plugin/output.rb#L1472-L1534
• How flush working: https://github.com/fluent/fluentd/blob/v1.14.6/lib/fluent/plugin/output.rb#L1142-L1239

Input plugins read data and write/append it into the suitable chunk files.
Enqueue-thread queues the chunks that satify some conditions. (This doesn't use memory at all.)
Flush-thread flushes the alread queued chunks.

These process are done by asynchronously.

I apologize for the many questions, but I hope to have a deeper understanding and contribute to the community in the future.

Great! Fluentd is useful but difficult to use well.
User's contributions are needed to make it easier to use!

For example, just helping anyone in DISCUSSIONS who has the similar memory problems in the future,
or adding any missing information in the documentation, would be a great contribution.

• The documentation repository: https://github.com/fluent/fluentd-docs-gitbook/tree/1.0

We look forward to your contribution.

[zxhdaniel]

Thank you very much for your detailed, patient, and meticulous explanation.This is very encouraging and I will continue to patiently adjust the parameters in order to solve the problem.

[zxhdaniel]

What I want to ask about this image is why the buffer_stage_byte_size shows over 100 MiB, but in my buffer directory, it only seems to have 364K?

[daipom]

Hmm, certainly, this is strange...

total of ls can be different from buffer_stage_byte_size in the following 3 points

• total is the sum of the file block sizes, not data sizes.
• The sizes of .meta files are included in total.
• There may be some already queued files too. (buffer.q... is the queued chunk file.)

However, in this case, these all seem to be unrelated.

It's strange that buffer_stage_byte_size is so much bigger than total.
Looking at that image, I think buffer_stage_byte_size should be about 237KB...

buffer_queue_byte_size is also strange...
Looking at that image, it should be about 53KB...

I'm not sure if the lack of memory has caused it to operate incorrectly...

If you stop Fluentd, and start it after clearing the buffer, and check how buffer_stage_byte_size value and the actual file sizes will change, we might figure out something.

For example, it would be good to know if the values do not match immediately after startup, or if they do not match after some error occurs or after memory runs out.

[zxhdaniel]

It does feel quite strange. My current test has allocated 1GiB of memory to fluentd, which should be sufficient. It seems quite easy to reproduce on my end.

Below is my current buffer configuration.

 <buffer tag>
    @type file
    path /var/log/fluentd/buffer                

    # Buffering Parameters
    chunk_limit_size 2M                         
    queue_limit_length 1024                     
    overflow_action drop_oldest_chunk          
    queued_chunks_limit_size 10

    # Flushing Parameters
    flush_mode interval                         
    flush_thread_count 10                       
    flush_interval 0.1                           
    flush_thread_interval 0.1

    # Retries Parameters
    retry_max_interval 30                       
  </buffer> 

[daipom]

You can use 3 back quotations ``` for code-block.

I am concerned that the log flow rate seems to be too large for in_tail with read_lines_limit 50.

First, these settings are too tight, so try a looser setting

flush_thread_count 10
flush_interval 0.1             
flush_thread_interval 0.1

flush_thread_count 2
flush_interval 10
flush_thread_interval 1

You can check the behavior according to the amount of logs as follows.

<source>
  @type sample
  tag test.fuga
  size 50 # Adjust this to change log flow rate (log/s)
  sample {"message": "test"}
</source>

<match test.**>
  @type null
  <buffer tag>
    @type file
    path /var/log/fluentd/buffer
    flush_at_shutdown false
    chunk_limit_size 2M
    queue_limit_length 1024
    overflow_action drop_oldest_chunk
    queued_chunks_limit_size 10
    flush_mode interval
    flush_thread_count 10
    flush_interval 0.1
    flush_thread_interval 0.1
  </buffer>
</match>

Checking how much memory is consumed in such a setting may help narrow down the cause of the problem.

[zxhdaniel]

Now the problem with oom has been largely resolved by increasing the memory to1GiB. The only remaining issue is that the threads seem to stop running after a while, as indicated in the title.

The following chart shows that this fluentd stopped running after a while without any retries, error logs, or updates to the files in the buffer directory.

no retry, stop flush data when 03.26 05:22

buffer dir stop update when 03.26 05:21

process of fluentd is still running

I don't know much about gdb, but I tried to look at the threads and found that there are some differences compared to normal operation.

threads of abnormality process
It looks like the stack of flush_thread seems abnormal.

cannot see the stack of flush_thread

threds of normality process
It seems that the stack of flush_thread is different.

flush_thread of normality process
It seems that flush_thread is waiting for fd.

I am still at the scene, do you think I can provide any more information to help locate the problem? @daipom

[daipom]

So this is happening even if the memory issue is resolved, right?

Hmm, I have no idea why this is happening...
It looks like all flush threads and Input plugins stop running...
I've never heard of any other phenomenon like this...

I would like to see the Fluentd debug level logs when this phenomenon occurs.

<system>
  log_level debug
</system>

[daipom]

Possibly this is the same phenomenon as

• Why do Fluentd aggregators stop flushing buffers once in a while and refuse to resume flushing after restart? #4068

[zxhdaniel]

Okay, I will continue to pay my attention