Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
From:   Tommi Rantala <tommi.t.rantala@nokia.com>
Subject: perf trace --no-syscalls -e rcu:* -- garbage in output
To:     Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@redhat.com>,
        Arnaldo Carvalho de Melo <acme@kernel.org>,
        Alexander Shishkin <alexander.shishkin@linux.intel.com>,
        Jiri Olsa <jolsa@redhat.com>,
        Namhyung Kim <namhyung@kernel.org>
Cc:     linux-kernel@vger.kernel.org
Message-ID: <a67d93f2-ea36-b399-0843-8cd8fc190bfd@nokia.com>
Date:   Tue, 26 Jun 2018 15:25:41 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101
 Thunderbird/52.8.0
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Received-SPF: None (protection.outlook.com: nokia.com does not designate
 permitted sender hosts)
SpamDiagnosticOutput: 1:99
SpamDiagnosticMetadata: NSPM
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 26 Jun 2018 12:25:51.0194 (UTC)
X-MS-Exchange-CrossTenant-Network-Message-Id: 1ee0e456-acfa-4c0c-a67b-08d5db5ff534
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 5d471751-9675-428d-917b-70f44f9630b0
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DB6PR07MB3143
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Hi,

There some garbage in perf trace output, when tracing some rcu 
tracepoints (kernel is configured with CONFIG_RCU_TRACE=y).

For example in rcu:rcu_callback, instead of getting proper rcuname in 
the first "%s" here, there's garbage:

$ tail -1 /sys/kernel/debug/tracing/events/rcu/rcu_callback/format
print fmt: "%s rhp=%p func=%pf %ld/%ld", REC->rcuname, REC->rhp, 
REC->func, REC->qlen_lazy, REC->qlen

$ ./perf trace --no-syscalls -e 'rcu:*' -- sleep 1 2>&1 | od -t c

0000000                       0   .   0   0   0       r   c   u   :   r
0000020   c   u   _   c   a   l   l   b   a   c   k   : 200 351 345 215
0000040 377 377 377 377       r   h   p   =   0   x   f   f   f   f   8
0000060   d   5   5   8   f   5   b   0   1   0   0       f   u   n   c
0000100   =   f   i   l   e   _   f   r   e   e   _   r   c   u       0
0000120   /   1  \n                       0   .   0   0   8       r   c
0000140   u   :   r   c   u   _   d   y   n   t   i   c   k   : 373 217
0000160 276 215 377 377 377 377       4   0   0   0   0   0   0   0   0
0000200   0   0   0   0   0   0   0       4   0   0   0   0   0   0   0
0000220   0   0   0   0   0   0   0   2       0   x   1   d   2  \n
0000240                   0   .   0   2   3       r   c   u   :   r   c
0000260   u   _   d   y   n   t   i   c   k   : 023 220 276 215 377 377
0000300 377 377       4   0   0   0   0   0   0   0   0   0   0   0   0
0000320   0   0   2       4   0   0   0   0   0   0   0   0   0   0   0
0000340   0   0   0   0       0   x   1   d   2  \n
0000360   0   .   0   2   8       r   c   u   :   r   c   u   _   d   y
0000400   n   t   i   c   k   : 373 217 276 215 377 377 377 377       4
0000420   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
0000440   4   0   0   0   0   0   0   0   0   0   0   0   0   0   0   2
0000460       0   x   1   d   2  \n                       0   .   0   3
[...]


If I got it right, "pevent" in print_str_arg() is zero-initialized 
(pevent->long_size is zero...), causing "%s" format to produce garbage 
bytes instead of the proper string.

-Tommi