Linux audit performance impact

* Linux audit performance impact
@ 2015-01-28 14:57 Viswanath, Logeswari P (MCOU OSTL)
  2015-01-28 15:16 ` Steve Grubb
  2015-01-28 15:18 ` Satish Chandra Kilaru
  0 siblings, 2 replies; 49+ messages in thread
From: Viswanath, Logeswari P (MCOU OSTL) @ 2015-01-28 14:57 UTC (permalink / raw)
  To: linux-audit

[-- Attachment #1.1: Type: text/plain, Size: 1625 bytes --]

Hi Steve,

I am Logeswari working for HP.

We want to know audit performance impact on RHEL and Suse linux to help us evaluate linux audit as data source for our host based IDS.
When we ran our own performance test with a test audispd plugin, we found if a system can perform 200000 open/close system calls per second without auditing, system can perform only 3000 open/close system calls auditing is enabled for open/close system call which is a HUGE impact on the system performance. It would be great if anyone can help us answering the following questions.

1)      Is this performance impact expected? If yes, what is the reason behind it and can we fix it?

2)      Have anyone done any benchmarking for performance impact? If yes, can you please share the numbers and also the steps/programs used the run the same.

3)      Help us validating the performance test we have done in our test setup using the steps mentioned along with the results attached.

Attached test program (loader.c) to invoke open and close system calls.
Attached idskerndsp is the audispd plugin program.
We used time command to determine how much time the system took to complete 50000 open/close system calls without (results attached Without-auditing) and with auditing enabled on the system (With-auditing-NOLOG-audispd-plugin and With-auditing-RAW)

System details:

1 CPU machine

OS Version
RHEL 6.5

Kernel Version
uname -r
2.6.32-431.el6.x86_64

Note: auditd was occupying 35% of CPU and was sleeping for most of the time whereas kauditd was occupying 20% of the CPU.

Thanks & Regards,
Logeswari.

[-- Attachment #1.2: Type: text/html, Size: 6956 bytes --]

[-- Attachment #2: loader.c --]
[-- Type: text/plain, Size: 4359 bytes --]

#include <stdio.h>
#include <stdlib.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <errno.h>

void create_load(int iters);

int   high_rate = 0;
int   num_iters = 50000;
int   fd1;
char  file1[50];

/* Purpose: To create system load by invoking system calls used by templates.
 *
 * Note: The unlink(2) of a file can be an expensive operation (i.e., event 
 *       rate goes way down).
 * Note: Needs to be run as a non-ids user since IDDS is typically configured
 *       to not audit ids. Some system calls below require you to run as root.
 */

main(int argc, char **argv) {

  int              num_children;
  int              iters;
  int              i;
  char             c;
  struct passwd   *passwd_entry;

  while ((c = getopt(argc, argv, "hi:")) != -1) {
    switch (c) {
    case 'h':
      /*
       * Desire "high" event rate
       */
      high_rate = 1;
      argc--;
      break;
    case 'i':
      /*
       * Desire a specified number of iterations
       */
      num_iters = atoi(optarg);
      argc--;
      break;
    default:
      fprintf(stderr,"Unknown option: %c\n",optarg);
      exit(1);
    }
  }

  if(argv[optind] != NULL) {
    num_children = atoi(argv[optind]);
  } else {
    num_children = 4;
  }
  num_children = 1;

  /* fork child processes, if any requested */
  for(i=1; i < num_children; i++) {
    if(fork() == 0) {

      printf("child pid: %d\n",getpid());

      /* Setup file names based on child's pid */
      //sprintf(file1,"./file1_%d",getpid());

      /* each child creates load */	
      iters=0;
      if (num_iters == -1) {
	while(1) {
	  create_load(iters);
	  iters++;
	  if( (iters % 1000) == 0) {
	    printf("pid %d iteration %d\n",getpid(),iters);
	  }
	}
      } else {
	while(iters < num_iters) {
	  create_load(iters);
	  iters++;
	  if( (iters % 1000) == 0) {
	    printf("pid %d iteration %d\n",getpid(),iters);
	  }
	}
      }
    }
  }

  /* Parent creates load also */
  printf("parent pid: %d\n",getpid());

  /* Setup file names based on parent's pid */
  //sprintf(file1,"./file1_%d",getpid());

  iters=0;
  if (num_iters == -1) {
    while(1) {
      create_load(iters);
      iters++;
      if( (iters % 1000) == 0) {
	printf("pid %d iteration %d\n",getpid(),iters);
      }
    }
  } else {
    while(iters < num_iters) {
      create_load(iters);
      iters++;
      if( (iters % 1000) == 0) {
	printf("pid %d iteration %d\n",getpid(),iters);
      }
    }
  }

} /* main */

void create_load(int iters) {

  int pid;
  char *args[2];
  struct stat stat_buf;

  fd1 = open("file1", O_RDWR, 0777);
  if (fd1 == -1) {
    fprintf(stderr,"pid %d: open() returned error, errno=%d(%s)\n",
	    getpid(),errno,strerror(errno));
    exit(1);
  }

  if (close(fd1) == -1) {
      fprintf(stderr,"pid %d: close() returned error, errno=%d(%s)\n",
	      getpid(),errno,strerror(errno));
      exit(1);
  }

  /*if (chown("file1",0,0) == -1) {
   fprintf(stderr,"pid %d: chown(%d,%d) returned error, errno=%d(%s)\n",
           getpid(),0,0,errno,strerror(errno));
    exit(1);
  }

  pid = fork();
  if(pid == 0) {
      fprintf(stderr,"child pid %d: fork!\n",getpid());
      args[0] = "/bin/ls";
      args[1] = NULL;
      close(1);
      close(2);
      execve(args[0], args, NULL);
      fprintf(stderr,"pid %d: execve(%s) returned error, errno=%d(%s)\n",
              getpid(),args[0],errno,strerror(errno));
      _exit(1);
    } else if (pid < 0) {
      fprintf(stderr,"pid %d: fork() returned error, errno=%d(%s)\n",
              getpid(),errno,strerror(errno));
      exit(1);
    } else {
      fprintf(stderr,"parent pid %d, child pid: %d: fork!\n",getpid(),pid);
    }

    pid = vfork();
    if(pid == 0) {
      args[0] = "/bin/pwd";
      args[1] = NULL;
      close(1);
      close(2);
      execv(args[0], args);
      fprintf(stderr,"pid %d: execve(%s) returned error, errno=%d(%s)\n",
              getpid(),args[0],errno,strerror(errno));
      _exit(1);
    } else if (pid < 0) {
      fprintf(stderr,"pid %d: vfork() returned error, errno=%d(%s)\n",
              getpid(),errno,strerror(errno));
      exit(1);
  }*/

  return;
} /* create_load() */

[-- Attachment #3: idskerndsp.c --]
[-- Type: text/plain, Size: 1513 bytes --]

#include <stdio.h>
#include <stdlib.h>
#include <signal.h>
#include <syslog.h>
#include <string.h>
#include <ctype.h>
#include <pwd.h>
#include <sys/stat.h>
#include <sys/select.h>
#include <errno.h>
#include "libaudit.h"
#include "auparse.h"

/* Global Data */
static auparse_state_t *au = NULL;

/* Local declarations */
static void handle_event(auparse_state_t *au,
		auparse_cb_event_t cb_event_type, void *user_data);

int main(int argc, char *argv[])
{
	char tmp[MAX_AUDIT_MESSAGE_LENGTH+1];

	/* Initialize the auparse library */
	au = auparse_init(AUSOURCE_FEED, 0);
	if (au == NULL) {
		return -1;
	}
	auparse_add_callback(au, handle_event, NULL, NULL);

	do {
		fd_set read_mask;
		struct timeval tv;
		int retval;

		do {
			tv.tv_sec = 5;
			tv.tv_usec = 0;
			FD_ZERO(&read_mask);
			FD_SET(0, &read_mask);
			retval= select(1, &read_mask, NULL, NULL, &tv);
                } while (retval == -1 && errno == EINTR);

		/* Now the event loop */
		if (retval > 0) {
			if (fgets_unlocked(tmp, MAX_AUDIT_MESSAGE_LENGTH,
				stdin)){
				auparse_feed(au, tmp, strnlen(tmp,
						MAX_AUDIT_MESSAGE_LENGTH));
			}
		} else if (retval == 0)
			auparse_flush_feed(au);
		if (feof(stdin))
			break;
	} while (1);

	/* Flush any accumulated events from queue */
	auparse_flush_feed(au);

	auparse_destroy(au);
	return 0;
}

static void handle_event(auparse_state_t *au,
		auparse_cb_event_t cb_event_type, void *user_data)
{
	return;
}

[-- Attachment #4: Without-auditing.txt --]
[-- Type: text/plain, Size: 219 bytes --]

Audit Status
# auditctl -s
AUDIT_STATUS: enabled=0 flag=1 pid=20358 rate_limit=0 backlog_limit=320 lost=0 backlog=0

Without auditing enabled, time taken is 

real    0m0.252s
user    0m0.018s
sys     0m0.215s

[-- Attachment #5: With-auditing-NOLOG-audispd-plugin.txt --]
[-- Type: text/plain, Size: 520 bytes --]

audispd-plugin configuration

# cat /etc/audisp/plugins.d/idskerndsp.conf

active = yes
direction = out
path = /ux/ids/idskerndsp
type = always
args = --test
format = string

Rules Configured

# auditctl -l
LIST_RULES: exit,always syscall=open,close

Audit Status

# auditctl -s
AUDIT_STATUS: enabled=1 flag=1 pid=20358 rate_limit=0 backlog_limit=320 lost=0 backlog=0

With log_format = NOLOG, above rule enabled for auditing, time taken is

real    0m16.849s
user    0m0.045s
sys     0m3.838s

[-- Attachment #6: With-auditing-RAW.txt --]
[-- Type: text/plain, Size: 629 bytes --]

We tried to disable the plugin i.e. idskerndsp and restarted auditd process to log the audit events to disk.

audispd-plugin configuration

# cat /etc/audisp/plugins.d/idskerndsp.conf

active = no
direction = out
path = /ux/ids/idskerndsp
type = always
args = --test
format = string

Rules Configured

# auditctl -l
LIST_RULES: exit,always syscall=open,close

Audit Status

# auditctl -s
AUDIT_STATUS: enabled=1 flag=1 pid=20819 rate_limit=0 backlog_limit=320 lost=0 backlog=0

With log_format = RAW, above rule enabled for auditing, time taken is

real    2m41.484s
user    0m0.028s
sys     0m8.789s

[-- Attachment #7: Type: text/plain, Size: 0 bytes --]

^ permalink raw reply	[flat|nested] 49+ messages in thread