[BUG] trace_printk() broken?

[BUG] trace_printk() broken?

[Brian Foster]

Hi,

While poking around the bcachefs tree I ran into a problem where
trace_printk() seems to be broken. I suspect this has something to do
with the printbuf bits as it works once I back out some of those
changes.

What I observe is that a smaller printk with a fixed string seems to
work as expected, but once I add some variable args the message string
seems to get chewed up. This results in wonky formatting when reading
/sys/kernel/debug/tracing/trace and a read of the corresponding
trace_pipe file seems to spin in a livelock.

A diff is appended below to give a simple example of each case. A read
of the trace file ends up looking like this:

       fsck.ext4-535     [003] .....     6.112680: write_cache_pages:        fsck.ext4-535     [003] .....     6.113224: write_cache_pages: test
       fsck.ext4-535     [003] .....     6.117957: write_cache_pages:        fsck.ext4-535     [003] .....     6.118445: write_cache_pages: test
...

Brian

--- 8< ---

diff --git a/mm/page-writeback.c b/mm/page-writeback.c
index 032a7bf8d259..59ae76cb5756 100644
--- a/mm/page-writeback.c
+++ b/mm/page-writeback.c
@@ -2355,6 +2355,9 @@ int write_cache_pages(struct address_space *mapping,
 			if (!clear_page_dirty_for_io(page))
 				goto continue_unlock;
 
+			trace_printk("%d: ino 0x%lx\n", __LINE__, mapping->host->i_ino);
+			trace_printk("test\n");
+
 			trace_wbc_writepage(wbc, inode_to_bdi(mapping->host));
 			error = (*writepage)(page, wbc, data);
 			if (unlikely(error)) {

Re: [BUG] trace_printk() broken?

[Kent Overstreet]

On Mon, Dec 12, 2022 at 02:20:39PM -0500, Brian Foster wrote:
> Hi,
> 
> While poking around the bcachefs tree I ran into a problem where
> trace_printk() seems to be broken. I suspect this has something to do
> with the printbuf bits as it works once I back out some of those
> changes.
> 
> What I observe is that a smaller printk with a fixed string seems to
> work as expected, but once I add some variable args the message string
> seems to get chewed up. This results in wonky formatting when reading
> /sys/kernel/debug/tracing/trace and a read of the corresponding
> trace_pipe file seems to spin in a livelock.

I recently noticed it was broken too, but different symptoms - I wasn't getting
any output at all. Thanks for the reminder, I'll have a look soon.

Re: [BUG] trace_printk() broken?

[Brian Foster]

On Tue, Dec 13, 2022 at 06:32:17PM -0500, Kent Overstreet wrote:
> On Mon, Dec 12, 2022 at 02:20:39PM -0500, Brian Foster wrote:
> > Hi,
> > 
> > While poking around the bcachefs tree I ran into a problem where
> > trace_printk() seems to be broken. I suspect this has something to do
> > with the printbuf bits as it works once I back out some of those
> > changes.
> > 
> > What I observe is that a smaller printk with a fixed string seems to
> > work as expected, but once I add some variable args the message string
> > seems to get chewed up. This results in wonky formatting when reading
> > /sys/kernel/debug/tracing/trace and a read of the corresponding
> > trace_pipe file seems to spin in a livelock.
> 
> I recently noticed it was broken too, but different symptoms - I wasn't getting
> any output at all. Thanks for the reminder, I'll have a look soon.
> 

Thanks. Just to be clear, I saw no output from trace_pipe. The separate
.../tracing/trace file is where I observed the wonky event formatting.

Brian