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.

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

false positives with T0 #199

Open
dvyukov opened this issue Aug 28, 2015 · 3 comments
Open

false positives with T0 #199

dvyukov opened this issue Aug 28, 2015 · 3 comments
Labels
bug KTSAN KTSAN-related issues wontfix

Comments

@dvyukov
Copy link
Collaborator

dvyukov commented Aug 28, 2015

I am seeing false positives with T0. Presumably both racy accesses are executed on the same CPU, but first accesses is executed on a thread context, while another on the scheduler context (T0).

ThreadSanitizer: data-race in rb_insert_color

Write of size 8 by thread T0 (K0):
 [<     inlined    >] rb_insert_color+0x2e6/0x380 rb_set_parent_color include/linux/rbtree_augmented.h:117
 [<     inlined    >] rb_insert_color+0x2e6/0x380 __rb_insert lib/rbtree.c:111
 [<ffffffff81552056>] rb_insert_color+0x2e6/0x380 lib/rbtree.c:420
 [<ffffffff810cf2c7>] __enqueue_entity+0x67/0x70 kernel/sched/fair.c:524
 [<     inlined    >] enqueue_task_fair+0x784/0x1230 enqueue_entity kernel/sched/fair.c:3118
 [<ffffffff810d3b44>] enqueue_task_fair+0x784/0x1230 kernel/sched/fair.c:4239
 [<ffffffff810c4507>] enqueue_task+0x37/0x60 kernel/sched/core.c:834
 [<ffffffff810c7076>] activate_task+0x26/0x30 kernel/sched/core.c:849
 [<     inlined    >] ttwu_do_activate.constprop.95+0x2e/0x60 ttwu_activate kernel/sched/core.c:1643
 [<ffffffff810c72fe>] ttwu_do_activate.constprop.95+0x2e/0x60 kernel/sched/core.c:1696
 [<     inlined    >] try_to_wake_up+0x314/0x3c0 ttwu_queue kernel/sched/core.c:1841
 [<ffffffff810c7e84>] try_to_wake_up+0x314/0x3c0 kernel/sched/core.c:1909
 [<ffffffff810c7f52>] wake_up_process+0x22/0x40 kernel/sched/core.c:1977 (discriminator 3)
 [<ffffffff8110e6cd>] process_timeout+0x1d/0x30 kernel/time/timer.c:1441
 [<ffffffff8110e72c>] call_timer_fn+0x4c/0x1c0 kernel/time/timer.c:1155
 [<     inlined    >] run_timer_softirq+0x313/0x510 __run_timers kernel/time/timer.c:1231
 [<ffffffff8110f683>] run_timer_softirq+0x313/0x510 kernel/time/timer.c:1414
 [<ffffffff81091d1e>] __do_softirq+0xbe/0x300 kernel/softirq.c:273
 [<     inlined    >] irq_exit+0xb0/0xc0 invoke_softirq kernel/softirq.c:350
 [<ffffffff81092100>] irq_exit+0xb0/0xc0 kernel/softirq.c:391
 [<     inlined    >] smp_apic_timer_interrupt+0x7b/0xb0 exiting_irq ./arch/x86/include/asm/apic.h:655
 [<ffffffff8105eb1b>] smp_apic_timer_interrupt+0x7b/0xb0 arch/x86/kernel/apic/apic.c:915
 [<ffffffff81ee529b>] apic_timer_interrupt+0x6b/0x70 arch/x86/entry/entry_64.S:782
 [<     inlined    >] default_idle+0x3f/0x170 arch_safe_halt ./arch/x86/include/asm/paravirt.h:111
 [<ffffffff81015c9f>] default_idle+0x3f/0x170 arch/x86/kernel/process.c:301
 [<ffffffff810165cf>] arch_cpu_idle+0x1f/0x30 arch/x86/kernel/process.c:292
 [<ffffffff810dcf8f>] default_idle_call+0x3f/0x60 kernel/sched/idle.c:89
 [<     inlined    >] cpu_startup_entry+0x37c/0x3f0 cpuidle_idle_call kernel/sched/idle.c:157
 [<     inlined    >] cpu_startup_entry+0x37c/0x3f0 cpu_idle_loop kernel/sched/idle.c:253
 [<ffffffff810dd3bc>] cpu_startup_entry+0x37c/0x3f0 kernel/sched/idle.c:301
 [<ffffffff81ed095d>] rest_init+0x9d/0xb0 init/main.c:413
 [<ffffffff8252c738>] start_kernel+0x564/0x578 init/main.c:687
 [<ffffffff8252b3ce>] x86_64_start_reservations+0x49/0x52 arch/x86/kernel/head64.c:195
 [<ffffffff8252b695>] x86_64_start_kernel+0x2be/0x2d2 arch/x86/kernel/head64.c:184
DBG: cpu = ffffe8ffffc00910
DBG: cpu id = 0

Previous read of size 8 by thread T10 (K0):
 [<     inlined    >] rb_insert_color+0x3e/0x380 __rb_insert lib/rbtree.c:113
 [<ffffffff81551dae>] rb_insert_color+0x3e/0x380 lib/rbtree.c:420
 [<ffffffff810cf2c7>] __enqueue_entity+0x67/0x70 kernel/sched/fair.c:524
 [<ffffffff810af76c>] __queue_work+0x2dc/0x680 kernel/workqueue.c:1394
 [<ffffffff810b0227>] delayed_work_timer_fn+0x37/0x50 kernel/workqueue.c:1433
 [<ffffffff8110e72c>] call_timer_fn+0x4c/0x1c0 kernel/time/timer.c:1155
 [<     inlined    >] run_timer_softirq+0x2c9/0x510 __run_timers kernel/time/timer.c:1227
 [<ffffffff8110f639>] run_timer_softirq+0x2c9/0x510 kernel/time/timer.c:1414
 [<ffffffff81091d1e>] __do_softirq+0xbe/0x300 kernel/softirq.c:273
 [<ffffffff81ee529b>] apic_timer_interrupt+0x6b/0x70 arch/x86/entry/entry_64.S:782
 [<     inlined    >] cpu_startup_entry+0x193/0x3f0 cpu_idle_loop kernel/sched/idle.c:267
 [<ffffffff810dd1d3>] cpu_startup_entry+0x193/0x3f0 kernel/sched/idle.c:301
DBG: cpu = 0

DBG: addr: ffff880139585238
DBG: first offset: 0, second offset: 0
DBG: T0 clock: {T0: 21687551, T10: 23571656}
DBG: T10 clock: {T10: 23571668}
@dvyukov
Copy link
Collaborator Author

dvyukov commented Aug 28, 2015

Here is another one:

ThreadSanitizer: data-race in mm_release

Write of size 8 by thread T219 (K753):
 [<     inlined    >] mm_release+0x115/0x200 complete_vfork_done kernel/fork.c:814
 [<ffffffff81086ba5>] mm_release+0x115/0x200 kernel/fork.c:901
 [<     inlined    >] do_exit+0x228/0x13d0 exit_mm kernel/exit.c:392
 [<ffffffff8108d418>] do_exit+0x228/0x13d0 kernel/exit.c:733
 [<ffffffff810bbbce>] kthread+0x13e/0x170 kernel/kthread.c:210
 [<ffffffff81ee485f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = ffffe8ffffd00910
DBG: cpu id = 2

Previous read of size 8 by thread T11 (K0):
 [<     inlined    >] kthread_data+0x21/0x50 to_kthread kernel/kthread.c:61
 [<ffffffff810bca21>] kthread_data+0x21/0x50 kernel/kthread.c:136
 [<ffffffff810b5852>] wq_worker_waking_up+0x22/0xc0 kernel/workqueue.c:823
 [<     inlined    >] ttwu_do_activate.constprop.95+0x4b/0x60 ttwu_activate kernel/sched/core.c:1648
 [<ffffffff810c731b>] ttwu_do_activate.constprop.95+0x4b/0x60 kernel/sched/core.c:1696
 [<ffffffff81ee599b>] reschedule_interrupt+0x6b/0x70 arch/x86/entry/entry_64.S:805
 [<ffffffff810165cf>] arch_cpu_idle+0x1f/0x30 arch/x86/kernel/process.c:292
 [<ffffffff810dcf8f>] default_idle_call+0x3f/0x60 kernel/sched/idle.c:89
DBG: cpu = 0

DBG: addr: ffff8801397e95e0
DBG: first offset: 0, second offset: 0
DBG: T219 clock: {T219: 4625, T11: 21633748}
DBG: T11 clock: {T11: 21633834}

@dvyukov
Copy link
Collaborator Author

dvyukov commented Aug 28, 2015

Another one:

ThreadSanitizer: data-race in handle_edge_irq

Write of size 4 by thread T11 (K0):
 [<     inlined    >] handle_edge_irq+0x1ae/0x3b0 irqd_set kernel/irq/internals.h:182
 [<     inlined    >] handle_edge_irq+0x1ae/0x3b0 irq_state_set_masked kernel/irq/chip.c:172
 [<     inlined    >] handle_edge_irq+0x1ae/0x3b0 mask_ack_irq kernel/irq/chip.c:267
 [<ffffffff810fc0be>] handle_edge_irq+0x1ae/0x3b0 kernel/irq/chip.c:582
 [<     inlined    >] handle_irq+0x9f/0x230 generic_handle_irq_desc include/linux/irqdesc.h:146
 [<ffffffff8100a1ff>] handle_irq+0x9f/0x230 arch/x86/kernel/irq_64.c:81
 [<ffffffff810094da>] do_IRQ+0x8a/0x170 arch/x86/kernel/irq.c:223
 [<ffffffff81ee2f6b>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
 [<     inlined    >] default_idle+0x3f/0x170 arch_safe_halt ./arch/x86/include/asm/paravirt.h:111
 [<ffffffff81015c9f>] default_idle+0x3f/0x170 arch/x86/kernel/process.c:301
 [<ffffffff810165cf>] arch_cpu_idle+0x1f/0x30 arch/x86/kernel/process.c:292
 [<ffffffff810dcf7f>] default_idle_call+0x3f/0x60 kernel/sched/idle.c:89
 [<     inlined    >] cpu_startup_entry+0x37c/0x3f0 cpuidle_idle_call kernel/sched/idle.c:157
 [<     inlined    >] cpu_startup_entry+0x37c/0x3f0 cpu_idle_loop kernel/sched/idle.c:253
 [<ffffffff810dd3ac>] cpu_startup_entry+0x37c/0x3f0 kernel/sched/idle.c:301
 [<ffffffff8105b33d>] start_secondary+0x22d/0x240 arch/x86/kernel/smpboot.c:260

Previous read of size 4 by thread T1 (K1):
 [<     inlined    >] __synchronize_hardirq+0x43/0xa0 irqd_irq_inprogress include/linux/irq.h:277
 [<ffffffff810f70f3>] __synchronize_hardirq+0x43/0xa0 kernel/irq/manage.c:46
 [<ffffffff810f727a>] synchronize_irq+0x3a/0xd0 kernel/irq/manage.c:103
 [<ffffffff810f7d69>] __free_irq+0x169/0x290 kernel/irq/manage.c:1410
 [<ffffffff810f7fa5>] free_irq+0x95/0x120 kernel/irq/manage.c:1480
 [<     inlined    >] univ8250_release_irq+0x10e/0x110 serial_unlink_irq_chain drivers/tty/serial/8250/8250_core.c:1835
 [<ffffffff81692f6e>] univ8250_release_irq+0x10e/0x110 drivers/tty/serial/8250/8250_core.c:1941
 [<ffffffff81693694>] serial8250_do_shutdown+0x1b4/0x300 drivers/tty/serial/8250/8250_core.c:2412
 [<ffffffff8169381d>] serial8250_shutdown+0x3d/0x50 drivers/tty/serial/8250/8250_core.c:2421
 [<ffffffff81684856>] uart_port_shutdown+0x66/0x90 drivers/tty/serial/serial_core.c:1556
 [<ffffffff81687bf2>] uart_shutdown+0x162/0x200 drivers/tty/serial/serial_core.c:246
 [<ffffffff81687f35>] uart_close+0xd5/0x3d0 drivers/tty/serial/serial_core.c:1419
 [<ffffffff81655ed1>] tty_release+0x1c1/0x7c0 drivers/tty/tty_io.c:1791
 [<ffffffff8126154f>] __fput+0x15f/0x310 fs/file_table.c:207
 [<ffffffff8126176d>] ____fput+0x1d/0x30 fs/file_table.c:243
 [<ffffffff810b9485>] task_work_run+0x115/0x130 kernel/task_work.c:123 (discriminator 1)
 [<     inlined    >] do_notify_resume+0x73/0x80 tracehook_notify_resume include/linux/tracehook.h:190
 [<ffffffff81006da3>] do_notify_resume+0x73/0x80 arch/x86/kernel/signal.c:757
 [<ffffffff81ee25fc>] int_signal+0x12/0x17 arch/x86/entry/entry_64.S:326

xairy referenced this issue in google/ktsan Aug 31, 2015
Nikolay has reported a hang when a memcg reclaim got stuck with the
following backtrace:

PID: 18308  TASK: ffff883d7c9b0a30  CPU: 1   COMMAND: "rsync"
  #0 __schedule at ffffffff815ab152
  #1 schedule at ffffffff815ab76e
  #2 schedule_timeout at ffffffff815ae5e5
  #3 io_schedule_timeout at ffffffff815aad6a
  #4 bit_wait_io at ffffffff815abfc6
  #5 __wait_on_bit at ffffffff815abda5
  #6 wait_on_page_bit at ffffffff8111fd4f
  #7 shrink_page_list at ffffffff81135445
  #8 shrink_inactive_list at ffffffff81135845
  #9 shrink_lruvec at ffffffff81135ead
 #10 shrink_zone at ffffffff811360c3
 #11 shrink_zones at ffffffff81136eff
 #12 do_try_to_free_pages at ffffffff8113712f
 #13 try_to_free_mem_cgroup_pages at ffffffff811372be
 #14 try_charge at ffffffff81189423
 #15 mem_cgroup_try_charge at ffffffff8118c6f5
 #16 __add_to_page_cache_locked at ffffffff8112137d
 #17 add_to_page_cache_lru at ffffffff81121618
 #18 pagecache_get_page at ffffffff8112170b
 #19 grow_dev_page at ffffffff811c8297
 #20 __getblk_slow at ffffffff811c91d6
 #21 __getblk_gfp at ffffffff811c92c1
 #22 ext4_ext_grow_indepth at ffffffff8124565c
 #23 ext4_ext_create_new_leaf at ffffffff81246ca8
 #24 ext4_ext_insert_extent at ffffffff81246f09
 #25 ext4_ext_map_blocks at ffffffff8124a848
 #26 ext4_map_blocks at ffffffff8121a5b7
 #27 mpage_map_one_extent at ffffffff8121b1fa
 #28 mpage_map_and_submit_extent at ffffffff8121f07b
 #29 ext4_writepages at ffffffff8121f6d5
 #30 do_writepages at ffffffff8112c490
 #31 __filemap_fdatawrite_range at ffffffff81120199
 #32 filemap_flush at ffffffff8112041c
 #33 ext4_alloc_da_blocks at ffffffff81219da1
 #34 ext4_rename at ffffffff81229b91
 #35 ext4_rename2 at ffffffff81229e32
 #36 vfs_rename at ffffffff811a08a5
 #37 SYSC_renameat2 at ffffffff811a3ffc
 #38 sys_renameat2 at ffffffff811a408e
 #39 sys_rename at ffffffff8119e51e
 #40 system_call_fastpath at ffffffff815afa89

Dave Chinner has properly pointed out that this is a deadlock in the
reclaim code because ext4 doesn't submit pages which are marked by
PG_writeback right away.

The heuristic was introduced by commit e62e384 ("memcg: prevent OOM
with too many dirty pages") and it was applied only when may_enter_fs
was specified.  The code has been changed by c3b94f4 ("memcg:
further prevent OOM with too many dirty pages") which has removed the
__GFP_FS restriction with a reasoning that we do not get into the fs
code.  But this is not sufficient apparently because the fs doesn't
necessarily submit pages marked PG_writeback for IO right away.

ext4_bio_write_page calls io_submit_add_bh but that doesn't necessarily
submit the bio.  Instead it tries to map more pages into the bio and
mpage_map_one_extent might trigger memcg charge which might end up
waiting on a page which is marked PG_writeback but hasn't been submitted
yet so we would end up waiting for something that never finishes.

Fix this issue by replacing __GFP_IO by may_enter_fs check (for case 2)
before we go to wait on the writeback.  The page fault path, which is
the only path that triggers memcg oom killer since 3.12, shouldn't
require GFP_NOFS and so we shouldn't reintroduce the premature OOM
killer issue which was originally addressed by the heuristic.

As per David Chinner the xfs is doing similar thing since 2.6.15 already
so ext4 is not the only affected filesystem.  Moreover he notes:

: For example: IO completion might require unwritten extent conversion
: which executes filesystem transactions and GFP_NOFS allocations. The
: writeback flag on the pages can not be cleared until unwritten
: extent conversion completes. Hence memory reclaim cannot wait on
: page writeback to complete in GFP_NOFS context because it is not
: safe to do so, memcg reclaim or otherwise.

Cc: [email protected] # 3.9+
[[email protected]: corrected the control flow]
Fixes: c3b94f4 ("memcg: further prevent OOM with too many dirty pages")
Reported-by: Nikolay Borisov <[email protected]>
Signed-off-by: Michal Hocko <[email protected]>
Signed-off-by: Hugh Dickins <[email protected]>
Signed-off-by: Linus Torvalds <[email protected]>
@dvyukov
Copy link
Collaborator Author

dvyukov commented Sep 1, 2015

The last report (handle_edge_irq) turned out to be a real race.
First two seems to be false positives presumably related to the fact that we ignore work queue mutex in scheduler.
E.g. a thread accesses task->vfork_data and then puts the task in the current cpu work queue (under the mutex); then this task is extracted by scheduler and executed (but mutex is ignored). Then the task accesses own task->vfork_data. Ktsan reports a race between accesses to task->vfork_data, while they are synchronized by the work queue mutex.

melver referenced this issue in google/ktsan Nov 4, 2019
In nsim_fib_init(), if register_fib_notifier failed, nsim_fib_net_ops
should be unregistered before return.

In nsim_fib_exit(), unregister_fib_notifier should be called before
nsim_fib_net_ops be unregistered, otherwise may cause use-after-free:

BUG: KASAN: use-after-free in nsim_fib_event_nb+0x342/0x570 [netdevsim]
Read of size 8 at addr ffff8881daaf4388 by task kworker/0:3/3499

CPU: 0 PID: 3499 Comm: kworker/0:3 Not tainted 5.3.0-rc7+ #30
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu1 04/01/2014
Workqueue: ipv6_addrconf addrconf_dad_work [ipv6]
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0xa9/0x10e lib/dump_stack.c:113
 print_address_description+0x65/0x380 mm/kasan/report.c:351
 __kasan_report+0x149/0x18d mm/kasan/report.c:482
 kasan_report+0xe/0x20 mm/kasan/common.c:618
 nsim_fib_event_nb+0x342/0x570 [netdevsim]
 notifier_call_chain+0x52/0xf0 kernel/notifier.c:95
 __atomic_notifier_call_chain+0x78/0x140 kernel/notifier.c:185
 call_fib_notifiers+0x30/0x60 net/core/fib_notifier.c:30
 call_fib6_entry_notifiers+0xc1/0x100 [ipv6]
 fib6_add+0x92e/0x1b10 [ipv6]
 __ip6_ins_rt+0x40/0x60 [ipv6]
 ip6_ins_rt+0x84/0xb0 [ipv6]
 __ipv6_ifa_notify+0x4b6/0x550 [ipv6]
 ipv6_ifa_notify+0xa5/0x180 [ipv6]
 addrconf_dad_completed+0xca/0x640 [ipv6]
 addrconf_dad_work+0x296/0x960 [ipv6]
 process_one_work+0x5c0/0xc00 kernel/workqueue.c:2269
 worker_thread+0x5c/0x670 kernel/workqueue.c:2415
 kthread+0x1d7/0x200 kernel/kthread.c:255
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352

Allocated by task 3388:
 save_stack+0x19/0x80 mm/kasan/common.c:69
 set_track mm/kasan/common.c:77 [inline]
 __kasan_kmalloc.constprop.3+0xa0/0xd0 mm/kasan/common.c:493
 kmalloc include/linux/slab.h:557 [inline]
 kzalloc include/linux/slab.h:748 [inline]
 ops_init+0xa9/0x220 net/core/net_namespace.c:127
 __register_pernet_operations net/core/net_namespace.c:1135 [inline]
 register_pernet_operations+0x1d4/0x420 net/core/net_namespace.c:1212
 register_pernet_subsys+0x24/0x40 net/core/net_namespace.c:1253
 nsim_fib_init+0x12/0x70 [netdevsim]
 veth_get_link_ksettings+0x2b/0x50 [veth]
 do_one_initcall+0xd4/0x454 init/main.c:939
 do_init_module+0xe0/0x330 kernel/module.c:3490
 load_module+0x3c2f/0x4620 kernel/module.c:3841
 __do_sys_finit_module+0x163/0x190 kernel/module.c:3931
 do_syscall_64+0x72/0x2e0 arch/x86/entry/common.c:296
 entry_SYSCALL_64_after_hwframe+0x49/0xbe

Freed by task 3534:
 save_stack+0x19/0x80 mm/kasan/common.c:69
 set_track mm/kasan/common.c:77 [inline]
 __kasan_slab_free+0x130/0x180 mm/kasan/common.c:455
 slab_free_hook mm/slub.c:1423 [inline]
 slab_free_freelist_hook mm/slub.c:1474 [inline]
 slab_free mm/slub.c:3016 [inline]
 kfree+0xe9/0x2d0 mm/slub.c:3957
 ops_free net/core/net_namespace.c:151 [inline]
 ops_free_list.part.7+0x156/0x220 net/core/net_namespace.c:184
 ops_free_list net/core/net_namespace.c:182 [inline]
 __unregister_pernet_operations net/core/net_namespace.c:1165 [inline]
 unregister_pernet_operations+0x221/0x2a0 net/core/net_namespace.c:1224
 unregister_pernet_subsys+0x1d/0x30 net/core/net_namespace.c:1271
 nsim_fib_exit+0x11/0x20 [netdevsim]
 nsim_module_exit+0x16/0x21 [netdevsim]
 __do_sys_delete_module kernel/module.c:1015 [inline]
 __se_sys_delete_module kernel/module.c:958 [inline]
 __x64_sys_delete_module+0x244/0x330 kernel/module.c:958
 do_syscall_64+0x72/0x2e0 arch/x86/entry/common.c:296
 entry_SYSCALL_64_after_hwframe+0x49/0xbe

Reported-by: Hulk Robot <[email protected]>
Fixes: 59c84b9 ("netdevsim: Restore per-network namespace accounting for fib entries")
Signed-off-by: YueHaibing <[email protected]>
Acked-by: Jakub Kicinski <[email protected]>
Signed-off-by: David S. Miller <[email protected]>
@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
Labels
bug KTSAN KTSAN-related issues wontfix
Projects
None yet
Development

No branches or pull requests

3 participants