Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
References: <0000000000006e8af605ba99c1af@google.com>
In-Reply-To: <0000000000006e8af605ba99c1af@google.com>
From:   Marco Elver <elver@google.com>
Date:   Fri, 5 Feb 2021 18:06:53 +0100
Message-ID: <CANpmjNNX22dDoYK3XgrgCmoEPo5Fv+1dqm=nbYhTJWs7gPSw_A@mail.gmail.com>
Subject: Re: KCSAN: data-race in blk_stat_add / blk_stat_timer_fn (5)
To:     syzbot <syzbot+2b6452167d85a022bc6f@syzkaller.appspotmail.com>
Cc:     Jens Axboe <axboe@kernel.dk>, linux-block@vger.kernel.org,
        LKML <linux-kernel@vger.kernel.org>,
        syzkaller-bugs <syzkaller-bugs@googlegroups.com>,
        Dmitry Vyukov <dvyukov@google.com>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Fri, 5 Feb 2021 at 18:00, syzbot
<syzbot+2b6452167d85a022bc6f@syzkaller.appspotmail.com> wrote:
> Hello,
>
> syzbot found the following issue on:
>
> HEAD commit:    2ab38c17 mailmap: remove the "repo-abbrev" comment
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=130e19b4d00000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=38728258f37833e3
> dashboard link: https://syzkaller.appspot.com/bug?extid=2b6452167d85a022bc6f
> compiler:       clang version 12.0.0 (https://github.com/llvm/llvm-project.git 913f6005669cfb590c99865a90bc51ed0983d09d)
>
> Unfortunately, I don't have any reproducer for this issue yet.
>
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+2b6452167d85a022bc6f@syzkaller.appspotmail.com
>
> ==================================================================
> BUG: KCSAN: data-race in blk_stat_add / blk_stat_timer_fn
>
> write to 0xffffe8ffffd35c80 of 8 bytes by interrupt on cpu 0:
>  blk_rq_stat_init block/blk-stat.c:24 [inline]
>  blk_stat_timer_fn+0x349/0x410 block/blk-stat.c:95
>  call_timer_fn+0x2e/0x240 kernel/time/timer.c:1417
>  expire_timers+0x116/0x260 kernel/time/timer.c:1462
>  __run_timers+0x338/0x3d0 kernel/time/timer.c:1731
>  run_timer_softirq+0x19/0x30 kernel/time/timer.c:1744
>  __do_softirq+0x13c/0x2c3 kernel/softirq.c:343
>  asm_call_irq_on_stack+0xf/0x20
>  __run_on_irqstack arch/x86/include/asm/irq_stack.h:26 [inline]
>  run_on_irqstack_cond arch/x86/include/asm/irq_stack.h:77 [inline]
>  do_softirq_own_stack+0x32/0x40 arch/x86/kernel/irq_64.c:77
>  invoke_softirq kernel/softirq.c:226 [inline]
>  __irq_exit_rcu+0xb4/0xc0 kernel/softirq.c:420
>  sysvec_apic_timer_interrupt+0x74/0x90 arch/x86/kernel/apic/apic.c:1096
>  asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:628
>
> read to 0xffffe8ffffd35c80 of 8 bytes by interrupt on cpu 1:
>  blk_rq_stat_add block/blk-stat.c:46 [inline]
>  blk_stat_add+0x13d/0x230 block/blk-stat.c:74
>  __blk_mq_end_request+0x142/0x230 block/blk-mq.c:546
>  scsi_end_request+0x2a6/0x470 drivers/scsi/scsi_lib.c:604
>  scsi_io_completion+0x104/0xfb0 drivers/scsi/scsi_lib.c:969
>  scsi_finish_command+0x263/0x2b0 drivers/scsi/scsi.c:214
>  scsi_softirq_done+0xdf/0x440 drivers/scsi/scsi_lib.c:1449
>  blk_done_softirq+0x145/0x190 block/blk-mq.c:588
>  __do_softirq+0x13c/0x2c3 kernel/softirq.c:343
>  asm_call_irq_on_stack+0xf/0x20
>  __run_on_irqstack arch/x86/include/asm/irq_stack.h:26 [inline]
>  run_on_irqstack_cond arch/x86/include/asm/irq_stack.h:77 [inline]
>  do_softirq_own_stack+0x32/0x40 arch/x86/kernel/irq_64.c:77
>  invoke_softirq kernel/softirq.c:226 [inline]
>  __irq_exit_rcu+0xb4/0xc0 kernel/softirq.c:420
>  common_interrupt+0xb5/0x130 arch/x86/kernel/irq.c:239
>  asm_common_interrupt+0x1e/0x40 arch/x86/include/asm/idtentry.h:619
>  check_access kernel/kcsan/core.c:633 [inline]
>  __tsan_read1+0x156/0x180 kernel/kcsan/core.c:839
>  tomoyo_get_mode security/tomoyo/util.c:1003 [inline]
>  tomoyo_init_request_info+0xfc/0x160 security/tomoyo/util.c:1031
>  tomoyo_path_perm+0x8b/0x330 security/tomoyo/file.c:815
>  tomoyo_inode_getattr+0x18/0x20 security/tomoyo/tomoyo.c:123
>  security_inode_getattr+0x7f/0xd0 security/security.c:1280
>  vfs_getattr fs/stat.c:121 [inline]
>  vfs_fstat+0x45/0x390 fs/stat.c:146
>  __do_sys_newfstat fs/stat.c:386 [inline]
>  __se_sys_newfstat+0x35/0x240 fs/stat.c:383
>  __x64_sys_newfstat+0x2d/0x40 fs/stat.c:383
>  do_syscall_64+0x39/0x80 arch/x86/entry/common.c:46
>  entry_SYSCALL_64_after_hwframe+0x44/0xa9
>
> Reported by Kernel Concurrency Sanitizer on:
> CPU: 1 PID: 18199 Comm: modprobe Not tainted 5.11.0-rc5-syzkaller #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> ==================================================================

I've been looking at some data races in block/. For this one I was
wondering if there are any requirements for the stats counters? E.g.
do they have to be somewhat consistent, or does it not matter at all?

Because as-is, with concurrent update and aggregation (followed by
reinit) of the per-CPU counters, the values in blk_rq_stat can become
quite inconsistent.

I wanted to throw together a fix for this, but wasn't sure what the
level of tolerable errors for these counters is appropriate. I thought
of 3 options:

1. Just add more data_race() around them and accept whatever
inaccuracies we get due to the data races.

2. Add a per-CPU spinlock. This should be uncontended unless the timer
fires too often.

3. Use per-CPU seqlock. Not sure this buys us much because the timer
also resets the per-CPU counters and has to be serialized with other
potential updaters.

Thanks,
-- Marco