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?
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 <[email protected]> 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...)
On Sun, Mar 20, 2016 at 2:14 AM, <[email protected]> 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 <[email protected]> 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