Merge branch 'kcsan.2021.05.18a' of git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu

+36 -51

Documentation/dev-tools/kcsan.rst

··· 27 27 A typical data race report looks like this:: 28 28 29 29 ================================================================== 30 - BUG: KCSAN: data-race in generic_permission / kernfs_refresh_inode 30 + BUG: KCSAN: data-race in test_kernel_read / test_kernel_write 31 31 32 - write to 0xffff8fee4c40700c of 4 bytes by task 175 on cpu 4: 33 - kernfs_refresh_inode+0x70/0x170 34 - kernfs_iop_permission+0x4f/0x90 35 - inode_permission+0x190/0x200 36 - link_path_walk.part.0+0x503/0x8e0 37 - path_lookupat.isra.0+0x69/0x4d0 38 - filename_lookup+0x136/0x280 39 - user_path_at_empty+0x47/0x60 40 - vfs_statx+0x9b/0x130 41 - __do_sys_newlstat+0x50/0xb0 42 - __x64_sys_newlstat+0x37/0x50 43 - do_syscall_64+0x85/0x260 44 - entry_SYSCALL_64_after_hwframe+0x44/0xa9 32 + write to 0xffffffffc009a628 of 8 bytes by task 487 on cpu 0: 33 + test_kernel_write+0x1d/0x30 34 + access_thread+0x89/0xd0 35 + kthread+0x23e/0x260 36 + ret_from_fork+0x22/0x30 45 37 46 - read to 0xffff8fee4c40700c of 4 bytes by task 166 on cpu 6: 47 - generic_permission+0x5b/0x2a0 48 - kernfs_iop_permission+0x66/0x90 49 - inode_permission+0x190/0x200 50 - link_path_walk.part.0+0x503/0x8e0 51 - path_lookupat.isra.0+0x69/0x4d0 52 - filename_lookup+0x136/0x280 53 - user_path_at_empty+0x47/0x60 54 - do_faccessat+0x11a/0x390 55 - __x64_sys_access+0x3c/0x50 56 - do_syscall_64+0x85/0x260 57 - entry_SYSCALL_64_after_hwframe+0x44/0xa9 38 + read to 0xffffffffc009a628 of 8 bytes by task 488 on cpu 6: 39 + test_kernel_read+0x10/0x20 40 + access_thread+0x89/0xd0 41 + kthread+0x23e/0x260 42 + ret_from_fork+0x22/0x30 43 + 44 + value changed: 0x00000000000009a6 -> 0x00000000000009b2 58 45 59 46 Reported by Kernel Concurrency Sanitizer on: 60 - CPU: 6 PID: 166 Comm: systemd-journal Not tainted 5.3.0-rc7+ #1 61 - Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014 47 + CPU: 6 PID: 488 Comm: access_thread Not tainted 5.12.0-rc2+ #1 48 + Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014 62 49 ================================================================== 63 50 64 51 The header of the report provides a short summary of the functions involved in 65 52 the race. It is followed by the access types and stack traces of the 2 threads 66 - involved in the data race. 53 + involved in the data race. If KCSAN also observed a value change, the observed 54 + old value and new value are shown on the "value changed" line respectively. 67 55 68 56 The other less common type of data race report looks like this:: 69 57 70 58 ================================================================== 71 - BUG: KCSAN: data-race in e1000_clean_rx_irq+0x551/0xb10 59 + BUG: KCSAN: data-race in test_kernel_rmw_array+0x71/0xd0 72 60 73 - race at unknown origin, with read to 0xffff933db8a2ae6c of 1 bytes by interrupt on cpu 0: 74 - e1000_clean_rx_irq+0x551/0xb10 75 - e1000_clean+0x533/0xda0 76 - net_rx_action+0x329/0x900 77 - __do_softirq+0xdb/0x2db 78 - irq_exit+0x9b/0xa0 79 - do_IRQ+0x9c/0xf0 80 - ret_from_intr+0x0/0x18 81 - default_idle+0x3f/0x220 82 - arch_cpu_idle+0x21/0x30 83 - do_idle+0x1df/0x230 84 - cpu_startup_entry+0x14/0x20 85 - rest_init+0xc5/0xcb 86 - arch_call_rest_init+0x13/0x2b 87 - start_kernel+0x6db/0x700 61 + race at unknown origin, with read to 0xffffffffc009bdb0 of 8 bytes by task 515 on cpu 2: 62 + test_kernel_rmw_array+0x71/0xd0 63 + access_thread+0x89/0xd0 64 + kthread+0x23e/0x260 65 + ret_from_fork+0x22/0x30 66 + 67 + value changed: 0x0000000000002328 -> 0x0000000000002329 88 68 89 69 Reported by Kernel Concurrency Sanitizer on: 90 - CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.3.0-rc7+ #2 91 - Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014 70 + CPU: 2 PID: 515 Comm: access_thread Not tainted 5.12.0-rc2+ #1 71 + Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014 92 72 ================================================================== 93 73 94 74 This report is generated where it was not possible to determine the other 95 75 racing thread, but a race was inferred due to the data value of the watched 96 - memory location having changed. These can occur either due to missing 97 - instrumentation or e.g. DMA accesses. These reports will only be generated if 98 - ``CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN=y`` (selected by default). 76 + memory location having changed. These reports always show a "value changed" 77 + line. A common reason for reports of this type are missing instrumentation in 78 + the racing thread, but could also occur due to e.g. DMA accesses. Such reports 79 + are shown only if ``CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN=y``, which is 80 + enabled by default. 99 81 100 82 Selective analysis 101 83 ~~~~~~~~~~~~~~~~~~ ··· 88 106 89 107 * KCSAN understands the ``data_race(expr)`` annotation, which tells KCSAN that 90 108 any data races due to accesses in ``expr`` should be ignored and resulting 91 - behaviour when encountering a data race is deemed safe. 109 + behaviour when encountering a data race is deemed safe. Please see 110 + `"Marking Shared-Memory Accesses" in the LKMM`_ for more information. 92 111 93 112 * Disabling data race detection for entire functions can be accomplished by 94 113 using the function attribute ``__no_kcsan``:: ··· 110 127 ``Makefile``, add to the respective ``Makefile``:: 111 128 112 129 KCSAN_SANITIZE := n 130 + 131 + .. _"Marking Shared-Memory Accesses" in the LKMM: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/tools/memory-model/Documentation/access-marking.txt 113 132 114 133 Furthermore, it is possible to tell KCSAN to show or hide entire classes of 115 134 data races, depending on preferences. These can be changed via the following

+21 -32

kernel/kcsan/core.c

··· 380 380 381 381 if (consumed) { 382 382 kcsan_save_irqtrace(current); 383 - kcsan_report(ptr, size, type, KCSAN_VALUE_CHANGE_MAYBE, 384 - KCSAN_REPORT_CONSUMED_WATCHPOINT, 385 - watchpoint - watchpoints); 383 + kcsan_report_set_info(ptr, size, type, watchpoint - watchpoints); 386 384 kcsan_restore_irqtrace(current); 387 385 } else { 388 386 /* ··· 405 407 const bool is_write = (type & KCSAN_ACCESS_WRITE) != 0; 406 408 const bool is_assert = (type & KCSAN_ACCESS_ASSERT) != 0; 407 409 atomic_long_t *watchpoint; 408 - union { 409 - u8 _1; 410 - u16 _2; 411 - u32 _4; 412 - u64 _8; 413 - } expect_value; 410 + u64 old, new, diff; 414 411 unsigned long access_mask; 415 412 enum kcsan_value_change value_change = KCSAN_VALUE_CHANGE_MAYBE; 416 413 unsigned long ua_flags = user_access_save(); ··· 461 468 * Read the current value, to later check and infer a race if the data 462 469 * was modified via a non-instrumented access, e.g. from a device. 463 470 */ 464 - expect_value._8 = 0; 471 + old = 0; 465 472 switch (size) { 466 473 case 1: 467 - expect_value._1 = READ_ONCE(*(const u8 *)ptr); 474 + old = READ_ONCE(*(const u8 *)ptr); 468 475 break; 469 476 case 2: 470 - expect_value._2 = READ_ONCE(*(const u16 *)ptr); 477 + old = READ_ONCE(*(const u16 *)ptr); 471 478 break; 472 479 case 4: 473 - expect_value._4 = READ_ONCE(*(const u32 *)ptr); 480 + old = READ_ONCE(*(const u32 *)ptr); 474 481 break; 475 482 case 8: 476 - expect_value._8 = READ_ONCE(*(const u64 *)ptr); 483 + old = READ_ONCE(*(const u64 *)ptr); 477 484 break; 478 485 default: 479 486 break; /* ignore; we do not diff the values */ ··· 499 506 * racy access. 500 507 */ 501 508 access_mask = get_ctx()->access_mask; 509 + new = 0; 502 510 switch (size) { 503 511 case 1: 504 - expect_value._1 ^= READ_ONCE(*(const u8 *)ptr); 505 - if (access_mask) 506 - expect_value._1 &= (u8)access_mask; 512 + new = READ_ONCE(*(const u8 *)ptr); 507 513 break; 508 514 case 2: 509 - expect_value._2 ^= READ_ONCE(*(const u16 *)ptr); 510 - if (access_mask) 511 - expect_value._2 &= (u16)access_mask; 515 + new = READ_ONCE(*(const u16 *)ptr); 512 516 break; 513 517 case 4: 514 - expect_value._4 ^= READ_ONCE(*(const u32 *)ptr); 515 - if (access_mask) 516 - expect_value._4 &= (u32)access_mask; 518 + new = READ_ONCE(*(const u32 *)ptr); 517 519 break; 518 520 case 8: 519 - expect_value._8 ^= READ_ONCE(*(const u64 *)ptr); 520 - if (access_mask) 521 - expect_value._8 &= (u64)access_mask; 521 + new = READ_ONCE(*(const u64 *)ptr); 522 522 break; 523 523 default: 524 524 break; /* ignore; we do not diff the values */ 525 525 } 526 526 527 + diff = old ^ new; 528 + if (access_mask) 529 + diff &= access_mask; 530 + 527 531 /* Were we able to observe a value-change? */ 528 - if (expect_value._8 != 0) 532 + if (diff != 0) 529 533 value_change = KCSAN_VALUE_CHANGE_TRUE; 530 534 531 535 /* Check if this access raced with another. */ ··· 556 566 if (is_assert && value_change == KCSAN_VALUE_CHANGE_TRUE) 557 567 atomic_long_inc(&kcsan_counters[KCSAN_COUNTER_ASSERT_FAILURES]); 558 568 559 - kcsan_report(ptr, size, type, value_change, KCSAN_REPORT_RACE_SIGNAL, 560 - watchpoint - watchpoints); 569 + kcsan_report_known_origin(ptr, size, type, value_change, 570 + watchpoint - watchpoints, 571 + old, new, access_mask); 561 572 } else if (value_change == KCSAN_VALUE_CHANGE_TRUE) { 562 573 /* Inferring a race, since the value should not have changed. */ 563 574 ··· 567 576 atomic_long_inc(&kcsan_counters[KCSAN_COUNTER_ASSERT_FAILURES]); 568 577 569 578 if (IS_ENABLED(CONFIG_KCSAN_REPORT_RACE_UNKNOWN_ORIGIN) || is_assert) 570 - kcsan_report(ptr, size, type, KCSAN_VALUE_CHANGE_TRUE, 571 - KCSAN_REPORT_RACE_UNKNOWN_ORIGIN, 572 - watchpoint - watchpoints); 579 + kcsan_report_unknown_origin(ptr, size, type, old, new, access_mask); 573 580 } 574 581 575 582 /*

+19 -22

kernel/kcsan/kcsan.h

··· 116 116 KCSAN_VALUE_CHANGE_TRUE, 117 117 }; 118 118 119 - enum kcsan_report_type { 120 - /* 121 - * The thread that set up the watchpoint and briefly stalled was 122 - * signalled that another thread triggered the watchpoint. 123 - */ 124 - KCSAN_REPORT_RACE_SIGNAL, 125 - 126 - /* 127 - * A thread found and consumed a matching watchpoint. 128 - */ 129 - KCSAN_REPORT_CONSUMED_WATCHPOINT, 130 - 131 - /* 132 - * No other thread was observed to race with the access, but the data 133 - * value before and after the stall differs. 134 - */ 135 - KCSAN_REPORT_RACE_UNKNOWN_ORIGIN, 136 - }; 119 + /* 120 + * The calling thread hit and consumed a watchpoint: set the access information 121 + * to be consumed by the reporting thread. No report is printed yet. 122 + */ 123 + void kcsan_report_set_info(const volatile void *ptr, size_t size, int access_type, 124 + int watchpoint_idx); 137 125 138 126 /* 139 - * Print a race report from thread that encountered the race. 127 + * The calling thread observed that the watchpoint it set up was hit and 128 + * consumed: print the full report based on information set by the racing 129 + * thread. 140 130 */ 141 - extern void kcsan_report(const volatile void *ptr, size_t size, int access_type, 142 - enum kcsan_value_change value_change, 143 - enum kcsan_report_type type, int watchpoint_idx); 131 + void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access_type, 132 + enum kcsan_value_change value_change, int watchpoint_idx, 133 + u64 old, u64 new, u64 mask); 134 + 135 + /* 136 + * No other thread was observed to race with the access, but the data value 137 + * before and after the stall differs. Reports a race of "unknown origin". 138 + */ 139 + void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type, 140 + u64 old, u64 new, u64 mask); 144 141 145 142 #endif /* _KERNEL_KCSAN_KCSAN_H */

+88 -81

kernel/kcsan/report.c

··· 325 325 print_irqtrace_events(task); 326 326 } 327 327 328 - /* 329 - * Returns true if a report was generated, false otherwise. 330 - */ 331 - static bool print_report(enum kcsan_value_change value_change, 332 - enum kcsan_report_type type, 328 + static void print_report(enum kcsan_value_change value_change, 333 329 const struct access_info *ai, 334 - const struct other_info *other_info) 330 + const struct other_info *other_info, 331 + u64 old, u64 new, u64 mask) 335 332 { 336 333 unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 }; 337 334 int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1); ··· 341 344 * Must check report filter rules before starting to print. 342 345 */ 343 346 if (skip_report(KCSAN_VALUE_CHANGE_TRUE, stack_entries[skipnr])) 344 - return false; 347 + return; 345 348 346 - if (type == KCSAN_REPORT_RACE_SIGNAL) { 349 + if (other_info) { 347 350 other_skipnr = get_stack_skipnr(other_info->stack_entries, 348 351 other_info->num_stack_entries); 349 352 other_frame = other_info->stack_entries[other_skipnr]; 350 353 351 354 /* @value_change is only known for the other thread */ 352 355 if (skip_report(value_change, other_frame)) 353 - return false; 356 + return; 354 357 } 355 358 356 359 if (rate_limit_report(this_frame, other_frame)) 357 - return false; 360 + return; 358 361 359 362 /* Print report header. */ 360 363 pr_err("==================================================================\n"); 361 - switch (type) { 362 - case KCSAN_REPORT_RACE_SIGNAL: { 364 + if (other_info) { 363 365 int cmp; 364 366 365 367 /* ··· 370 374 get_bug_type(ai->access_type | other_info->ai.access_type), 371 375 (void *)(cmp < 0 ? other_frame : this_frame), 372 376 (void *)(cmp < 0 ? this_frame : other_frame)); 373 - } break; 374 - 375 - case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN: 377 + } else { 376 378 pr_err("BUG: KCSAN: %s in %pS\n", get_bug_type(ai->access_type), 377 379 (void *)this_frame); 378 - break; 379 - 380 - default: 381 - BUG(); 382 380 } 383 381 384 382 pr_err("\n"); 385 383 386 384 /* Print information about the racing accesses. */ 387 - switch (type) { 388 - case KCSAN_REPORT_RACE_SIGNAL: 385 + if (other_info) { 389 386 pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n", 390 387 get_access_type(other_info->ai.access_type), other_info->ai.ptr, 391 388 other_info->ai.size, get_thread_desc(other_info->ai.task_pid), ··· 396 407 pr_err("%s to 0x%px of %zu bytes by %s on cpu %i:\n", 397 408 get_access_type(ai->access_type), ai->ptr, ai->size, 398 409 get_thread_desc(ai->task_pid), ai->cpu_id); 399 - break; 400 - 401 - case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN: 410 + } else { 402 411 pr_err("race at unknown origin, with %s to 0x%px of %zu bytes by %s on cpu %i:\n", 403 412 get_access_type(ai->access_type), ai->ptr, ai->size, 404 413 get_thread_desc(ai->task_pid), ai->cpu_id); 405 - break; 406 - 407 - default: 408 - BUG(); 409 414 } 410 415 /* Print stack trace of this thread. */ 411 416 stack_trace_print(stack_entries + skipnr, num_stack_entries - skipnr, ··· 408 425 if (IS_ENABLED(CONFIG_KCSAN_VERBOSE)) 409 426 print_verbose_info(current); 410 427 428 + /* Print observed value change. */ 429 + if (ai->size <= 8) { 430 + int hex_len = ai->size * 2; 431 + u64 diff = old ^ new; 432 + 433 + if (mask) 434 + diff &= mask; 435 + if (diff) { 436 + pr_err("\n"); 437 + pr_err("value changed: 0x%0*llx -> 0x%0*llx\n", 438 + hex_len, old, hex_len, new); 439 + if (mask) { 440 + pr_err(" bits changed: 0x%0*llx with mask 0x%0*llx\n", 441 + hex_len, diff, hex_len, mask); 442 + } 443 + } 444 + } 445 + 411 446 /* Print report footer. */ 412 447 pr_err("\n"); 413 448 pr_err("Reported by Kernel Concurrency Sanitizer on:\n"); 414 449 dump_stack_print_info(KERN_DEFAULT); 415 450 pr_err("==================================================================\n"); 416 451 417 - return true; 452 + if (panic_on_warn) 453 + panic("panic_on_warn set ...\n"); 418 454 } 419 455 420 456 static void release_report(unsigned long *flags, struct other_info *other_info) 421 457 { 422 - if (other_info) 423 - /* 424 - * Use size to denote valid/invalid, since KCSAN entirely 425 - * ignores 0-sized accesses. 426 - */ 427 - other_info->ai.size = 0; 428 - 458 + /* 459 + * Use size to denote valid/invalid, since KCSAN entirely ignores 460 + * 0-sized accesses. 461 + */ 462 + other_info->ai.size = 0; 429 463 raw_spin_unlock_irqrestore(&report_lock, *flags); 430 464 } 431 465 ··· 575 575 return false; 576 576 } 577 577 578 - /* 579 - * Depending on the report type either sets @other_info and returns false, or 580 - * awaits @other_info and returns true. If @other_info is not required for the 581 - * report type, simply acquires @report_lock and returns true. 582 - */ 583 - static noinline bool prepare_report(unsigned long *flags, 584 - enum kcsan_report_type type, 585 - const struct access_info *ai, 586 - struct other_info *other_info) 578 + static struct access_info prepare_access_info(const volatile void *ptr, size_t size, 579 + int access_type) 587 580 { 588 - switch (type) { 589 - case KCSAN_REPORT_CONSUMED_WATCHPOINT: 590 - prepare_report_producer(flags, ai, other_info); 591 - return false; 592 - case KCSAN_REPORT_RACE_SIGNAL: 593 - return prepare_report_consumer(flags, ai, other_info); 594 - default: 595 - /* @other_info not required; just acquire @report_lock. */ 596 - raw_spin_lock_irqsave(&report_lock, *flags); 597 - return true; 598 - } 599 - } 600 - 601 - void kcsan_report(const volatile void *ptr, size_t size, int access_type, 602 - enum kcsan_value_change value_change, 603 - enum kcsan_report_type type, int watchpoint_idx) 604 - { 605 - unsigned long flags = 0; 606 - const struct access_info ai = { 581 + return (struct access_info) { 607 582 .ptr = ptr, 608 583 .size = size, 609 584 .access_type = access_type, 610 585 .task_pid = in_task() ? task_pid_nr(current) : -1, 611 586 .cpu_id = raw_smp_processor_id() 612 587 }; 613 - struct other_info *other_info = type == KCSAN_REPORT_RACE_UNKNOWN_ORIGIN 614 - ? NULL : &other_infos[watchpoint_idx]; 588 + } 589 + 590 + void kcsan_report_set_info(const volatile void *ptr, size_t size, int access_type, 591 + int watchpoint_idx) 592 + { 593 + const struct access_info ai = prepare_access_info(ptr, size, access_type); 594 + unsigned long flags; 615 595 616 596 kcsan_disable_current(); 617 - if (WARN_ON(watchpoint_idx < 0 || watchpoint_idx >= ARRAY_SIZE(other_infos))) 618 - goto out; 597 + lockdep_off(); /* See kcsan_report_known_origin(). */ 619 598 599 + prepare_report_producer(&flags, &ai, &other_infos[watchpoint_idx]); 600 + 601 + lockdep_on(); 602 + kcsan_enable_current(); 603 + } 604 + 605 + void kcsan_report_known_origin(const volatile void *ptr, size_t size, int access_type, 606 + enum kcsan_value_change value_change, int watchpoint_idx, 607 + u64 old, u64 new, u64 mask) 608 + { 609 + const struct access_info ai = prepare_access_info(ptr, size, access_type); 610 + struct other_info *other_info = &other_infos[watchpoint_idx]; 611 + unsigned long flags = 0; 612 + 613 + kcsan_disable_current(); 620 614 /* 621 615 * Because we may generate reports when we're in scheduler code, the use 622 616 * of printk() could deadlock. Until such time that all printing code ··· 620 626 */ 621 627 lockdep_off(); 622 628 623 - if (prepare_report(&flags, type, &ai, other_info)) { 624 - /* 625 - * Never report if value_change is FALSE, only if we it is 626 - * either TRUE or MAYBE. In case of MAYBE, further filtering may 627 - * be done once we know the full stack trace in print_report(). 628 - */ 629 - bool reported = value_change != KCSAN_VALUE_CHANGE_FALSE && 630 - print_report(value_change, type, &ai, other_info); 629 + if (!prepare_report_consumer(&flags, &ai, other_info)) 630 + goto out; 631 + /* 632 + * Never report if value_change is FALSE, only when it is 633 + * either TRUE or MAYBE. In case of MAYBE, further filtering may 634 + * be done once we know the full stack trace in print_report(). 635 + */ 636 + if (value_change != KCSAN_VALUE_CHANGE_FALSE) 637 + print_report(value_change, &ai, other_info, old, new, mask); 631 638 632 - if (reported && panic_on_warn) 633 - panic("panic_on_warn set ...\n"); 639 + release_report(&flags, other_info); 640 + out: 641 + lockdep_on(); 642 + kcsan_enable_current(); 643 + } 634 644 635 - release_report(&flags, other_info); 636 - } 645 + void kcsan_report_unknown_origin(const volatile void *ptr, size_t size, int access_type, 646 + u64 old, u64 new, u64 mask) 647 + { 648 + const struct access_info ai = prepare_access_info(ptr, size, access_type); 649 + unsigned long flags; 650 + 651 + kcsan_disable_current(); 652 + lockdep_off(); /* See kcsan_report_known_origin(). */ 653 + 654 + raw_spin_lock_irqsave(&report_lock, flags); 655 + print_report(KCSAN_VALUE_CHANGE_TRUE, &ai, NULL, old, new, mask); 656 + raw_spin_unlock_irqrestore(&report_lock, flags); 637 657 638 658 lockdep_on(); 639 - out: 640 659 kcsan_enable_current(); 641 660 }

Configure Feed

Configure Feed