problems with slow auditing/journaling after updating to RHEL 6.8
by Jacobson, Robert C. (GSFC-444.0)[HONEYWELL TECHNOLOGY SOLUTIONS INC]
I guess the first question I should ask is : is this the proper list for questions about problems? If not, then please accept my apology -- and I would greatly appreciate if you could direct me to the proper list.
I recently upgraded a system to RHEL 6.8.
kernel: 2.6.32-642.1.1.el6.x86_64
audit: audit-2.4.5-3.el6.x86_64
My users and I immediately noticed a huge drop in application performance -- and when I investigated further, I found a large amount of CPU wait.
Here's a graph from nagios data via splunk, over the past 48 hours. The system was patched ~1300 (right about the middle of each graph -- the first spike), then rebooted at 1715 (the second spike):
http://i.imgur.com/BuyazLH.jpg
Here's some nmon snapshot during a "problem" period:
http://i.imgur.com/YbQjeK2.jpg
(note: all logical volumes on sda5, dm-9 is the logical volume for audit logs)
If I'm interpreting things correctly, it is due to drastic slow-down of journaling on my audit volume. I don't know if this is a problem with the auditing subsystem, or the disk I/O subsystem, or ... what?
Here's an excerpt from iotop, while I run a process that generates perhaps 1000 audit log messages:
Total DISK READ : 0.00 B/s | Total DISK WRITE : 160.53 K/s
Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 586.11 K/s
PID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
1458 be/3 root 0.00 B/s 0.00 B/s 0.00 % 97.23 % [jbd2/dm-9-8]
24354 be/3 root 0.00 B/s 145.59 K/s 0.00 % 0.54 % auditd
The total amount of data generated in the logs is actually very small -- approximately 1 MB -- so I'm puzzled as to why it would take so long to write it out.
The process that generates most of these audit messages takes 1.1 second to run with auditing off (or on a RHEL 6.7 system with auditing on or off).
With auditing running, it takes 32 seconds to run.
## auditing is off:
$ time nice -n 10 /product/bin/fclient.rb -d 3
Logging in /tmp/ferret.log
real 0m1.113s
user 0m0.435s
sys 0m0.643s
## auditing is on:
$ time nice -n 10 /product/bin/fclient.rb -d 3
Logging in /tmp/ferret.log
real 0m32.088s
user 0m0.394s
sys 0m0.686s
I'll note that the ruby version hasn't changed between 6.7 and 6.8 (still ruby-1.8.7.374-4.el6_6.x86_64)
The system is using CFQ for disk I/O. The filesystem is ext4. Disks are all local SATA disks.
I'd appreciate any guidance you have!
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Robert Jacobson Robert.C.Jacobson(a)nasa.gov
Lead System Admin Solar Dynamics Observatory (SDO)
Bldg 14, E222 (301) 286-1591