* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 14:19 [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer Masami Hiramatsu (Google)
@ 2023-08-21 15:16 ` Masami Hiramatsu
2023-08-21 15:27 ` Steven Rostedt
2023-08-22 0:15 ` Masami Hiramatsu
` (4 subsequent siblings)
5 siblings, 1 reply; 10+ messages in thread
From: Masami Hiramatsu @ 2023-08-21 15:16 UTC (permalink / raw)
To: Masami Hiramatsu (Google)
Cc: Steven Rostedt, linux-kernel, linux-trace-kernel
On Mon, 21 Aug 2023 23:19:18 +0900
"Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
> From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
>
> ftrace user can set 0 or small number to the 'buffer_percent' for quick
> response for the ring buffer. In that case wait_on_pipe() will return
> before filling a page of the ring buffer. That is too soon for splice()
> because ring_buffer_read_page() will fail again.
> This leads unnecessary loop in tracing_buffers_splice_read().
>
> Set a minimum percentage of the buffer which is enough to fill a page to
> wait_on_pipe() to avoid this situation.
>
> Fixes: 03329f993978 ("tracing: Add tracefs file buffer_percentage")
> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
So this is what I found when I played with virtio-trace.
I think now trace-cmd has richer feature, so it can be replaced with that,
maybe what we need is a selftest that ensures trace_pipe_raw supports
splice correctly.
BTW, even with this fix, blocking splice still causes a strange behavior.
If I set '400' to buffer_size_kb (so 100 pages) and '1' to buffer_percent,
splice always returns 8192 (2 pages) to read. But I expected that should
return 4096 (1 page). This means splice() waits longer than I thought.
I think the fullfilled percentage calculation will be a bit wrong.
Thank you,
> ---
> kernel/trace/trace.c | 12 +++++++++++-
> 1 file changed, 11 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index b8870078ef58..88448e8d8214 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -8462,6 +8462,8 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
> /* did we read anything? */
> if (!spd.nr_pages) {
> long wait_index;
> + size_t nr_pages;
> + size_t full;
>
> if (ret)
> goto out;
> @@ -8472,7 +8474,15 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
>
> wait_index = READ_ONCE(iter->wait_index);
>
> - ret = wait_on_pipe(iter, iter->tr->buffer_percent);
> + /* For splice, we have to ensure at least 1 page is filled */
> + nr_pages = ring_buffer_nr_pages(iter->array_buffer->buffer, iter->cpu_file);
> + if (nr_pages * iter->tr->buffer_percent < 100) {
> + full = nr_pages + 99;
> + do_div(full, nr_pages);
> + } else
> + full = iter->tr->buffer_percent;
> +
> + ret = wait_on_pipe(iter, full);
> if (ret)
> goto out;
>
>
--
Masami Hiramatsu (Google) <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 15:16 ` Masami Hiramatsu
@ 2023-08-21 15:27 ` Steven Rostedt
2023-08-21 23:50 ` Masami Hiramatsu
0 siblings, 1 reply; 10+ messages in thread
From: Steven Rostedt @ 2023-08-21 15:27 UTC (permalink / raw)
To: Masami Hiramatsu (Google); +Cc: linux-kernel, linux-trace-kernel
On Tue, 22 Aug 2023 00:16:39 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> BTW, even with this fix, blocking splice still causes a strange behavior.
> If I set '400' to buffer_size_kb (so 100 pages) and '1' to buffer_percent,
> splice always returns 8192 (2 pages) to read. But I expected that should
> return 4096 (1 page). This means splice() waits longer than I thought.
>
> I think the fullfilled percentage calculation will be a bit wrong.
Note, the percentage is when to wake up the task. If between the wakeup and
the read/splice, another ring buffer page gets filled more, then it will
give that as well. The buffer_percent is just how long to wait, not for how
much to read.
Now if you test this with just adding enough to fill one page, and it
doesn't wake up the reader, then that would be a bug.
-- Steve
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 15:27 ` Steven Rostedt
@ 2023-08-21 23:50 ` Masami Hiramatsu
0 siblings, 0 replies; 10+ messages in thread
From: Masami Hiramatsu @ 2023-08-21 23:50 UTC (permalink / raw)
To: Steven Rostedt; +Cc: linux-kernel, linux-trace-kernel
On Mon, 21 Aug 2023 11:27:03 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:
> On Tue, 22 Aug 2023 00:16:39 +0900
> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
>
> > BTW, even with this fix, blocking splice still causes a strange behavior.
> > If I set '400' to buffer_size_kb (so 100 pages) and '1' to buffer_percent,
> > splice always returns 8192 (2 pages) to read. But I expected that should
> > return 4096 (1 page). This means splice() waits longer than I thought.
> >
> > I think the fullfilled percentage calculation will be a bit wrong.
>
> Note, the percentage is when to wake up the task. If between the wakeup and
> the read/splice, another ring buffer page gets filled more, then it will
> give that as well. The buffer_percent is just how long to wait, not for how
> much to read.
Yes, but I used the trace_marker as Zheng did for testing, and I saw the
buffer is filled more than 4096 bytes via tracefs/per_cpu/cpu*/stats.
>
> Now if you test this with just adding enough to fill one page, and it
> doesn't wake up the reader, then that would be a bug.
Yes.
Run trace_agent with 1% buffer_percent == 1 page;
# echo 400 > /sys/kernel/tracing/buffer_size_kb
# echo 1 > /sys/kernel/tracing/buffer_percent
# trace-agent &
Ready to read in the host side,
$ for i in `seq 0 7`; do cat trace-path-cpu$i.out > trace-data.$i & done
$ echo 1 > agent-ctl-path.in
Write events on per-cpu buffer in the guest
# for i in `seq 1 1000`; do echo "test event data $i" | tee /sys/kernel/tracing/trace_marker > /dev/null; done
But trace_agent doesn't wake up. The data is still there.
# grep bytes /sys/kernel/tracing/per_cpu/cpu*/stats
/sys/kernel/tracing/per_cpu/cpu0/stats:bytes: 5936
/sys/kernel/tracing/per_cpu/cpu1/stats:bytes: 5584
/sys/kernel/tracing/per_cpu/cpu2/stats:bytes: 6368
/sys/kernel/tracing/per_cpu/cpu3/stats:bytes: 4704
/sys/kernel/tracing/per_cpu/cpu4/stats:bytes: 5972
/sys/kernel/tracing/per_cpu/cpu5/stats:bytes: 5620
/sys/kernel/tracing/per_cpu/cpu6/stats:bytes: 6588
/sys/kernel/tracing/per_cpu/cpu7/stats:bytes: 3496
And write more events via trace_marker again
# for i in `seq 1001 2000`; do echo "test event data $i" | tee /sys/kernel/tracing/trace_marker > /dev/null; done
The data is read;
# grep bytes /sys/kernel/tracing/per_cpu/cpu*/stats
/sys/kernel/tracing/per_cpu/cpu0/stats:bytes: 3220
/sys/kernel/tracing/per_cpu/cpu1/stats:bytes: 3960
/sys/kernel/tracing/per_cpu/cpu2/stats:bytes: 2420
/sys/kernel/tracing/per_cpu/cpu3/stats:bytes: 2024
/sys/kernel/tracing/per_cpu/cpu4/stats:bytes: 2912
/sys/kernel/tracing/per_cpu/cpu5/stats:bytes: 1064
/sys/kernel/tracing/per_cpu/cpu6/stats:bytes: 5004
/sys/kernel/tracing/per_cpu/cpu7/stats:bytes: 2684
I think this full_hit() function is somewhat wrong.
static __always_inline bool full_hit(struct trace_buffer *buffer, int cpu, int full)
{
...
return (dirty * 100) > (full * nr_pages);
}
Ah, I also found a mistake on this patch too.
Thanks,
--
Masami Hiramatsu (Google) <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 14:19 [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer Masami Hiramatsu (Google)
2023-08-21 15:16 ` Masami Hiramatsu
@ 2023-08-22 0:15 ` Masami Hiramatsu
2023-08-22 4:00 ` kernel test robot
` (3 subsequent siblings)
5 siblings, 0 replies; 10+ messages in thread
From: Masami Hiramatsu @ 2023-08-22 0:15 UTC (permalink / raw)
To: Masami Hiramatsu (Google)
Cc: Steven Rostedt, linux-kernel, linux-trace-kernel
On Mon, 21 Aug 2023 23:19:18 +0900
"Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
> From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
>
> ftrace user can set 0 or small number to the 'buffer_percent' for quick
> response for the ring buffer. In that case wait_on_pipe() will return
> before filling a page of the ring buffer. That is too soon for splice()
> because ring_buffer_read_page() will fail again.
> This leads unnecessary loop in tracing_buffers_splice_read().
>
> Set a minimum percentage of the buffer which is enough to fill a page to
> wait_on_pipe() to avoid this situation.
>
> Fixes: 03329f993978 ("tracing: Add tracefs file buffer_percentage")
> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> ---
> kernel/trace/trace.c | 12 +++++++++++-
> 1 file changed, 11 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index b8870078ef58..88448e8d8214 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -8462,6 +8462,8 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
> /* did we read anything? */
> if (!spd.nr_pages) {
> long wait_index;
> + size_t nr_pages;
> + size_t full;
>
> if (ret)
> goto out;
> @@ -8472,7 +8474,15 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
>
> wait_index = READ_ONCE(iter->wait_index);
>
> - ret = wait_on_pipe(iter, iter->tr->buffer_percent);
> + /* For splice, we have to ensure at least 1 page is filled */
> + nr_pages = ring_buffer_nr_pages(iter->array_buffer->buffer, iter->cpu_file);
> + if (nr_pages * iter->tr->buffer_percent < 100) {
> + full = nr_pages + 99;
> + do_div(full, nr_pages);
> + } else
> + full = iter->tr->buffer_percent;
Ah I must have to take a sleep well. What I need is to ensure full >= 1.
static __always_inline bool full_hit(struct trace_buffer *buffer, int cpu, int full)
{
...
return (dirty * 100) > (full * nr_pages);
}
If dirty = 0, this always false.
But I think if full == 0, this should return true.
If dirty = 1,
- nr_pages < 100, this is always true and that is good.
- nr_pages > 100, even if full is 1 (smallest), it doesn't true. But that is OK
because dirty page number will be increased later.
- nr_pages == 100 is the corner case. I think this should be
return (dirty * 100) >= (full * nr_pages);
Let me update the patch.
Thank you,
> +
> + ret = wait_on_pipe(iter, full);
> if (ret)
> goto out;
>
>
--
Masami Hiramatsu (Google) <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 14:19 [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer Masami Hiramatsu (Google)
2023-08-21 15:16 ` Masami Hiramatsu
2023-08-22 0:15 ` Masami Hiramatsu
@ 2023-08-22 4:00 ` kernel test robot
2023-08-22 6:56 ` kernel test robot
` (2 subsequent siblings)
5 siblings, 0 replies; 10+ messages in thread
From: kernel test robot @ 2023-08-22 4:00 UTC (permalink / raw)
To: Masami Hiramatsu (Google), Steven Rostedt
Cc: oe-kbuild-all, Masami Hiramatsu, linux-kernel, linux-trace-kernel
Hi Masami,
kernel test robot noticed the following build warnings:
[auto build test WARNING on linus/master]
[also build test WARNING on v6.5-rc7 next-20230821]
[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/Masami-Hiramatsu-Google/tracing-Fix-to-avoid-wakeup-loop-in-splice-read-of-per-cpu-buffer/20230821-222307
base: linus/master
patch link: https://lore.kernel.org/r/169262755804.106231.8245792908363050528.stgit%40devnote2
patch subject: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
config: mips-allyesconfig (https://download.01.org/0day-ci/archive/20230822/202308221154.hil5JaxI-lkp@intel.com/config)
compiler: mips-linux-gcc (GCC) 12.3.0
reproduce: (https://download.01.org/0day-ci/archive/20230822/202308221154.hil5JaxI-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/202308221154.hil5JaxI-lkp@intel.com/
All warnings (new ones prefixed by >>):
In file included from arch/mips/include/asm/div64.h:89,
from include/linux/math.h:6,
from include/linux/math64.h:6,
from include/linux/time64.h:5,
from include/linux/restart_block.h:10,
from include/linux/thread_info.h:14,
from include/asm-generic/preempt.h:5,
from ./arch/mips/include/generated/asm/preempt.h:1,
from include/linux/preempt.h:79,
from include/linux/spinlock.h:56,
from include/linux/mmzone.h:8,
from include/linux/gfp.h:7,
from include/linux/mm.h:7,
from include/linux/ring_buffer.h:5,
from kernel/trace/trace.c:15:
kernel/trace/trace.c: In function 'tracing_buffers_splice_read':
>> include/asm-generic/div64.h:222:35: warning: comparison of distinct pointer types lacks a cast
222 | (void)(((typeof((n)) *)0) == ((uint64_t *)0)); \
| ^~
kernel/trace/trace.c:8481:25: note: in expansion of macro 'do_div'
8481 | do_div(full, nr_pages);
| ^~~~~~
In file included from arch/mips/include/asm/bug.h:5,
from include/linux/bug.h:5,
from include/linux/mmdebug.h:5,
from include/linux/mm.h:6:
>> include/asm-generic/div64.h:234:32: warning: right shift count >= width of type [-Wshift-count-overflow]
234 | } else if (likely(((n) >> 32) == 0)) { \
| ^~
include/linux/compiler.h:76:45: note: in definition of macro 'likely'
76 | # define likely(x) __builtin_expect(!!(x), 1)
| ^
kernel/trace/trace.c:8481:25: note: in expansion of macro 'do_div'
8481 | do_div(full, nr_pages);
| ^~~~~~
vim +222 include/asm-generic/div64.h
^1da177e4c3f41 Linus Torvalds 2005-04-16 215
^1da177e4c3f41 Linus Torvalds 2005-04-16 216 /* The unnecessary pointer compare is there
^1da177e4c3f41 Linus Torvalds 2005-04-16 217 * to check for type safety (n must be 64bit)
^1da177e4c3f41 Linus Torvalds 2005-04-16 218 */
^1da177e4c3f41 Linus Torvalds 2005-04-16 219 # define do_div(n,base) ({ \
^1da177e4c3f41 Linus Torvalds 2005-04-16 220 uint32_t __base = (base); \
^1da177e4c3f41 Linus Torvalds 2005-04-16 221 uint32_t __rem; \
^1da177e4c3f41 Linus Torvalds 2005-04-16 @222 (void)(((typeof((n)) *)0) == ((uint64_t *)0)); \
911918aa7ef6f8 Nicolas Pitre 2015-11-02 223 if (__builtin_constant_p(__base) && \
911918aa7ef6f8 Nicolas Pitre 2015-11-02 224 is_power_of_2(__base)) { \
911918aa7ef6f8 Nicolas Pitre 2015-11-02 225 __rem = (n) & (__base - 1); \
911918aa7ef6f8 Nicolas Pitre 2015-11-02 226 (n) >>= ilog2(__base); \
c747ce4706190e Geert Uytterhoeven 2021-08-11 227 } else if (__builtin_constant_p(__base) && \
461a5e51060c93 Nicolas Pitre 2015-10-30 228 __base != 0) { \
461a5e51060c93 Nicolas Pitre 2015-10-30 229 uint32_t __res_lo, __n_lo = (n); \
461a5e51060c93 Nicolas Pitre 2015-10-30 230 (n) = __div64_const32(n, __base); \
461a5e51060c93 Nicolas Pitre 2015-10-30 231 /* the remainder can be computed with 32-bit regs */ \
461a5e51060c93 Nicolas Pitre 2015-10-30 232 __res_lo = (n); \
461a5e51060c93 Nicolas Pitre 2015-10-30 233 __rem = __n_lo - __res_lo * __base; \
911918aa7ef6f8 Nicolas Pitre 2015-11-02 @234 } else if (likely(((n) >> 32) == 0)) { \
^1da177e4c3f41 Linus Torvalds 2005-04-16 235 __rem = (uint32_t)(n) % __base; \
^1da177e4c3f41 Linus Torvalds 2005-04-16 236 (n) = (uint32_t)(n) / __base; \
c747ce4706190e Geert Uytterhoeven 2021-08-11 237 } else { \
^1da177e4c3f41 Linus Torvalds 2005-04-16 238 __rem = __div64_32(&(n), __base); \
c747ce4706190e Geert Uytterhoeven 2021-08-11 239 } \
^1da177e4c3f41 Linus Torvalds 2005-04-16 240 __rem; \
^1da177e4c3f41 Linus Torvalds 2005-04-16 241 })
^1da177e4c3f41 Linus Torvalds 2005-04-16 242
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 14:19 [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer Masami Hiramatsu (Google)
` (2 preceding siblings ...)
2023-08-22 4:00 ` kernel test robot
@ 2023-08-22 6:56 ` kernel test robot
2023-08-22 8:59 ` Steven Rostedt
2023-08-23 12:18 ` kernel test robot
5 siblings, 0 replies; 10+ messages in thread
From: kernel test robot @ 2023-08-22 6:56 UTC (permalink / raw)
To: Masami Hiramatsu (Google), Steven Rostedt
Cc: llvm, oe-kbuild-all, Masami Hiramatsu, linux-kernel,
linux-trace-kernel
Hi Masami,
kernel test robot noticed the following build errors:
[auto build test ERROR on linus/master]
[also build test ERROR on v6.5-rc7 next-20230821]
[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/Masami-Hiramatsu-Google/tracing-Fix-to-avoid-wakeup-loop-in-splice-read-of-per-cpu-buffer/20230821-222307
base: linus/master
patch link: https://lore.kernel.org/r/169262755804.106231.8245792908363050528.stgit%40devnote2
patch subject: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
config: arm-randconfig-r004-20230822 (https://download.01.org/0day-ci/archive/20230822/202308221429.cY9ifC65-lkp@intel.com/config)
compiler: clang version 17.0.0 (https://github.com/llvm/llvm-project.git 4a5ac14ee968ff0ad5d2cc1ffa0299048db4c88a)
reproduce: (https://download.01.org/0day-ci/archive/20230822/202308221429.cY9ifC65-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/202308221429.cY9ifC65-lkp@intel.com/
All error/warnings (new ones prefixed by >>):
>> kernel/trace/trace.c:8481:4: warning: comparison of distinct pointer types ('typeof ((full)) *' (aka 'unsigned int *') and 'uint64_t *' (aka 'unsigned long long *')) [-Wcompare-distinct-pointer-types]
8481 | do_div(full, nr_pages);
| ^~~~~~~~~~~~~~~~~~~~~~
include/asm-generic/div64.h:222:28: note: expanded from macro 'do_div'
222 | (void)(((typeof((n)) *)0) == ((uint64_t *)0)); \
| ~~~~~~~~~~~~~~~~~~ ^ ~~~~~~~~~~~~~~~
>> kernel/trace/trace.c:8481:4: error: incompatible pointer types passing 'size_t *' (aka 'unsigned int *') to parameter of type 'uint64_t *' (aka 'unsigned long long *') [-Werror,-Wincompatible-pointer-types]
8481 | do_div(full, nr_pages);
| ^~~~~~~~~~~~~~~~~~~~~~
include/asm-generic/div64.h:238:22: note: expanded from macro 'do_div'
238 | __rem = __div64_32(&(n), __base); \
| ^~~~
arch/arm/include/asm/div64.h:24:45: note: passing argument to parameter 'n' here
24 | static inline uint32_t __div64_32(uint64_t *n, uint32_t base)
| ^
>> kernel/trace/trace.c:8481:4: warning: shift count >= width of type [-Wshift-count-overflow]
8481 | do_div(full, nr_pages);
| ^~~~~~~~~~~~~~~~~~~~~~
include/asm-generic/div64.h:234:25: note: expanded from macro 'do_div'
234 | } else if (likely(((n) >> 32) == 0)) { \
| ^ ~~
include/linux/compiler.h:76:40: note: expanded from macro 'likely'
76 | # define likely(x) __builtin_expect(!!(x), 1)
| ^
2 warnings and 1 error generated.
vim +8481 kernel/trace/trace.c
8400
8401 if (*ppos & (PAGE_SIZE - 1))
8402 return -EINVAL;
8403
8404 if (len & (PAGE_SIZE - 1)) {
8405 if (len < PAGE_SIZE)
8406 return -EINVAL;
8407 len &= PAGE_MASK;
8408 }
8409
8410 if (splice_grow_spd(pipe, &spd))
8411 return -ENOMEM;
8412
8413 again:
8414 trace_access_lock(iter->cpu_file);
8415 entries = ring_buffer_entries_cpu(iter->array_buffer->buffer, iter->cpu_file);
8416
8417 for (i = 0; i < spd.nr_pages_max && len && entries; i++, len -= PAGE_SIZE) {
8418 struct page *page;
8419 int r;
8420
8421 ref = kzalloc(sizeof(*ref), GFP_KERNEL);
8422 if (!ref) {
8423 ret = -ENOMEM;
8424 break;
8425 }
8426
8427 refcount_set(&ref->refcount, 1);
8428 ref->buffer = iter->array_buffer->buffer;
8429 ref->page = ring_buffer_alloc_read_page(ref->buffer, iter->cpu_file);
8430 if (IS_ERR(ref->page)) {
8431 ret = PTR_ERR(ref->page);
8432 ref->page = NULL;
8433 kfree(ref);
8434 break;
8435 }
8436 ref->cpu = iter->cpu_file;
8437
8438 r = ring_buffer_read_page(ref->buffer, &ref->page,
8439 len, iter->cpu_file, 1);
8440 if (r < 0) {
8441 ring_buffer_free_read_page(ref->buffer, ref->cpu,
8442 ref->page);
8443 kfree(ref);
8444 break;
8445 }
8446
8447 page = virt_to_page(ref->page);
8448
8449 spd.pages[i] = page;
8450 spd.partial[i].len = PAGE_SIZE;
8451 spd.partial[i].offset = 0;
8452 spd.partial[i].private = (unsigned long)ref;
8453 spd.nr_pages++;
8454 *ppos += PAGE_SIZE;
8455
8456 entries = ring_buffer_entries_cpu(iter->array_buffer->buffer, iter->cpu_file);
8457 }
8458
8459 trace_access_unlock(iter->cpu_file);
8460 spd.nr_pages = i;
8461
8462 /* did we read anything? */
8463 if (!spd.nr_pages) {
8464 long wait_index;
8465 size_t nr_pages;
8466 size_t full;
8467
8468 if (ret)
8469 goto out;
8470
8471 ret = -EAGAIN;
8472 if ((file->f_flags & O_NONBLOCK) || (flags & SPLICE_F_NONBLOCK))
8473 goto out;
8474
8475 wait_index = READ_ONCE(iter->wait_index);
8476
8477 /* For splice, we have to ensure at least 1 page is filled */
8478 nr_pages = ring_buffer_nr_pages(iter->array_buffer->buffer, iter->cpu_file);
8479 if (nr_pages * iter->tr->buffer_percent < 100) {
8480 full = nr_pages + 99;
> 8481 do_div(full, nr_pages);
8482 } else
8483 full = iter->tr->buffer_percent;
8484
8485 ret = wait_on_pipe(iter, full);
8486 if (ret)
8487 goto out;
8488
8489 /* No need to wait after waking up when tracing is off */
8490 if (!tracer_tracing_is_on(iter->tr))
8491 goto out;
8492
8493 /* Make sure we see the new wait_index */
8494 smp_rmb();
8495 if (wait_index != iter->wait_index)
8496 goto out;
8497
8498 goto again;
8499 }
8500
8501 ret = splice_to_pipe(pipe, &spd);
8502 out:
8503 splice_shrink_spd(&spd);
8504
8505 return ret;
8506 }
8507
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 14:19 [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer Masami Hiramatsu (Google)
` (3 preceding siblings ...)
2023-08-22 6:56 ` kernel test robot
@ 2023-08-22 8:59 ` Steven Rostedt
2023-08-22 12:51 ` Masami Hiramatsu
2023-08-23 12:18 ` kernel test robot
5 siblings, 1 reply; 10+ messages in thread
From: Steven Rostedt @ 2023-08-22 8:59 UTC (permalink / raw)
To: Masami Hiramatsu (Google); +Cc: linux-kernel, linux-trace-kernel
On Mon, 21 Aug 2023 23:19:18 +0900
"Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
> if (!spd.nr_pages) {
> long wait_index;
> + size_t nr_pages;
> + size_t full;
size_t is usually considered "long" (machine word length).
>
> if (ret)
> goto out;
> @@ -8472,7 +8474,15 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
>
> wait_index = READ_ONCE(iter->wait_index);
>
> - ret = wait_on_pipe(iter, iter->tr->buffer_percent);
> + /* For splice, we have to ensure at least 1 page is filled */
> + nr_pages = ring_buffer_nr_pages(iter->array_buffer->buffer, iter->cpu_file);
> + if (nr_pages * iter->tr->buffer_percent < 100) {
> + full = nr_pages + 99;
> + do_div(full, nr_pages);
No need for do_div() as full is not 64 bit on 32 bit machines.
That's why the kernel test robot is complaining.
-- Steve
> + } else
> + full = iter->tr->buffer_percent;
> +
> + ret = wait_on_pipe(iter, full);
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-22 8:59 ` Steven Rostedt
@ 2023-08-22 12:51 ` Masami Hiramatsu
0 siblings, 0 replies; 10+ messages in thread
From: Masami Hiramatsu @ 2023-08-22 12:51 UTC (permalink / raw)
To: Steven Rostedt; +Cc: linux-kernel, linux-trace-kernel
On Tue, 22 Aug 2023 04:59:37 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:
> On Mon, 21 Aug 2023 23:19:18 +0900
> "Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:
>
> > if (!spd.nr_pages) {
> > long wait_index;
> > + size_t nr_pages;
> > + size_t full;
>
> size_t is usually considered "long" (machine word length).
>
> >
> > if (ret)
> > goto out;
> > @@ -8472,7 +8474,15 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
> >
> > wait_index = READ_ONCE(iter->wait_index);
> >
> > - ret = wait_on_pipe(iter, iter->tr->buffer_percent);
> > + /* For splice, we have to ensure at least 1 page is filled */
> > + nr_pages = ring_buffer_nr_pages(iter->array_buffer->buffer, iter->cpu_file);
> > + if (nr_pages * iter->tr->buffer_percent < 100) {
> > + full = nr_pages + 99;
> > + do_div(full, nr_pages);
>
> No need for do_div() as full is not 64 bit on 32 bit machines.
>
> That's why the kernel test robot is complaining.
Thanks for the comment. I decided to set full = 1, maybe we don't need to set
the percent to be the page size because full_hit() checks it by the number
of dirty pages. :)
I'm testing a new one.
Thanks,
>
> -- Steve
>
> > + } else
> > + full = iter->tr->buffer_percent;
> > +
> > + ret = wait_on_pipe(iter, full);
--
Masami Hiramatsu (Google) <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
2023-08-21 14:19 [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer Masami Hiramatsu (Google)
` (4 preceding siblings ...)
2023-08-22 8:59 ` Steven Rostedt
@ 2023-08-23 12:18 ` kernel test robot
5 siblings, 0 replies; 10+ messages in thread
From: kernel test robot @ 2023-08-23 12:18 UTC (permalink / raw)
To: Masami Hiramatsu (Google), Steven Rostedt
Cc: oe-kbuild-all, Masami Hiramatsu, linux-kernel, linux-trace-kernel
Hi Masami,
kernel test robot noticed the following build warnings:
[auto build test WARNING on linus/master]
[also build test WARNING on v6.5-rc7 next-20230823]
[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/Masami-Hiramatsu-Google/tracing-Fix-to-avoid-wakeup-loop-in-splice-read-of-per-cpu-buffer/20230821-222307
base: linus/master
patch link: https://lore.kernel.org/r/169262755804.106231.8245792908363050528.stgit%40devnote2
patch subject: [PATCH] tracing: Fix to avoid wakeup loop in splice read of per-cpu buffer
config: mips-randconfig-r131-20230823 (https://download.01.org/0day-ci/archive/20230823/202308232056.401OxapL-lkp@intel.com/config)
compiler: mipsel-linux-gcc (GCC) 13.2.0
reproduce: (https://download.01.org/0day-ci/archive/20230823/202308232056.401OxapL-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/202308232056.401OxapL-lkp@intel.com/
sparse warnings: (new ones prefixed by >>)
kernel/trace/trace.c:446:28: sparse: sparse: incorrect type in argument 1 (different address spaces) @@ expected struct trace_export **list @@ got struct trace_export [noderef] __rcu ** @@
kernel/trace/trace.c:446:28: sparse: expected struct trace_export **list
kernel/trace/trace.c:446:28: sparse: got struct trace_export [noderef] __rcu **
kernel/trace/trace.c:460:33: sparse: sparse: incorrect type in argument 1 (different address spaces) @@ expected struct trace_export **list @@ got struct trace_export [noderef] __rcu ** @@
kernel/trace/trace.c:460:33: sparse: expected struct trace_export **list
kernel/trace/trace.c:460:33: sparse: got struct trace_export [noderef] __rcu **
kernel/trace/trace.c:2959:38: sparse: sparse: incorrect type in argument 1 (different address spaces) @@ expected struct event_filter *filter @@ got struct event_filter [noderef] __rcu *filter @@
kernel/trace/trace.c:2959:38: sparse: expected struct event_filter *filter
kernel/trace/trace.c:2959:38: sparse: got struct event_filter [noderef] __rcu *filter
>> kernel/trace/trace.c:8481:25: sparse: sparse: incompatible types in comparison expression (different type sizes):
>> kernel/trace/trace.c:8481:25: sparse: unsigned int *
>> kernel/trace/trace.c:8481:25: sparse: unsigned long long [usertype] *
kernel/trace/trace.c:400:9: sparse: sparse: incompatible types in comparison expression (different address spaces):
kernel/trace/trace.c:400:9: sparse: struct trace_export [noderef] __rcu *
kernel/trace/trace.c:400:9: sparse: struct trace_export *
kernel/trace/trace.c:415:9: sparse: sparse: incompatible types in comparison expression (different address spaces):
kernel/trace/trace.c:415:9: sparse: struct trace_export [noderef] __rcu *
kernel/trace/trace.c:415:9: sparse: struct trace_export *
>> kernel/trace/trace.c:8481:25: sparse: sparse: shift too big (32) for type unsigned int
vim +8481 kernel/trace/trace.c
8400
8401 if (*ppos & (PAGE_SIZE - 1))
8402 return -EINVAL;
8403
8404 if (len & (PAGE_SIZE - 1)) {
8405 if (len < PAGE_SIZE)
8406 return -EINVAL;
8407 len &= PAGE_MASK;
8408 }
8409
8410 if (splice_grow_spd(pipe, &spd))
8411 return -ENOMEM;
8412
8413 again:
8414 trace_access_lock(iter->cpu_file);
8415 entries = ring_buffer_entries_cpu(iter->array_buffer->buffer, iter->cpu_file);
8416
8417 for (i = 0; i < spd.nr_pages_max && len && entries; i++, len -= PAGE_SIZE) {
8418 struct page *page;
8419 int r;
8420
8421 ref = kzalloc(sizeof(*ref), GFP_KERNEL);
8422 if (!ref) {
8423 ret = -ENOMEM;
8424 break;
8425 }
8426
8427 refcount_set(&ref->refcount, 1);
8428 ref->buffer = iter->array_buffer->buffer;
8429 ref->page = ring_buffer_alloc_read_page(ref->buffer, iter->cpu_file);
8430 if (IS_ERR(ref->page)) {
8431 ret = PTR_ERR(ref->page);
8432 ref->page = NULL;
8433 kfree(ref);
8434 break;
8435 }
8436 ref->cpu = iter->cpu_file;
8437
8438 r = ring_buffer_read_page(ref->buffer, &ref->page,
8439 len, iter->cpu_file, 1);
8440 if (r < 0) {
8441 ring_buffer_free_read_page(ref->buffer, ref->cpu,
8442 ref->page);
8443 kfree(ref);
8444 break;
8445 }
8446
8447 page = virt_to_page(ref->page);
8448
8449 spd.pages[i] = page;
8450 spd.partial[i].len = PAGE_SIZE;
8451 spd.partial[i].offset = 0;
8452 spd.partial[i].private = (unsigned long)ref;
8453 spd.nr_pages++;
8454 *ppos += PAGE_SIZE;
8455
8456 entries = ring_buffer_entries_cpu(iter->array_buffer->buffer, iter->cpu_file);
8457 }
8458
8459 trace_access_unlock(iter->cpu_file);
8460 spd.nr_pages = i;
8461
8462 /* did we read anything? */
8463 if (!spd.nr_pages) {
8464 long wait_index;
8465 size_t nr_pages;
8466 size_t full;
8467
8468 if (ret)
8469 goto out;
8470
8471 ret = -EAGAIN;
8472 if ((file->f_flags & O_NONBLOCK) || (flags & SPLICE_F_NONBLOCK))
8473 goto out;
8474
8475 wait_index = READ_ONCE(iter->wait_index);
8476
8477 /* For splice, we have to ensure at least 1 page is filled */
8478 nr_pages = ring_buffer_nr_pages(iter->array_buffer->buffer, iter->cpu_file);
8479 if (nr_pages * iter->tr->buffer_percent < 100) {
8480 full = nr_pages + 99;
> 8481 do_div(full, nr_pages);
8482 } else
8483 full = iter->tr->buffer_percent;
8484
8485 ret = wait_on_pipe(iter, full);
8486 if (ret)
8487 goto out;
8488
8489 /* No need to wait after waking up when tracing is off */
8490 if (!tracer_tracing_is_on(iter->tr))
8491 goto out;
8492
8493 /* Make sure we see the new wait_index */
8494 smp_rmb();
8495 if (wait_index != iter->wait_index)
8496 goto out;
8497
8498 goto again;
8499 }
8500
8501 ret = splice_to_pipe(pipe, &spd);
8502 out:
8503 splice_shrink_spd(&spd);
8504
8505 return ret;
8506 }
8507
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
^ permalink raw reply [flat|nested] 10+ messages in thread