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]>
Reported-by: kernel test robot <[email protected]>
Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
---
v1 -> v2:
Moved the declaration of 'u32 nesting_level' inside #ifdef ACPI_APPLICATION ... #endif
according to the unused variable warning of the kernel test robot.
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..1faf7dc144f0 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;
}
}
@@ -136,6 +141,7 @@ acpi_debug_print(u32 requested_debug_level,
va_list args;
#ifdef ACPI_APPLICATION
int fill_count;
+ u32 nesting_level;
#endif
/* 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
On Wed, Sep 20, 2023 at 9:44 AM Mirsad Goran Todorovac
<[email protected]> wrote:
>
> KCSAN reported hundreds of instances of data-races in ACPICA like this one:
If you want to make changes in the ACPICA code, the way to do that is
to submit a pull request for the upstream ACPICA project on GitHub.
Then you can resend the Linux patch with a Link: tag pointing to the
upstream pull request.
> [ 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]>
> Reported-by: kernel test robot <[email protected]>
> Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
> ---
> v1 -> v2:
> Moved the declaration of 'u32 nesting_level' inside #ifdef ACPI_APPLICATION ... #endif
> according to the unused variable warning of the kernel test robot.
>
> 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..1faf7dc144f0 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;
> }
> }
>
> @@ -136,6 +141,7 @@ acpi_debug_print(u32 requested_debug_level,
> va_list args;
> #ifdef ACPI_APPLICATION
> int fill_count;
> + u32 nesting_level;
> #endif
>
> /* 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
>
On 9/20/23 11:53, Rafael J. Wysocki wrote:
> On Wed, Sep 20, 2023 at 9:44 AM Mirsad Goran Todorovac
> <[email protected]> wrote:
>>
>> KCSAN reported hundreds of instances of data-races in ACPICA like this one:
>
> If you want to make changes in the ACPICA code, the way to do that is
> to submit a pull request for the upstream ACPICA project on GitHub.
I think I have succeeded in this: https://github.com/acpica/acpica/pull/893
> Then you can resend the Linux patch with a Link: tag pointing to the
> upstream pull request.
Guess the linuxize.sh-d version goes into the Linux patch ...
Will do right after the testing.
Best regards,
Mirsad Todorovac
>> [ 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]>
>> Reported-by: kernel test robot <[email protected]>
>> Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
>> ---
>> v1 -> v2:
>> Moved the declaration of 'u32 nesting_level' inside #ifdef ACPI_APPLICATION ... #endif
>> according to the unused variable warning of the kernel test robot.
>>
>> 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..1faf7dc144f0 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;
>> }
>> }
>>
>> @@ -136,6 +141,7 @@ acpi_debug_print(u32 requested_debug_level,
>> va_list args;
>> #ifdef ACPI_APPLICATION
>> int fill_count;
>> + u32 nesting_level;
>> #endif
>>
>> /* 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
>>
On 9/20/2023 11:53 AM, Rafael J. Wysocki wrote:
> On Wed, Sep 20, 2023 at 9:44 AM Mirsad Goran Todorovac
> <[email protected]> wrote:
>>
>> KCSAN reported hundreds of instances of data-races in ACPICA like this one:
>
> If you want to make changes in the ACPICA code, the way to do that is
> to submit a pull request for the upstream ACPICA project on GitHub.
>
> Then you can resend the Linux patch with a Link: tag pointing to the
> upstream pull request.
I got the reply that I have to put the code into the ACPICA uniplatform
language and I just did not manage that at first attempt.
Best regards,
Mirsad Todorovac
>> [ 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]>
>> Reported-by: kernel test robot <[email protected]>
>> Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
>> ---
>> v1 -> v2:
>> Moved the declaration of 'u32 nesting_level' inside #ifdef ACPI_APPLICATION ... #endif
>> according to the unused variable warning of the kernel test robot.
>>
>> 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..1faf7dc144f0 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;
>> }
>> }
>>
>> @@ -136,6 +141,7 @@ acpi_debug_print(u32 requested_debug_level,
>> va_list args;
>> #ifdef ACPI_APPLICATION
>> int fill_count;
>> + u32 nesting_level;
>> #endif
>>
>> /* 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
>>