audit-userspace icon indicating copy to clipboard operation
audit-userspace copied to clipboard

Performance degradation of ausearch depending from rotation settings

Open mikhailnov opened this issue 2 years ago • 3 comments

Hello!

audit 3.0.8, glibc 2.31.

The first configuration:

localhost ~ # grep -e num_logs -e max_log_file -e max_log_file_action /etc/audit/auditd.conf num_logs = 10 max_log_file = 100 max_log_file_action = ROTATE

There are 100 files of 10 MB, ausearch takes a long time:

localhost ~ # time ausearch -k adjtime real 1m51,008s

If I set 50 * 20 MB or 100 * 10 MB, then ausearch takes about 30 seconds, but the total size of logs is the same.

I tried to understand why this happens, looked into the code and saw nothing special, it seems to just read the files line by line...

Is this a known issue? If yes, I would suggest to document it and recommend optimal log sizes.

mikhailnov avatar May 16 '22 07:05 mikhailnov

This is expected. The extra open/close takes time. Also, ausearch opens files with the memory map flag. That also adds startup/shutdown costs. It is impossible to guess what is optimal for any workload. You may want to optimize for searching. Someone else may want to optimize for the rotation to contain about a days worth of events. It really depends on what your rules are as to how much logging you get. I personally use 100 for the log size.

stevegrubb avatar May 18 '22 12:05 stevegrubb

This is expected. The extra open/close takes time. Also, ausearch opens files with the memory map flag. That also adds startup/shutdown costs.

But then 10 files per 100 MiB would be processed faster than 50 files per 20 MiB and it would make sense, but it is not so...

mikhailnov avatar May 18 '22 23:05 mikhailnov

I don't have a good answer for why it's taking longer. One thing is that it starts with audit.log.1 and check it exists and then increments until it finds the oldest file, then it turns around and starts processing them. I wouldn't think the check for existence would account for all of the extra time. But it is another difference.

stevegrubb avatar May 27 '22 19:05 stevegrubb

Thanks for reporting this. I have no good explanation for this. The perf command might show something in the kernel that is causing the delay. Unless there is a pull request, I won't be able to look into this. Closing this out.

stevegrubb avatar Jul 27 '23 17:07 stevegrubb