KASAN overhead?

KASAN overhead?

[Valdis Kletnieks]

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

So I built linux-next next-20160417 with KASAN enabled:

CONFIG_KASAN_SHADOW_OFFSET=0xdffffc0000000000
CONFIG_HAVE_ARCH_KASAN=y        
CONFIG_KASAN=y                  
# CONFIG_KASAN_OUTLINE is not set
CONFIG_KASAN_INLINE=y           
CONFIG_TEST_KASAN=m

and saw an *amazing* slowdown.  For comparison, here is the time taken
to reach various points in the dmesg:

% grep -i free dmesg.0317*
dmesg.0317:[    1.560907] Freeing SMP alternatives memory: 28K (ffffffff93d3e000 - ffffffff93d45000)
dmesg.0317:[   12.041550] Freeing initrd memory: 10432K (ffff88003f5cb000 - ffff88003fffb000)
dmesg.0317:[   16.458451] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
dmesg.0317:[   16.545603] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
dmesg.0317:[   17.818934] Freeing unused kernel memory: 1628K (ffffffff93ba7000 - ffffffff93d3e000)
dmesg.0317:[   17.820234] Freeing unused kernel memory: 1584K (ffff880012c74000 - ffff880012e00000)
dmesg.0317:[   17.828426] Freeing unused kernel memory: 1524K (ffff880013483000 - ffff880013600000)
dmesg.0317-nokasan:[    0.028821] Freeing SMP alternatives memory: 28K (ffffffffaf104000 - ffffffffaf10b000)
dmesg.0317-nokasan:[    1.587232] Freeing initrd memory: 10432K (ffff88003f5cb000 - ffff88003fffb000)
dmesg.0317-nokasan:[    2.433557] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
dmesg.0317-nokasan:[    2.439411] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
dmesg.0317-nokasan:[    2.488113] Freeing unused kernel memory: 1324K (ffffffffaefb9000 - ffffffffaf104000)
dmesg.0317-nokasan:[    2.488518] Freeing unused kernel memory: 88K (ffff88002e9ea000 - ffff88002ea00000)
dmesg.0317-nokasan:[    2.489490] Freeing unused kernel memory: 388K (ffff88002ed9f000 - ffff88002ee00000)

Only config difference was changing to CONFIG_KASAN=n.

Is this level of slowdown expected? Or is my kernel unexpectedly off in the weeds?

[-- Attachment #2: Type: application/pgp-signature, Size: 848 bytes --]

Re: KASAN overhead?

[Alexander Potapenko]

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

On Mar 18, 2016 9:41 PM, "Valdis Kletnieks" <Valdis.Kletnieks@vt.edu> wrote:
>
> So I built linux-next next-20160417 with KASAN enabled:
Is that next-20160317?

> CONFIG_KASAN_SHADOW_OFFSET=0xdffffc0000000000
> CONFIG_HAVE_ARCH_KASAN=y
> CONFIG_KASAN=y
> # CONFIG_KASAN_OUTLINE is not set
> CONFIG_KASAN_INLINE=y
> CONFIG_TEST_KASAN=m
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)?

> and saw an *amazing* slowdown.
Have you tried earlier KASAN versions? Is this a recent regression?

> For comparison, here is the time taken
> to reach various points in the dmesg:
>
> % grep -i free dmesg.0317*
> dmesg.0317:[    1.560907] Freeing SMP alternatives memory: 28K
(ffffffff93d3e000 - ffffffff93d45000)
> dmesg.0317:[   12.041550] Freeing initrd memory: 10432K (ffff88003f5cb000
- ffff88003fffb000)
> dmesg.0317:[   16.458451] ata1.00: ACPI cmd f5/00:00:00:00:00:00
(SECURITY FREEZE LOCK) filtered out
> dmesg.0317:[   16.545603] ata1.00: ACPI cmd f5/00:00:00:00:00:00
(SECURITY FREEZE LOCK) filtered out
> dmesg.0317:[   17.818934] Freeing unused kernel memory: 1628K
(ffffffff93ba7000 - ffffffff93d3e000)
> dmesg.0317:[   17.820234] Freeing unused kernel memory: 1584K
(ffff880012c74000 - ffff880012e00000)
> dmesg.0317:[   17.828426] Freeing unused kernel memory: 1524K
(ffff880013483000 - ffff880013600000)
> dmesg.0317-nokasan:[    0.028821] Freeing SMP alternatives memory: 28K
(ffffffffaf104000 - ffffffffaf10b000)
> dmesg.0317-nokasan:[    1.587232] Freeing initrd memory: 10432K
(ffff88003f5cb000 - ffff88003fffb000)
> dmesg.0317-nokasan:[    2.433557] ata1.00: ACPI cmd f5/00:00:00:00:00:00
(SECURITY FREEZE LOCK) filtered out
> dmesg.0317-nokasan:[    2.439411] ata1.00: ACPI cmd f5/00:00:00:00:00:00
(SECURITY FREEZE LOCK) filtered out
> dmesg.0317-nokasan:[    2.488113] Freeing unused kernel memory: 1324K
(ffffffffaefb9000 - ffffffffaf104000)
> dmesg.0317-nokasan:[    2.488518] Freeing unused kernel memory: 88K
(ffff88002e9ea000 - ffff88002ea00000)
> dmesg.0317-nokasan:[    2.489490] Freeing unused kernel memory: 388K
(ffff88002ed9f000 - ffff88002ee00000)

Was KASAN reporting anything between these lines? Sometimes a recurring
warning slows everything down.

> Only config difference was changing to CONFIG_KASAN=n.
>
> Is this level of slowdown expected? Or is my kernel unexpectedly off in
the weeds?
How did it behave after the startup? Was it still slow?
Which machine were you using? Was it a real device or a VM?

[-- Attachment #2: Type: text/html, Size: 2974 bytes --]

Re: KASAN overhead?

[Valdis.Kletnieks]

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

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?)

> > 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...)

[-- Attachment #2: Type: application/pgp-signature, Size: 848 bytes --]

Re: KASAN overhead?

[Alexander Potapenko]

[-- 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);
}