Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

False positive in blk_complete_request #205

Open
dvyukov opened this issue Sep 18, 2015 · 1 comment
Open

False positive in blk_complete_request #205

dvyukov opened this issue Sep 18, 2015 · 1 comment
Labels
bug KTSAN KTSAN-related issues wontfix

Comments

@dvyukov
Copy link
Collaborator

dvyukov commented Sep 18, 2015

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
Copy link
Collaborator Author

dvyukov commented Sep 18, 2015

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

@xairy xairy transferred this issue from google/ktsan Dec 23, 2021
@xairy xairy added bug KTSAN KTSAN-related issues labels Dec 23, 2021
@melver melver added the wontfix label Jan 25, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug KTSAN KTSAN-related issues wontfix
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@melver @dvyukov @xairy