LinuxLists.cc - [PATCH v1 1/1] acpica: use spinlocks to fix the data-races reported by the KCSAN

2023-09-20 00:07:35

Subject: [PATCH v1 1/1] acpica: use spinlocks to fix the data-races reported by the KCSAN

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 <[email protected]>
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 <[email protected]>
Cc: Linus Torvalds <[email protected]>
Cc: Erik Kaneda <[email protected]>
Cc: Bob Moore <[email protected]>
Cc: "Rafael J. Wysocki" <[email protected]>
Cc: Len Brown <[email protected]>
Cc: [email protected]
Cc: [email protected]
Signed-off-by: Mirsad Goran Todorovac <[email protected]>
---
v1:
Preliminary RFC version of the patch.

drivers/acpi/acpica/utdebug.c | 40 ++++++++++++++++++++++++++++++-----
1 file changed, 35 insertions(+), 5 deletions(-)

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 (&current_sp < acpi_gbl_lowest_stack_pointer) {
acpi_gbl_lowest_stack_pointer = &current_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);
}

/*******************************************************************************
--
2.34.1

2023-09-20 11:48:04

by kernel test robot

[permalink] [raw]

Subject: Re: [PATCH v1 1/1] acpica: use spinlocks to fix the data-races reported by the KCSAN

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/[email protected]/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/[email protected]/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 <[email protected]>
| Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/

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

--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

2023-09-20 13:50:16

by kernel test robot

[permalink] [raw]