Re: KASAN overhead?

[Alexander Potapenko <glider@google.com>]

[-- Attachment #1: Type: text/plain, Size: 2640 bytes --]

On Sun, Mar 20, 2016 at 2:14 AM,  <Valdis.Kletnieks@vt.edu> wrote:
> On Sat, 19 Mar 2016 13:13:59 +0100, Alexander Potapenko said:
>
>> Which GCC version were you using? Are you sure it didn't accidentally
>> enable the outline instrumentation (e.g. if the compiler is too old)?
>
>  gcc --version
> gcc (GCC) 6.0.0 20160311 (Red Hat 6.0.0-0.16)
>
> * Fri Mar 11 2016 Jakub Jelinek <jakub@redhat.com> 6.0.0-0.15
> - update from the trunk
>
> Doesn't get much newer than that.. :) (Hmm.. possibly *too* new?)
Fine,this one should be new enough.
>> > and saw an *amazing* slowdown.
>> Have you tried earlier KASAN versions? Is this a recent regression?
>
> First time I'd tried it, so no comparison point..
>
>> Was KASAN reporting anything between these lines? Sometimes a recurring
>> warning slows everything down.
>
> Nope, it didn't report a single thing.
>
>> How did it behave after the startup? Was it still slow?
>
> After seeing how long it took to get to a single-user prompt, I didn't
> investigate further. It took 126 seconds to get here:
>
> [  126.937247] audit: type=1327 audit(1458268293.617:100): proctitle="/usr/sbin/sulogin"
>
> compared to the more usual:
>
> [   29.249260] audit: type=1327 audit(1458326938.276:100): proctitle="/usr/sbin/sulogin"
>
> (In both cases, there's a 10-12 second pause for entering a LUKS
> passphrase, so we're looking at about 110 seconds with KASAN versus
> about 17-18 without.)
>
>> Which machine were you using? Was it a real device or a VM?
>
> Running native on a Dell Latitude laptop....
>
> (Based on the fact that you're asking questions rather than just saying
> it's expected behavior, I'm guessing I've once again managed to find
> a corner case of some sort.  I'm more than happy to troubleshoot, if
> you can provide hints of what to try...)

On my machine the kernel startup times with and without KASAN are
mostly similar (8.4 vs. 6.2 seconds), but I don't think the startup
times actually reflect anything.
First, they depend heavily on the kernel configuration, and second,
the percentage of time spent in the kernel during startup is greater
than that during normal operation.
With the attached benchmark (which is far from being ideal, but may
give some idea about the slowdown) I'm seeing the slowdown factor of
around 2.5x, which is more realistic.


-- 
Alexander Potapenko
Software Engineer

Google Germany GmbH
Erika-Mann-Straße, 33
80636 München

Geschäftsführer: Matthew Scott Sucherman, Paul Terence Manicle
Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg

[-- Attachment #2: bench_pipes.c --]
[-- Type: text/x-csrc, Size: 1556 bytes --]

#include <unistd.h>
#include <sys/types.h>
#include <stdlib.h>
#include <stdio.h>
#include <errno.h>
#include <pthread.h>


static int npipes = 1;
static int niters = 1;


void *do_pipes(void* unused);

int main(int argc, char **argv) {
	int nthreads = 1;
	pthread_t *threads;
	pthread_attr_t attr;
	int rc = 0;
	int i;
	if (argc < 2) {
		printf("Usage: %s <npipes> <niters> <nthreads>\n", argv[0]);
		return 1;
	}
	npipes = atoi(argv[1]);
	if (argc >= 3) 
		niters = atoi(argv[2]);
	if (argc >= 4)
		nthreads = atoi(argv[3]);
	
	pthread_attr_init(&attr);
	pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_JOINABLE);
	threads = malloc(sizeof(pthread_t) * nthreads);
	for (i = 0; i < nthreads; i++) {
		rc = pthread_create(&threads[i], &attr, &do_pipes, NULL);
		if (rc) {
			printf("Couldn't start thread. error %d\n", rc);
			return -1;	
		}
	}
	pthread_attr_destroy(&attr);
	for (i = 0; i < nthreads; i++) {
		rc = pthread_join(threads[i], NULL);
		if (rc) {
			printf("Couldn't join thread. error %d\n", rc);
			return -1;	
		}
	}
	free(threads);
	pthread_exit(NULL);
}

void *do_pipes(void* unused) {
	int* pipes;
	int i,j;
	char c = 'a';
	pipes = malloc(sizeof(int) * npipes * 2);
	for (j = 0; j < niters; ++j) {
		for (i = 0; i < npipes; ++i) {
			if (pipe(&pipes[i * 2])) {
				perror("Couldn't open pipe");
				free(pipes);
				exit(-1);
			}
		//	write(pipes[i * 2 + 1], &c, 1);
		}
		for (i = 0; i < npipes; ++i) {
		//	read(pipes[i * 2], &c, 1);
			close(pipes[i * 2]);
			close(pipes[i * 2 + 1]);
		}
	}
	free(pipes);
	pthread_exit(unused);
}