search

google / kernel-sanitizers

Linux Kernel Sanitizers, fast bug-detectors for the Linux kernel
https://google.github.io/kernel-sanitizers/
442 stars 87 forks source link

False positive in blk_complete_request #205

Open dvyukov opened 9 years ago

dvyukov commented 9 years ago

Here are two reports on commit c58422d251bc

ThreadSanitizer: data-race in kmem_cache_free

Write at 0xffff880485d5fdd0 of size 8 by thread 1206 on CPU 0:
 [<     inline     >] __cache_free mm/slab.c:3384
 [<ffffffff812451e2>] kmem_cache_free+0x92/0x480 mm/slab.c:3562
 [<ffffffff8150c440>] free_request_struct+0x30/0x40 block/blk-core.c:597
 [<ffffffff811d04a5>] mempool_free+0x75/0x130 mm/mempool.c:439
 [<     inline     >] blk_free_request block/blk-core.c:832
 [<ffffffff8150d5bb>] __blk_put_request+0x11b/0x200 block/blk-core.c:1424
 [<ffffffff8150d71d>] blk_put_request+0x7d/0xb0 block/blk-core.c:1441
 [<ffffffff818991cf>] scsi_execute+0x9f/0x2a0 drivers/scsi/scsi_lib.c:259
 [<ffffffff818baece>] sr_do_ioctl+0x11e/0x360 drivers/scsi/sr_ioctl.c:209
 [<ffffffff818b94c6>] sr_packet+0x56/0xc0 drivers/scsi/sr.c:949
 [<ffffffff81988a18>] cdrom_get_media_event+0xa8/0x130 drivers/cdrom/cdrom.c:673
 [<ffffffff818bba77>] sr_drive_status+0x97/0x1d0 drivers/scsi/sr_ioctl.c:312
 [<     inline     >] cdrom_ioctl_drive_status drivers/cdrom/cdrom.c:2530
 [<ffffffff8198f53e>] cdrom_ioctl+0xdde/0x11f0 drivers/cdrom/cdrom.c:3348
 [<ffffffff818b9eb6>] sr_block_ioctl+0xa6/0xf0 drivers/scsi/sr.c:568
 [<     inline     >] __blkdev_driver_ioctl block/ioctl.c:267
 [<ffffffff8152c69a>] blkdev_ioctl+0x22a/0xa10 block/ioctl.c:453
 [<ffffffff812bed52>] block_ioctl+0x82/0xa0 fs/block_dev.c:1593
 [<     inline     >] vfs_ioctl fs/ioctl.c:43
 [<ffffffff8127ffd9>] do_vfs_ioctl+0x449/0x750 fs/ioctl.c:607
 [<     inline     >] SYSC_ioctl fs/ioctl.c:622
 [<ffffffff81280359>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
 [<ffffffff81ee3e11>] entry_SYSCALL_64_fastpath+0x31/0x95 arch/x86/entry/entry_64.S:188

Previous read at 0xffff880485d5fdd0 of size 1 by thread 850 on CPU 0:
 [<     inline     >] test_and_set_bit ./arch/x86/include/asm/bitops.h:231
 [<     inline     >] blk_mark_rq_complete block/blk.h:102
 [<ffffffff815200a5>] blk_complete_request+0x25/0x40 block/blk-softirq.c:170
 [<ffffffff8189cb63>] scsi_done+0x43/0xb0 drivers/scsi/scsi_lib.c:1749
 [<ffffffff818d8b24>] atapi_qc_complete+0xd4/0x6d0 drivers/ata/libata-scsi.c:2738
 [<ffffffff818ca835>] __ata_qc_complete+0x155/0x2d0 drivers/ata/libata-core.c:4851
 [<ffffffff818cab09>] ata_qc_complete+0x159/0x5c0 drivers/ata/libata-core.c:4921
 [<ffffffff818eb34d>] ata_hsm_qc_complete+0x7d/0x1d0 drivers/ata/libata-sff.c:1021
 [<ffffffff818ec35d>] ata_sff_hsm_move+0x10d/0xcc0 drivers/ata/libata-sff.c:1293
 [<ffffffff818ed02b>] __ata_sff_port_intr+0x11b/0x210 drivers/ata/libata-sff.c:1581
 [<ffffffff818ed5a2>] ata_bmdma_port_intr+0x52/0x1f0 drivers/ata/libata-sff.c:2874
 [<     inline     >] __ata_sff_interrupt drivers/ata/libata-sff.c:1626
 [<ffffffff818ed898>] ata_bmdma_interrupt+0x158/0x2e0 drivers/ata/libata-sff.c:2899
 [<ffffffff810f7082>] handle_irq_event_percpu+0x62/0x2b0 kernel/irq/handle.c:143
 [<ffffffff810f736b>] handle_irq_event+0x9b/0xd0 kernel/irq/handle.c:192
 [<ffffffff810fc01f>] handle_edge_irq+0x11f/0x370 kernel/irq/chip.c:608
 [<     inline     >] generic_handle_irq_desc include/linux/irqdesc.h:146
 [<ffffffff8100a15f>] handle_irq+0x9f/0x230 arch/x86/kernel/irq_64.c:81
 [<ffffffff8100946a>] do_IRQ+0x8a/0x170 arch/x86/kernel/irq.c:223
 [<ffffffff81ee494a>] common_interrupt+0x8a/0x8f arch/x86/entry/entry_64.S:609
 [<ffffffff81ee494a>] common_interrupt+0x8a/0x8f arch/x86/entry/entry_64.S:609

ThreadSanitizer: data-race in kmem_cache_free

Write at 0xffff880485d5fe00 of size 8 by thread 1206 on CPU 0:
 [<     inline     >] __cache_free mm/slab.c:3384
 [<ffffffff812451e2>] kmem_cache_free+0x92/0x480 mm/slab.c:3562
 [<ffffffff8150c440>] free_request_struct+0x30/0x40 block/blk-core.c:597
 [<ffffffff811d04a5>] mempool_free+0x75/0x130 mm/mempool.c:439
 [<     inline     >] blk_free_request block/blk-core.c:832
 [<ffffffff8150d5bb>] __blk_put_request+0x11b/0x200 block/blk-core.c:1424
 [<ffffffff8150d71d>] blk_put_request+0x7d/0xb0 block/blk-core.c:1441
 [<ffffffff818991cf>] scsi_execute+0x9f/0x2a0 drivers/scsi/scsi_lib.c:259
 [<ffffffff818baece>] sr_do_ioctl+0x11e/0x360 drivers/scsi/sr_ioctl.c:209
 [<ffffffff818b94c6>] sr_packet+0x56/0xc0 drivers/scsi/sr.c:949
 [<ffffffff81988a18>] cdrom_get_media_event+0xa8/0x130 drivers/cdrom/cdrom.c:673
 [<ffffffff818bba77>] sr_drive_status+0x97/0x1d0 drivers/scsi/sr_ioctl.c:312
 [<     inline     >] cdrom_ioctl_drive_status drivers/cdrom/cdrom.c:2530
 [<ffffffff8198f53e>] cdrom_ioctl+0xdde/0x11f0 drivers/cdrom/cdrom.c:3348
 [<ffffffff818b9eb6>] sr_block_ioctl+0xa6/0xf0 drivers/scsi/sr.c:568
 [<     inline     >] __blkdev_driver_ioctl block/ioctl.c:267
 [<ffffffff8152c69a>] blkdev_ioctl+0x22a/0xa10 block/ioctl.c:453
 [<ffffffff812bed52>] block_ioctl+0x82/0xa0 fs/block_dev.c:1593
 [<     inline     >] vfs_ioctl fs/ioctl.c:43
 [<ffffffff8127ffd9>] do_vfs_ioctl+0x449/0x750 fs/ioctl.c:607
 [<     inline     >] SYSC_ioctl fs/ioctl.c:622
 [<ffffffff81280359>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
 [<ffffffff81ee3e11>] entry_SYSCALL_64_fastpath+0x31/0x95 arch/x86/entry/entry_64.S:188

Previous write at 0xffff880485d5fe00 of size 8 by thread 850 on CPU 0:
 [<     inline     >] __list_add include/linux/list.h:44
 [<     inline     >] list_add_tail include/linux/list.h:77
 [<ffffffff8151ffcc>] __blk_complete_request+0x11c/0x1d0 block/blk-softirq.c:139
 [<ffffffff815200b1>] blk_complete_request+0x31/0x40 block/blk-softirq.c:171
 [<ffffffff8189cb63>] scsi_done+0x43/0xb0 drivers/scsi/scsi_lib.c:1749
 [<ffffffff818d8b24>] atapi_qc_complete+0xd4/0x6d0 drivers/ata/libata-scsi.c:2738
 [<ffffffff818ca835>] __ata_qc_complete+0x155/0x2d0 drivers/ata/libata-core.c:4851
 [<ffffffff818cab09>] ata_qc_complete+0x159/0x5c0 drivers/ata/libata-core.c:4921
 [<ffffffff818eb34d>] ata_hsm_qc_complete+0x7d/0x1d0 drivers/ata/libata-sff.c:1021
 [<ffffffff818ec35d>] ata_sff_hsm_move+0x10d/0xcc0 drivers/ata/libata-sff.c:1293
 [<ffffffff818ed02b>] __ata_sff_port_intr+0x11b/0x210 drivers/ata/libata-sff.c:1581
 [<ffffffff818ed5a2>] ata_bmdma_port_intr+0x52/0x1f0 drivers/ata/libata-sff.c:2874
 [<     inline     >] __ata_sff_interrupt drivers/ata/libata-sff.c:1626
 [<ffffffff818ed898>] ata_bmdma_interrupt+0x158/0x2e0 drivers/ata/libata-sff.c:2899
 [<ffffffff810f7082>] handle_irq_event_percpu+0x62/0x2b0 kernel/irq/handle.c:143
 [<ffffffff810f736b>] handle_irq_event+0x9b/0xd0 kernel/irq/handle.c:192
 [<ffffffff810fc01f>] handle_edge_irq+0x11f/0x370 kernel/irq/chip.c:608
 [<     inline     >] generic_handle_irq_desc include/linux/irqdesc.h:146
 [<ffffffff8100a15f>] handle_irq+0x9f/0x230 arch/x86/kernel/irq_64.c:81
 [<ffffffff8100946a>] do_IRQ+0x8a/0x170 arch/x86/kernel/irq.c:223
 [<ffffffff81ee494a>] common_interrupt+0x8a/0x8f arch/x86/entry/entry_64.S:609
 [<ffffffff81ee494a>] common_interrupt+0x8a/0x8f arch/x86/entry/entry_64.S:609

__blk_complete_request queues softirq that unblocks scsi_execute/blk_execute_rq on a completion. KTSAN misses that synchronization for some reason.

dvyukov commented 9 years ago

Here are reports with similar stacks. However, the stacks are reversed, so it can be missed synchronization "via a decide'. FTR, the csd is issued in __blk_complete_request.

ThreadSanitizer: data-race in llist_reverse_order

Read at 0xffff88047e91a178 of size 8 by thread 3006 on CPU 6:
 [<ffffffff8156abbe>] llist_reverse_order+0x2e/0x60 lib/llist.c:97
 [<ffffffff81133e0d>] flush_smp_call_function_queue+0x5d/0x1c0 kernel/smp.c:223 (discriminator 3)
 [<ffffffff81134c57>] generic_smp_call_function_single_interrupt+0x17/0x80 kernel/smp.c:195
 [<     inline     >] __smp_call_function_single_interrupt arch/x86/kernel/smp.c:309
 [<ffffffff8105a4c8>] smp_trace_call_function_single_interrupt+0x58/0x160 arch/x86/kernel/smp.c:324
 [<ffffffff81ee54ea>] trace_call_function_single_interrupt+0x8a/0xa0 arch/x86/entry/entry_64.S:811

Previous write at 0xffff88047e91a178 of size 8 by thread 57 on CPU 6:
 [<ffffffff8154527f>] cfq_insert_request+0xef/0xc70 block/cfq-iosched.c:4018
 [<ffffffff81509ab3>] __elv_add_request+0x293/0x4e0 block/elevator.c:659
 [<ffffffff81516387>] blk_flush_plug_list+0x3a7/0x420 block/blk-core.c:3204
 [<     inline     >] blk_schedule_flush_plug include/linux/blkdev.h:1077
 [<     inline     >] sched_submit_work kernel/sched/core.c:3096
 [<ffffffff81eddadf>] schedule+0x5f/0x80 kernel/sched/core.c:3103
 [<     inline     >] add_transaction_credits fs/jbd2/transaction.c:207
 [<ffffffff813b5eba>] start_this_handle+0x40a/0xa20 fs/jbd2/transaction.c:339
 [<ffffffff813b666d>] jbd2__journal_start+0x19d/0x330 fs/jbd2/transaction.c:440
 [<ffffffff8138ddca>] __ext4_journal_start_sb+0x9a/0x180 fs/ext4/ext4_jbd2.c:76
 [<     inline     >] __ext4_journal_start fs/ext4/ext4_jbd2.h:312
 [<ffffffff8133ff4b>] ext4_writepages+0x5eb/0x15e0 fs/ext4/inode.c:2492
 [<ffffffff811e0453>] do_writepages+0x53/0x80 mm/page-writeback.c:2332
 [<ffffffff812aac2f>] __writeback_single_inode+0x7f/0x510 fs/fs-writeback.c:1259 (discriminator 3)
 [<ffffffff812ab5b8>] writeback_sb_inodes+0x4f8/0x720 fs/fs-writeback.c:1516
 [<ffffffff812ab8a4>] __writeback_inodes_wb+0xc4/0x100 fs/fs-writeback.c:1562
 [<ffffffff812abc8c>] wb_writeback+0x3ac/0x440 fs/fs-writeback.c:1666
 [<     inline     >] wb_do_writeback fs/fs-writeback.c:1801
 [<ffffffff812ac7b4>] wb_workfn+0x214/0x7e0 fs/fs-writeback.c:1852
 [<ffffffff810b1d6e>] process_one_work+0x47e/0x930 kernel/workqueue.c:2036
 [<ffffffff810b22d0>] worker_thread+0xb0/0x900 kernel/workqueue.c:2170
 [<ffffffff810bba40>] kthread+0x150/0x170 kernel/kthread.c:209
 [<ffffffff81ee420f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:529

ThreadSanitizer: data-race in llist_reverse_order

Write at 0xffff88047e000758 of size 8 by thread 763 on CPU 8:
 [<ffffffff8156abc9>] llist_reverse_order+0x39/0x60 lib/llist.c:98
 [<ffffffff81133e0d>] flush_smp_call_function_queue+0x5d/0x1c0 kernel/smp.c:223 (discriminator 3)
 [<ffffffff81134c57>] generic_smp_call_function_single_interrupt+0x17/0x80 kernel/smp.c:195
 [<     inline     >] __smp_call_function_single_interrupt arch/x86/kernel/smp.c:309
 [<ffffffff8105a4c8>] smp_trace_call_function_single_interrupt+0x58/0x160 arch/x86/kernel/smp.c:324
 [<ffffffff81ee54ea>] trace_call_function_single_interrupt+0x8a/0xa0 arch/x86/entry/entry_64.S:811

Previous read at 0xffff88047e000758 of size 8 by thread 2823 on CPU 0:
 [<     inline     >] cfq_check_fifo block/cfq-iosched.c:2895
 [<     inline     >] cfq_dispatch_request block/cfq-iosched.c:3369
 [<ffffffff8154321e>] cfq_dispatch_requests+0x58e/0x1550 block/cfq-iosched.c:3410
 [<     inline     >] __elv_next_request block/blk.h:149
 [<ffffffff81515916>] blk_peek_request+0xc6/0x4f0 block/blk-core.c:2284
 [<ffffffff8189df8b>] scsi_request_fn+0x6b/0xb20 drivers/scsi/scsi_lib.c:1784
 [<     inline     >] __blk_run_queue_uncond block/blk-core.c:310
 [<ffffffff8150c06f>] __blk_run_queue+0x6f/0xa0 block/blk-core.c:328
 [<ffffffff8150c0df>] blk_run_queue+0x3f/0x70 block/blk-core.c:360
 [<ffffffff81899a9a>] scsi_run_queue+0x51a/0x5f0 drivers/scsi/scsi_lib.c:497
 [<ffffffff8189b09b>] scsi_end_request+0x1db/0x300 drivers/scsi/scsi_lib.c:735
 [<ffffffff8189ec57>] scsi_io_completion+0x137/0x8f0 drivers/scsi/scsi_lib.c:914
 [<ffffffff818911be>] scsi_finish_command+0x15e/0x1f0 drivers/scsi/scsi.c:607
 [<ffffffff8[89ded2>] scsi_softirq_done+0x182/0x1d0
 [<ffffffff8151fc86>] blk_done_softirq+0x136/0x160 block/blk-softirq.c:35
 [<ffffffff81091c1e>] __do_softirq+0xbe/0x2f0 kernel/softirq.c:273
 [<ffffffff81ee4d6a>] trace_apic_timer_interrupt+0x8a/0xa0 arch/x86/entry/entry_64.S:790