| Message ID | 20230920000139.15533-1-mirsad.todorovac@alu.unizg.hr (mailing list archive) |
|---|---|
| State | Superseded, archived |
| Headers | show |
| Series | [v1,1/1] acpica: use spinlocks to fix the data-races reported by the KCSAN | expand |
Hi Mirsad, kernel test robot noticed the following build warnings: [auto build test WARNING on linus/master] [also build test WARNING on v6.6-rc2 next-20230920] [If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in https://git-scm.com/docs/git-format-patch#_base_tree_information] url: https://github.com/intel-lab-lkp/linux/commits/Mirsad-Goran-Todorovac/acpica-use-spinlocks-to-fix-the-data-races-reported-by-the-KCSAN/20230920-080345 base: linus/master patch link: https://lore.kernel.org/r/20230920000139.15533-1-mirsad.todorovac%40alu.unizg.hr patch subject: [PATCH v1 1/1] acpica: use spinlocks to fix the data-races reported by the KCSAN config: i386-randconfig-003-20230920 (https://download.01.org/0day-ci/archive/20230920/202309201331.S2c1JL2h-lkp@intel.com/config) compiler: gcc-12 (Debian 12.2.0-14) 12.2.0 reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20230920/202309201331.S2c1JL2h-lkp@intel.com/reproduce) If you fix the issue in a separate patch/commit (i.e. not just a new version of the same patch/commit), kindly add following tags | Reported-by: kernel test robot <lkp@intel.com> | Closes: https://lore.kernel.org/oe-kbuild-all/202309201331.S2c1JL2h-lkp@intel.com/ All warnings (new ones prefixed by >>): drivers/acpi/acpica/utdebug.c: In function 'acpi_debug_print': >> drivers/acpi/acpica/utdebug.c:145:13: warning: unused variable 'nesting_level' [-Wunused-variable] 145 | u32 nesting_level; | ^~~~~~~~~~~~~ vim +/nesting_level +145 drivers/acpi/acpica/utdebug.c 113 114 /******************************************************************************* 115 * 116 * FUNCTION: acpi_debug_print 117 * 118 * PARAMETERS: requested_debug_level - Requested debug print level 119 * line_number - Caller's line number (for error output) 120 * function_name - Caller's procedure name 121 * module_name - Caller's module name 122 * component_id - Caller's component ID 123 * format - Printf format field 124 * ... - Optional printf arguments 125 * 126 * RETURN: None 127 * 128 * DESCRIPTION: Print error message with prefix consisting of the module name, 129 * line number, and component ID. 130 * 131 ******************************************************************************/ 132 133 void ACPI_INTERNAL_VAR_XFACE 134 acpi_debug_print(u32 requested_debug_level, 135 u32 line_number, 136 const char *function_name, 137 const char *module_name, 138 u32 component_id, const char *format, ...) 139 { 140 acpi_thread_id thread_id; 141 va_list args; 142 #ifdef ACPI_APPLICATION 143 int fill_count; 144 #endif > 145 u32 nesting_level; 146 147 /* Check if debug output enabled */ 148 149 if (!ACPI_IS_DEBUG_ENABLED(requested_debug_level, component_id)) { 150 return; 151 } 152 153 /* 154 * Thread tracking and context switch notification 155 */ 156 thread_id = acpi_os_get_thread_id(); 157 if (thread_id != acpi_gbl_previous_thread_id) { 158 if (ACPI_LV_THREADS & acpi_dbg_level) { 159 acpi_os_printf 160 ("\n**** Context Switch from TID %u to TID %u ****\n\n", 161 (u32)acpi_gbl_previous_thread_id, (u32)thread_id); 162 } 163 164 acpi_gbl_previous_thread_id = thread_id; 165 WRITE_ONCE(acpi_gbl_nesting_level, 0); 166 } 167 168 /* 169 * Display the module name, current line number, thread ID (if requested), 170 * current procedure nesting level, and the current procedure name 171 */ 172 acpi_os_printf("%9s-%04d ", module_name, line_number); 173
Hi Mirsad,
kernel test robot noticed the following build warnings:
[auto build test WARNING on linus/master]
[also build test WARNING on v6.6-rc2 next-20230920]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]
url: https://github.com/intel-lab-lkp/linux/commits/Mirsad-Goran-Todorovac/acpica-use-spinlocks-to-fix-the-data-races-reported-by-the-KCSAN/20230920-080345
base: linus/master
patch link: https://lore.kernel.org/r/20230920000139.15533-1-mirsad.todorovac%40alu.unizg.hr
patch subject: [PATCH v1 1/1] acpica: use spinlocks to fix the data-races reported by the KCSAN
config: i386-randconfig-012-20230920 (https://download.01.org/0day-ci/archive/20230920/202309201308.5ZBJFbjh-lkp@intel.com/config)
compiler: gcc-9 (Debian 9.3.0-22) 9.3.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20230920/202309201308.5ZBJFbjh-lkp@intel.com/reproduce)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202309201308.5ZBJFbjh-lkp@intel.com/
All warnings (new ones prefixed by >>):
In file included from include/linux/spinlock.h:89,
from include/linux/wait.h:9,
from include/linux/pid.h:6,
from include/linux/sched.h:14,
from include/acpi/platform/aclinux.h:55,
from include/acpi/platform/acenv.h:160,
from include/acpi/acpi.h:22,
from drivers/acpi/acpica/utdebug.c:12:
>> drivers/acpi/acpica/utdebug.c:19:24: warning: 'acpi_utdebug_lock' defined but not used [-Wunused-variable]
19 | static DEFINE_SPINLOCK(acpi_utdebug_lock);
| ^~~~~~~~~~~~~~~~~
include/linux/spinlock_types.h:43:39: note: in definition of macro 'DEFINE_SPINLOCK'
43 | #define DEFINE_SPINLOCK(x) spinlock_t x = __SPIN_LOCK_UNLOCKED(x)
| ^
vim +/acpi_utdebug_lock +19 drivers/acpi/acpica/utdebug.c
11
> 12 #include <acpi/acpi.h>
13 #include "accommon.h"
14 #include "acinterp.h"
15
16 #define _COMPONENT ACPI_UTILITIES
17 ACPI_MODULE_NAME("utdebug")
18
> 19 static DEFINE_SPINLOCK(acpi_utdebug_lock);
20
diff --git a/drivers/acpi/acpica/utdebug.c b/drivers/acpi/acpica/utdebug.c index c5f6c85a3a09..148f2b820c88 100644 --- a/drivers/acpi/acpica/utdebug.c +++ b/drivers/acpi/acpica/utdebug.c @@ -16,6 +16,8 @@ #define _COMPONENT ACPI_UTILITIES ACPI_MODULE_NAME("utdebug") +static DEFINE_SPINLOCK(acpi_utdebug_lock); + #ifdef ACPI_DEBUG_OUTPUT static acpi_thread_id acpi_gbl_previous_thread_id = (acpi_thread_id) 0xFFFFFFFF; static const char *acpi_gbl_function_entry_prefix = "----Entry"; @@ -60,13 +62,16 @@ void acpi_ut_init_stack_ptr_trace(void) void acpi_ut_track_stack_ptr(void) { acpi_size current_sp; + u32 nesting_level; if (¤t_sp < acpi_gbl_lowest_stack_pointer) { acpi_gbl_lowest_stack_pointer = ¤t_sp; } - if (acpi_gbl_nesting_level > acpi_gbl_deepest_nesting) { - acpi_gbl_deepest_nesting = acpi_gbl_nesting_level; + nesting_level = READ_ONCE(acpi_gbl_nesting_level); + + if (nesting_level > acpi_gbl_deepest_nesting) { + acpi_gbl_deepest_nesting = nesting_level; } } @@ -137,6 +142,7 @@ acpi_debug_print(u32 requested_debug_level, #ifdef ACPI_APPLICATION int fill_count; #endif + u32 nesting_level; /* Check if debug output enabled */ @@ -156,7 +162,7 @@ acpi_debug_print(u32 requested_debug_level, } acpi_gbl_previous_thread_id = thread_id; - acpi_gbl_nesting_level = 0; + WRITE_ONCE(acpi_gbl_nesting_level, 0); } /* @@ -176,14 +182,16 @@ acpi_debug_print(u32 requested_debug_level, acpi_os_printf("[%u] ", (u32)thread_id); } - fill_count = 48 - acpi_gbl_nesting_level - + fill_count = 48 - READ_ONCE(acpi_gbl_nesting_level) - strlen(acpi_ut_trim_function_name(function_name)); if (fill_count < 0) { fill_count = 0; } + nesting_level = READ_ONCE(acpi_gbl_nesting_level); + acpi_os_printf("[%02d] %*s", - acpi_gbl_nesting_level, acpi_gbl_nesting_level + 1, " "); + nesting_level, nesting_level + 1, " "); acpi_os_printf("%s%*s: ", acpi_ut_trim_function_name(function_name), fill_count, " "); @@ -260,7 +268,10 @@ acpi_ut_trace(u32 line_number, const char *module_name, u32 component_id) { + spin_lock(&acpi_utdebug_lock); acpi_gbl_nesting_level++; + spin_unlock(&acpi_utdebug_lock); + acpi_ut_track_stack_ptr(); /* Check if enabled up-front for performance */ @@ -298,7 +309,10 @@ acpi_ut_trace_ptr(u32 line_number, u32 component_id, const void *pointer) { + spin_lock(&acpi_utdebug_lock); acpi_gbl_nesting_level++; + spin_unlock(&acpi_utdebug_lock); + acpi_ut_track_stack_ptr(); /* Check if enabled up-front for performance */ @@ -334,7 +348,10 @@ acpi_ut_trace_str(u32 line_number, const char *module_name, u32 component_id, const char *string) { + spin_lock(&acpi_utdebug_lock); acpi_gbl_nesting_level++; + spin_unlock(&acpi_utdebug_lock); + acpi_ut_track_stack_ptr(); /* Check if enabled up-front for performance */ @@ -370,7 +387,10 @@ acpi_ut_trace_u32(u32 line_number, const char *module_name, u32 component_id, u32 integer) { + spin_lock(&acpi_utdebug_lock); acpi_gbl_nesting_level++; + spin_unlock(&acpi_utdebug_lock); + acpi_ut_track_stack_ptr(); /* Check if enabled up-front for performance */ @@ -414,9 +434,11 @@ acpi_ut_exit(u32 line_number, acpi_gbl_function_exit_prefix); } + spin_lock(&acpi_utdebug_lock); if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } + spin_unlock(&acpi_utdebug_lock); } ACPI_EXPORT_SYMBOL(acpi_ut_exit) @@ -463,9 +485,11 @@ acpi_ut_status_exit(u32 line_number, } } + spin_lock(&acpi_utdebug_lock); if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } + spin_unlock(&acpi_utdebug_lock); } ACPI_EXPORT_SYMBOL(acpi_ut_status_exit) @@ -502,9 +526,11 @@ acpi_ut_value_exit(u32 line_number, ACPI_FORMAT_UINT64(value)); } + spin_lock(&acpi_utdebug_lock); if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } + spin_unlock(&acpi_utdebug_lock); } ACPI_EXPORT_SYMBOL(acpi_ut_value_exit) @@ -540,9 +566,11 @@ acpi_ut_ptr_exit(u32 line_number, acpi_gbl_function_exit_prefix, ptr); } + spin_lock(&acpi_utdebug_lock); if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } + spin_unlock(&acpi_utdebug_lock); } /******************************************************************************* @@ -577,9 +605,11 @@ acpi_ut_str_exit(u32 line_number, acpi_gbl_function_exit_prefix, string); } + spin_lock(&acpi_utdebug_lock); if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } + spin_unlock(&acpi_utdebug_lock); } /*******************************************************************************
KCSAN reported hundreds of instances of data-races in ACPICA like this one: [ 6.994149] ================================================================== [ 6.994443] BUG: KCSAN: data-race in acpi_ut_status_exit / acpi_ut_trace [ 6.994795] write to 0xffffffffbae5a884 of 4 bytes by task 0 on cpu 2: [ 6.994944] acpi_ut_status_exit (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/utdebug.c:467) [ 6.994957] acpi_hw_register_read (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwregs.c:563) [ 6.994968] acpi_read_bit_register (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwxface.c:171) [ 6.994980] acpi_idle_bm_check (/home/marvin/linux/kernel/torvalds2/drivers/acpi/processor_idle.c:511) [ 6.994990] acpi_idle_enter_bm (/home/marvin/linux/kernel/torvalds2/drivers/acpi/processor_idle.c:644 (discriminator 1)) [ 6.995000] acpi_idle_enter (/home/marvin/linux/kernel/torvalds2/drivers/acpi/processor_idle.c:695) [ 6.995010] cpuidle_enter_state (/home/marvin/linux/kernel/torvalds2/drivers/cpuidle/cpuidle.c:267) [ 6.995019] cpuidle_enter (/home/marvin/linux/kernel/torvalds2/drivers/cpuidle/cpuidle.c:390) [ 6.995027] call_cpuidle (/home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:135) [ 6.995038] do_idle (/home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:219 /home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:282) [ 6.995046] cpu_startup_entry (/home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:378 (discriminator 1)) [ 6.995055] start_secondary (/home/marvin/linux/kernel/torvalds2/arch/x86/kernel/smpboot.c:210 /home/marvin/linux/kernel/torvalds2/arch/x86/kernel/smpboot.c:294) [ 6.995066] secondary_startup_64_no_verify (/home/marvin/linux/kernel/torvalds2/arch/x86/kernel/head_64.S:433) [ 6.995121] read to 0xffffffffbae5a884 of 4 bytes by task 0 on cpu 9: [ 6.995267] acpi_ut_trace (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/utdebug.c:263) [ 6.995279] acpi_hw_validate_io_request (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwvalid.c:101) [ 6.995291] acpi_hw_read_port (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwvalid.c:202) [ 6.995303] acpi_hw_read (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwregs.c:251) [ 6.995313] acpi_hw_register_read (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwregs.c:725 /home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwregs.c:499) [ 6.995325] acpi_read_bit_register (/home/marvin/linux/kernel/torvalds2/drivers/acpi/acpica/hwxface.c:171) [ 6.995336] acpi_idle_bm_check (/home/marvin/linux/kernel/torvalds2/drivers/acpi/processor_idle.c:511) [ 6.995346] acpi_idle_enter_bm (/home/marvin/linux/kernel/torvalds2/drivers/acpi/processor_idle.c:644 (discriminator 1)) [ 6.995356] acpi_idle_enter (/home/marvin/linux/kernel/torvalds2/drivers/acpi/processor_idle.c:695) [ 6.995366] cpuidle_enter_state (/home/marvin/linux/kernel/torvalds2/drivers/cpuidle/cpuidle.c:267) [ 6.995375] cpuidle_enter (/home/marvin/linux/kernel/torvalds2/drivers/cpuidle/cpuidle.c:390) [ 6.995383] call_cpuidle (/home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:135) [ 6.995394] do_idle (/home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:219 /home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:282) [ 6.995402] cpu_startup_entry (/home/marvin/linux/kernel/torvalds2/kernel/sched/idle.c:378 (discriminator 1)) [ 6.995411] start_secondary (/home/marvin/linux/kernel/torvalds2/arch/x86/kernel/smpboot.c:210 /home/marvin/linux/kernel/torvalds2/arch/x86/kernel/smpboot.c:294) [ 6.995422] secondary_startup_64_no_verify (/home/marvin/linux/kernel/torvalds2/arch/x86/kernel/head_64.S:433) [ 6.995476] value changed: 0x00000004 -> 0x00000002 [ 6.995629] Reported by Kernel Concurrency Sanitizer on: [ 6.995748] CPU: 9 PID: 0 Comm: swapper/9 Not tainted 6.6.0-rc2-kcsan-00003-g16819584c239-dirty #21 [ 6.995758] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023 [ 6.995765] ================================================================== Please find the complete list at: https://domac.alu.unizg.hr/~mtodorov/linux/patches/acpica_utdebug/acpi_ut_status_exit.log.xz A number of unprotected increments: acpi_gbl_nesting_level++; and conditional statements: if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } no longer work in SMP environment. Proper locking like spin_lock(&acpi_utdebug_lock); acpi_gbl_nesting_level++; spin_unlock(&acpi_utdebug_lock); and spin_lock(&acpi_utdebug_lock); if (acpi_gbl_nesting_level) { acpi_gbl_nesting_level--; } spin_unlock(&acpi_utdebug_lock); makes these data-races go away. Additionally, READ_ONCE() or WRITE_ONCE() is required with the global variable acpi_gbl_nesting_level to prevent unwanted read or write reordering or other funny stuff the optmisers do. The patch eliminates KCSAN BUG warnings. Reported-by: Mirsad Goran Todorovac <mirsad.todorovac@alu.unizg.hr> Fixes: 6be2d72b18649 ("ACPICA: Update for a few debug output statements") Fixes: bf9b448ef8430 ("ACPICA: Debug output: Do not emit function nesting level for kernel build.") Fixes: 6e875fa0480c1 ("ACPICA: Debugger: fix slight indentation issue") Fixes: ^1da177e4c3f4 ("Initial git repository build.") Cc: Jung-uk Kim <jkim@FreeBSD.org> Cc: Linus Torvalds <torvalds@linux-foundation.org> Cc: Erik Kaneda <erik.kaneda@intel.com> Cc: Bob Moore <robert.moore@intel.com> Cc: "Rafael J. Wysocki" <rafael.j.wysocki@intel.com> Cc: Len Brown <lenb@kernel.org> Cc: linux-acpi@vger.kernel.org Cc: acpica-devel@lists.linuxfoundation.org Signed-off-by: Mirsad Goran Todorovac <mirsad.todorovac@alu.unizg.hr> --- v1: Preliminary RFC version of the patch. drivers/acpi/acpica/utdebug.c | 40 ++++++++++++++++++++++++++++++----- 1 file changed, 35 insertions(+), 5 deletions(-)