Re: [PATCH v3 4/4] test-lib: add "fast_unwind_on_malloc=0" to LSAN_OPTIONS

["Ævar Arnfjörð Bjarmason" <avarab@gmail.com>]

On Mon, Feb 21 2022, Taylor Blau wrote:

> On Mon, Feb 21, 2022 at 04:58:35PM +0100, Ævar Arnfjörð Bjarmason wrote:
>> Add "fast_unwind_on_malloc=0" to LSAN_OPTIONS to get more meaningful
>> stack traces from LSAN. This isn't required under ASAN which will emit
>> traces such as this one for a leak in "t/t0006-date.sh":
>>
>>     $ ASAN_OPTIONS=detect_leaks=1 ./t0006-date.sh -vixd
>>     [...]
>>     Direct leak of 3 byte(s) in 1 object(s) allocated from:
>>         #0 0x488b94 in strdup (t/helper/test-tool+0x488b94)
>>         #1 0x9444a4 in xstrdup wrapper.c:29:14
>>         #2 0x5995fa in parse_date_format date.c:991:24
>>         #3 0x4d2056 in show_dates t/helper/test-date.c:39:2
>>         #4 0x4d174a in cmd__date t/helper/test-date.c:116:3
>>         #5 0x4cce89 in cmd_main t/helper/test-tool.c:127:11
>>         #6 0x4cd1e3 in main common-main.c:52:11
>>         #7 0x7fef3c695e49 in __libc_start_main csu/../csu/libc-start.c:314:16
>>         #8 0x422b09 in _start (t/helper/test-tool+0x422b09)
>>
>>     SUMMARY: AddressSanitizer: 3 byte(s) leaked in 1 allocation(s).
>>     Aborted
>>
>> Whereas LSAN would emit this instead:
>>
>>     $ ./t0006-date.sh -vixd
>>     [...]
>>     Direct leak of 3 byte(s) in 1 object(s) allocated from:
>>         #0 0x4323b8 in malloc (t/helper/test-tool+0x4323b8)
>>         #1 0x7f2be1d614aa in strdup string/strdup.c:42:15
>>
>>     SUMMARY: LeakSanitizer: 3 byte(s) leaked in 1 allocation(s).
>>     Aborted
>>
>> Now we'll instead git this sensible stack trace under
>> LSAN. I.e. almost the same one (but starting with "malloc", as is
>> usual for LSAN) as under ASAN:
>>
>>     Direct leak of 3 byte(s) in 1 object(s) allocated from:
>>         #0 0x4323b8 in malloc (t/helper/test-tool+0x4323b8)
>>         #1 0x7f012af5c4aa in strdup string/strdup.c:42:15
>>         #2 0x5cb164 in xstrdup wrapper.c:29:14
>>         #3 0x495ee9 in parse_date_format date.c:991:24
>>         #4 0x453aac in show_dates t/helper/test-date.c:39:2
>>         #5 0x453782 in cmd__date t/helper/test-date.c:116:3
>>         #6 0x451d95 in cmd_main t/helper/test-tool.c:127:11
>>         #7 0x451f1e in main common-main.c:52:11
>>         #8 0x7f012aef5e49 in __libc_start_main csu/../csu/libc-start.c:314:16
>>         #9 0x42e0a9 in _start (t/helper/test-tool+0x42e0a9)
>>
>>     SUMMARY: LeakSanitizer: 3 byte(s) leaked in 1 allocation(s).
>>     Aborted
>
> This is great, by the way. I have often hit that bug in LSan and been
> incredibly frustrated by it. I'm happy to see it getting fixed here,
> thank you.

Cheers!

>> As the option name suggests this does make things slower, e.g. for
>> t0001-init.sh we're around 10% slower:
>>
>>     $ hyperfine -L v 0,1 'LSAN_OPTIONS=fast_unwind_on_malloc={v} make T=t0001-init.sh' -r 3
>>     Benchmark 1: LSAN_OPTIONS=fast_unwind_on_malloc=0 make T=t0001-init.sh
>>       Time (mean ± σ):      2.135 s ±  0.015 s    [User: 1.951 s, System: 0.554 s]
>>       Range (min … max):    2.122 s …  2.152 s    3 runs
>>
>>     Benchmark 2: LSAN_OPTIONS=fast_unwind_on_malloc=1 make T=t0001-init.sh
>>       Time (mean ± σ):      1.981 s ±  0.055 s    [User: 1.769 s, System: 0.488 s]
>>       Range (min … max):    1.941 s …  2.044 s    3 runs
>>
>>     Summary
>>       'LSAN_OPTIONS=fast_unwind_on_malloc=1 make T=t0001-init.sh' ran
>>         1.08 ± 0.03 times faster than 'LSAN_OPTIONS=fast_unwind_on_malloc=0 make T=t0001-init.sh'
>>
>> I think that's more than worth it to get the more meaningful stack
>> traces, we can always provide LSAN_OPTIONS=fast_unwind_on_malloc=0 for
>> one-off "fast" runs.
>
> I completely agree. I am almost always run ASan / LSan tests a single
> script at a time (often focusing on just one script that I know
> demonstrates some bug).
>
> At GitHub, we use both a sanitized and un-sanitized build when running
> CI. So we'll probably feel the effects a little more during the "run
> make test under a sanitized build" CI job, but we could easily set
> fast_unwind_on_malloc=0 if it becomes too big of a problem for us
> (though I suspect it won't matter in practice).

I suspect you mean SANITIZE=address not SANITIZE=leak, i.e. ASAN not
LSAN. Note that the performance of the two is often quite different
(with ASAN starting out much slower).

I almost never use ASAN, but I've been using LSAN a lot.

I also haven't been able to have ASAN spew out these worse stack traces,
as noted in the commit message. But in some brief testing now if I were
setting fast_unwind_on_malloc=0 it would be around 15% slower:
    
    $ hyperfine -L v 0,1 'ASAN_OPTIONS=fast_unwind_on_malloc={v} make T=t0001-init.sh' -r 5
    Benchmark 1: ASAN_OPTIONS=fast_unwind_on_malloc=0 make T=t0001-init.sh
      Time (mean ± σ):      3.264 s ±  0.014 s    [User: 2.456 s, System: 0.927 s]
      Range (min … max):    3.249 s …  3.282 s    5 runs
     
    Benchmark 2: ASAN_OPTIONS=fast_unwind_on_malloc=1 make T=t0001-init.sh
      Time (mean ± σ):      2.826 s ±  0.023 s    [User: 2.008 s, System: 0.936 s]
      Range (min … max):    2.814 s …  2.866 s    5 runs
     
    Summary
      'ASAN_OPTIONS=fast_unwind_on_malloc=1 make T=t0001-init.sh' ran
        1.15 ± 0.01 times faster than 'ASAN_OPTIONS=fast_unwind_on_malloc=0 make T=t0001-init.sh'

But I don't know in the ASAN case what, if anything, you're getting for
that reduction in performance.