Hi, steve,
after some operations on file 'tracing_cpumask' and 'snapshot', trace
ring buffer can no longer record anything. This series contain a patch
to fix it and a constrived testcase to reproduce it.
I think the reproduction testcase is useful to help others to check if
their version has this problem and verify the bugfix. However, currently
in "tools/testing/selftests/ftrace/test.d", there seems no appropriate
subdirectory to put this kind reproductions.
So I now put the testcase in "00basic" because it is basicly simple. Or
would there be a new directory to collect simple reproduction testcases?
Zheng Yejian (2):
tracing: Fix cpu buffers unavailable due to 'record_disabled' messed
selftests/ftrace: Add a basic testcase for snapshot
kernel/trace/trace.c | 2 ++
.../ftrace/test.d/00basic/snapshot1.tc | 17 +++++++++++++++++
2 files changed, 19 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/00basic/snapshot1.tc
--
2.25.1
Trace ring buffer can no longer record anything after executing like:
# cd /sys/kernel/tracing
# cat tracing_cpumask
fff
# echo 0 > tracing_cpumask
# echo 1 > snapshot
# echo fff > tracing_cpumask
# echo "hello world" > trace_marker
-bash: echo: write error: Bad file descriptor
The root cause is that:
1. After `echo 0 > tracing_cpumask`, 'record_disabled' of cpu buffers
in 'tr->array_buffer.buffer' became 1 (see tracing_set_cpumask());
2. After `echo 1 > snapshot`, 'tr->array_buffer.buffer' is swapped
with 'tr->max_buffer.buffer', then the 'record_disabled' became 0
(see update_max_tr());
3. After `echo fff > tracing_cpumask`, the 'record_disabled' become -1;
Then array_buffer and max_buffer are both unavailable due to value of
'record_disabled' is not 0.
To fix it, enable or disable both array_buffer and max_buffer at the same
time in tracing_set_cpumask().
Fixes: 71babb2705e2 ("tracing: change CPU ring buffer state from tracing_cpumask")
Signed-off-by: Zheng Yejian <[email protected]>
---
kernel/trace/trace.c | 2 ++
1 file changed, 2 insertions(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index b8870078ef58..691ec4d4cd19 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5277,11 +5277,13 @@ int tracing_set_cpumask(struct trace_array *tr,
!cpumask_test_cpu(cpu, tracing_cpumask_new)) {
atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
+ ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
}
if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
cpumask_test_cpu(cpu, tracing_cpumask_new)) {
atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
+ ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
}
}
arch_spin_unlock(&tr->max_lock);
--
2.25.1
This testcase is constrived to reproduce a problem that the cpu buffers
become unavailable which is due to 'record_disabled' of array_buffer and
max_buffer being messed up.
Local test result after bugfix:
# ./ftracetest test.d/00basic/snapshot1.tc
=== Ftrace unit tests ===
[1] Snapshot and tracing_cpumask [PASS]
[2] (instance) Snapshot and tracing_cpumask [PASS]
# of passed: 2
# of failed: 0
# of unresolved: 0
# of untested: 0
# of unsupported: 0
# of xfailed: 0
# of undefined(test bug): 0
Signed-off-by: Zheng Yejian <[email protected]>
---
.../ftrace/test.d/00basic/snapshot1.tc | 17 +++++++++++++++++
1 file changed, 17 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/00basic/snapshot1.tc
diff --git a/tools/testing/selftests/ftrace/test.d/00basic/snapshot1.tc b/tools/testing/selftests/ftrace/test.d/00basic/snapshot1.tc
new file mode 100644
index 000000000000..0d9b84b3adc3
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/00basic/snapshot1.tc
@@ -0,0 +1,17 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: Snapshot and tracing_cpumask
+# requires: trace_marker tracing_cpumask snapshot
+# flags: instance
+
+# This testcase is constrived to reproduce a problem that the cpu buffers
+# become unavailable which is due to 'record_disabled' of array_buffer and
+# max_buffer being messed up.
+
+ORIG_CPUMASK=`cat tracing_cpumask`
+echo 0 > tracing_cpumask
+echo 1 > snapshot
+echo ${ORIG_CPUMASK} > tracing_cpumask
+echo "test input 1" > trace_marker
+grep -q "test input 1" trace
+exit 0
--
2.25.1
On Sat, 5 Aug 2023 00:41:13 +0800
kernel test robot <[email protected]> wrote:
> 5276 if (cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
> 5277 !cpumask_test_cpu(cpu, tracing_cpumask_new)) {
> 5278 atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
> 5279 ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
> > 5280 ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
The access to max_buffer requires a:
#ifdef CONFIG_TRACER_MAX_TRACE
Around them.
-- Steve
> 5281 }
> 5282 if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
> 5283 cpumask_test_cpu(cpu, tracing_cpumask_new)) {
> 5284 atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
> 5285 ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
> 5286 ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
> 5287 }
> 5288 }
> 5289 arch_spin_unlock(&tr->max_lock);
Hi Zheng,
kernel test robot noticed the following build errors:
[auto build test ERROR on linus/master]
[cannot apply to rostedt-trace/for-next-urgent]
[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/Zheng-Yejian/tracing-Fix-cpu-buffers-unavailable-due-to-record_disabled-messed/20230804-204751
base: linus/master
patch link: https://lore.kernel.org/r/20230804124549.2562977-2-zhengyejian1%40huawei.com
patch subject: [PATCH 1/2] tracing: Fix cpu buffers unavailable due to 'record_disabled' messed
config: i386-randconfig-r025-20230731 (https://download.01.org/0day-ci/archive/20230805/[email protected]/config)
compiler: clang version 16.0.4 (https://github.com/llvm/llvm-project.git ae42196bc493ffe877a7e3dff8be32035dea4d07)
reproduce: (https://download.01.org/0day-ci/archive/20230805/[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 errors (new ones prefixed by >>):
>> kernel/trace/trace.c:5280:39: error: no member named 'max_buffer' in 'struct trace_array'
ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
~~ ^
kernel/trace/trace.c:5286:38: error: no member named 'max_buffer' in 'struct trace_array'
ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
~~ ^
2 errors generated.
vim +5280 kernel/trace/trace.c
5260
5261 int tracing_set_cpumask(struct trace_array *tr,
5262 cpumask_var_t tracing_cpumask_new)
5263 {
5264 int cpu;
5265
5266 if (!tr)
5267 return -EINVAL;
5268
5269 local_irq_disable();
5270 arch_spin_lock(&tr->max_lock);
5271 for_each_tracing_cpu(cpu) {
5272 /*
5273 * Increase/decrease the disabled counter if we are
5274 * about to flip a bit in the cpumask:
5275 */
5276 if (cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
5277 !cpumask_test_cpu(cpu, tracing_cpumask_new)) {
5278 atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
5279 ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
> 5280 ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
5281 }
5282 if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
5283 cpumask_test_cpu(cpu, tracing_cpumask_new)) {
5284 atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
5285 ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
5286 ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
5287 }
5288 }
5289 arch_spin_unlock(&tr->max_lock);
5290 local_irq_enable();
5291
5292 cpumask_copy(tr->tracing_cpumask, tracing_cpumask_new);
5293
5294 return 0;
5295 }
5296
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
Hi Zheng,
kernel test robot noticed the following build errors:
[auto build test ERROR on linus/master]
[also build test ERROR on rostedt-trace/for-next v6.5-rc4 next-20230804]
[cannot apply to rostedt-trace/for-next-urgent]
[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/Zheng-Yejian/tracing-Fix-cpu-buffers-unavailable-due-to-record_disabled-messed/20230804-204751
base: linus/master
patch link: https://lore.kernel.org/r/20230804124549.2562977-2-zhengyejian1%40huawei.com
patch subject: [PATCH 1/2] tracing: Fix cpu buffers unavailable due to 'record_disabled' messed
config: i386-defconfig (https://download.01.org/0day-ci/archive/20230805/[email protected]/config)
compiler: gcc-12 (Debian 12.2.0-14) 12.2.0
reproduce: (https://download.01.org/0day-ci/archive/20230805/[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 errors (new ones prefixed by >>):
kernel/trace/trace.c: In function 'tracing_set_cpumask':
>> kernel/trace/trace.c:5280:60: error: 'struct trace_array' has no member named 'max_buffer'; did you mean 'array_buffer'?
5280 | ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
| ^~~~~~~~~~
| array_buffer
kernel/trace/trace.c:5286:59: error: 'struct trace_array' has no member named 'max_buffer'; did you mean 'array_buffer'?
5286 | ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
| ^~~~~~~~~~
| array_buffer
vim +5280 kernel/trace/trace.c
5260
5261 int tracing_set_cpumask(struct trace_array *tr,
5262 cpumask_var_t tracing_cpumask_new)
5263 {
5264 int cpu;
5265
5266 if (!tr)
5267 return -EINVAL;
5268
5269 local_irq_disable();
5270 arch_spin_lock(&tr->max_lock);
5271 for_each_tracing_cpu(cpu) {
5272 /*
5273 * Increase/decrease the disabled counter if we are
5274 * about to flip a bit in the cpumask:
5275 */
5276 if (cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
5277 !cpumask_test_cpu(cpu, tracing_cpumask_new)) {
5278 atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
5279 ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
> 5280 ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
5281 }
5282 if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
5283 cpumask_test_cpu(cpu, tracing_cpumask_new)) {
5284 atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
5285 ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
5286 ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
5287 }
5288 }
5289 arch_spin_unlock(&tr->max_lock);
5290 local_irq_enable();
5291
5292 cpumask_copy(tr->tracing_cpumask, tracing_cpumask_new);
5293
5294 return 0;
5295 }
5296
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
On 2023/8/5 00:51, Steven Rostedt wrote:
> On Sat, 5 Aug 2023 00:41:13 +0800
> kernel test robot <[email protected]> wrote:
>
>> 5276 if (cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
>> 5277 !cpumask_test_cpu(cpu, tracing_cpumask_new)) {
>> 5278 atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
>> 5279 ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
>>> 5280 ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
>
> The access to max_buffer requires a:
>
> #ifdef CONFIG_TRACER_MAX_TRACE
>
> Around them.
>
> -- Steve
Thanks, Steve, I'll add it in v2.
-- Zheng Yejian
>
>> 5281 }
>> 5282 if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
>> 5283 cpumask_test_cpu(cpu, tracing_cpumask_new)) {
>> 5284 atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
>> 5285 ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
>> 5286 ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
>> 5287 }
>> 5288 }
>> 5289 arch_spin_unlock(&tr->max_lock);
>
Hi Zheng,
kernel test robot noticed the following build errors:
[auto build test ERROR on linus/master]
[also build test ERROR on rostedt-trace/for-next v6.5-rc4 next-20230804]
[cannot apply to rostedt-trace/for-next-urgent]
[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/Zheng-Yejian/tracing-Fix-cpu-buffers-unavailable-due-to-record_disabled-messed/20230804-204751
base: linus/master
patch link: https://lore.kernel.org/r/20230804124549.2562977-2-zhengyejian1%40huawei.com
patch subject: [PATCH 1/2] tracing: Fix cpu buffers unavailable due to 'record_disabled' messed
config: x86_64-defconfig (https://download.01.org/0day-ci/archive/20230805/[email protected]/config)
compiler: gcc-12 (Debian 12.2.0-14) 12.2.0
reproduce: (https://download.01.org/0day-ci/archive/20230805/[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 errors (new ones prefixed by >>):
kernel/trace/trace.c: In function 'tracing_set_cpumask':
>> kernel/trace/trace.c:5280:60: error: 'struct trace_array' has no member named 'max_buffer'; did you mean 'array_buffer'?
5280 | ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
| ^~~~~~~~~~
| array_buffer
kernel/trace/trace.c:5286:59: error: 'struct trace_array' has no member named 'max_buffer'; did you mean 'array_buffer'?
5286 | ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
| ^~~~~~~~~~
| array_buffer
vim +5280 kernel/trace/trace.c
5260
5261 int tracing_set_cpumask(struct trace_array *tr,
5262 cpumask_var_t tracing_cpumask_new)
5263 {
5264 int cpu;
5265
5266 if (!tr)
5267 return -EINVAL;
5268
5269 local_irq_disable();
5270 arch_spin_lock(&tr->max_lock);
5271 for_each_tracing_cpu(cpu) {
5272 /*
5273 * Increase/decrease the disabled counter if we are
5274 * about to flip a bit in the cpumask:
5275 */
5276 if (cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
5277 !cpumask_test_cpu(cpu, tracing_cpumask_new)) {
5278 atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
5279 ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
> 5280 ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
5281 }
5282 if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
5283 cpumask_test_cpu(cpu, tracing_cpumask_new)) {
5284 atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
5285 ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
5286 ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
5287 }
5288 }
5289 arch_spin_unlock(&tr->max_lock);
5290 local_irq_enable();
5291
5292 cpumask_copy(tr->tracing_cpumask, tracing_cpumask_new);
5293
5294 return 0;
5295 }
5296
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
On 2023/8/5 09:15, kernel test robot wrote:
> Hi Zheng,
>
> kernel test robot noticed the following build errors:
>
> [auto build test ERROR on linus/master]
> [also build test ERROR on rostedt-trace/for-next v6.5-rc4 next-20230804]
> [cannot apply to rostedt-trace/for-next-urgent]
> [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/Zheng-Yejian/tracing-Fix-cpu-buffers-unavailable-due-to-record_disabled-messed/20230804-204751
> base: linus/master
> patch link: https://lore.kernel.org/r/20230804124549.2562977-2-zhengyejian1%40huawei.com
> patch subject: [PATCH 1/2] tracing: Fix cpu buffers unavailable due to 'record_disabled' messed
> config: x86_64-defconfig (https://download.01.org/0day-ci/archive/20230805/[email protected]/config)
> compiler: gcc-12 (Debian 12.2.0-14) 12.2.0
> reproduce: (https://download.01.org/0day-ci/archive/20230805/[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 errors (new ones prefixed by >>):
>
> kernel/trace/trace.c: In function 'tracing_set_cpumask':
>>> kernel/trace/trace.c:5280:60: error: 'struct trace_array' has no member named 'max_buffer'; did you mean 'array_buffer'?
> 5280 | ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
> | ^~~~~~~~~~
> | array_buffer
> kernel/trace/trace.c:5286:59: error: 'struct trace_array' has no member named 'max_buffer'; did you mean 'array_buffer'?
> 5286 | ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
> | ^~~~~~~~~~
> | array_buffer
>
Thank you, robot!
I'll fix it in v2 soon.
>
> vim +5280 kernel/trace/trace.c
>
> 5260
> 5261 int tracing_set_cpumask(struct trace_array *tr,
> 5262 cpumask_var_t tracing_cpumask_new)
> 5263 {
> 5264 int cpu;
> 5265
> 5266 if (!tr)
> 5267 return -EINVAL;
> 5268
> 5269 local_irq_disable();
> 5270 arch_spin_lock(&tr->max_lock);
> 5271 for_each_tracing_cpu(cpu) {
> 5272 /*
> 5273 * Increase/decrease the disabled counter if we are
> 5274 * about to flip a bit in the cpumask:
> 5275 */
> 5276 if (cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
> 5277 !cpumask_test_cpu(cpu, tracing_cpumask_new)) {
> 5278 atomic_inc(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
> 5279 ring_buffer_record_disable_cpu(tr->array_buffer.buffer, cpu);
>> 5280 ring_buffer_record_disable_cpu(tr->max_buffer.buffer, cpu);
> 5281 }
> 5282 if (!cpumask_test_cpu(cpu, tr->tracing_cpumask) &&
> 5283 cpumask_test_cpu(cpu, tracing_cpumask_new)) {
> 5284 atomic_dec(&per_cpu_ptr(tr->array_buffer.data, cpu)->disabled);
> 5285 ring_buffer_record_enable_cpu(tr->array_buffer.buffer, cpu);
> 5286 ring_buffer_record_enable_cpu(tr->max_buffer.buffer, cpu);
> 5287 }
> 5288 }
> 5289 arch_spin_unlock(&tr->max_lock);
> 5290 local_irq_enable();
> 5291
> 5292 cpumask_copy(tr->tracing_cpumask, tracing_cpumask_new);
> 5293
> 5294 return 0;
> 5295 }
> 5296
>