2013-10-08 08:42:10

by Mike Galbraith

[permalink] [raw]
Subject: perf: perf sched lat segfault - bisected

Box: Q6600

Reproducer:
perf sched record -- sleep 1
perf sched lat (boom)

The bisect winner:

marge:/usr/local/src/kernel/linux-3.x.git # git bisect good
5c5e854bc760a2e2c878df3cfcf2afa4febcd511 is the first bad commit
commit 5c5e854bc760a2e2c878df3cfcf2afa4febcd511
Author: Stephane Eranian <[email protected]>
Date: Wed Aug 21 12:10:25 2013 +0200

perf tools: Add attr->mmap2 support

This patch adds support for the new PERF_RECORD_MMAP2 record type
exposed by the kernel. This is an extended PERF_RECORD_MMAP record.

It adds for each file-backed mapping the device major, minor number and
the inode number and generation.

This triplet uniquely identifies the source of a file-backed mapping. It
can be used to detect identical virtual mappings between processes, for
instance.

The patch will prefer MMAP2 over MMAP.

Signed-off-by: Stephane Eranian <[email protected]>
Cc: Andi Kleen <[email protected]>
Cc: David Ahern <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
[ Cope with 314add6 "Change machine__findnew_thread() to set thread pid",
fix 'perf test' regression test entry affected,
use perf_missing_features.mmap2 to fallback to not using .mmap2 in older kernels,
so that new tools can work with kernels where this feature is not present ]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>

:040000 040000 2d600afbdd11b323bbcd00a4c6b50ee82a604acc d2a81503d08aeea994e203245358ae939eb5e787 M tools


git bisect start
# bad: [8b5ede69d24db939f52b47effff2f6fe1e83e08b] powerpc/irq: Don't switch to irq stack from softirq stack
git bisect bad 8b5ede69d24db939f52b47effff2f6fe1e83e08b
# good: [6e4664525b1db28f8c4e1130957f70a94c19213e] Linux 3.11
git bisect good 6e4664525b1db28f8c4e1130957f70a94c19213e
# good: [57d730924d5cc2c3e280af16a9306587c3a511db] Merge branch 'timers-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 57d730924d5cc2c3e280af16a9306587c3a511db
# good: [d8cacd3a259bf522ea5e6c4c60eba67ba22f599c] Merge tag 'virtio-next-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/rusty/linux
git bisect good d8cacd3a259bf522ea5e6c4c60eba67ba22f599c
# good: [b55ee2816ed6d8f8a00d4badab0e3642ffbac19f] Merge branch 'sched-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good b55ee2816ed6d8f8a00d4badab0e3642ffbac19f
# bad: [d45004f9947e521fc9e812bc7937ed6e0328793b] Merge tag 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mst/vhost
git bisect bad d45004f9947e521fc9e812bc7937ed6e0328793b
# bad: [9bf12df31f282e845b3dfaac1e5d5376a041da22] Merge git://git.kvack.org/~bcrl/aio-next
git bisect bad 9bf12df31f282e845b3dfaac1e5d5376a041da22
# bad: [26935fb06ee88f1188789807687c03041f3c70d9] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs
git bisect bad 26935fb06ee88f1188789807687c03041f3c70d9
# bad: [5223161dc0f5e44fbf3d5e42d23697b6796cdf4e] Merge branch 'for-next' of git://git.kernel.org/pub/scm/linux/kernel/git/cooloney/linux-leds
git bisect bad 5223161dc0f5e44fbf3d5e42d23697b6796cdf4e
# bad: [02b9735c12892e04d3e101b06e4c6d64a814f566] Merge tag 'pm+acpi-fixes-3.12-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
git bisect bad 02b9735c12892e04d3e101b06e4c6d64a814f566
# good: [0df03a30c333d67ee9b4c37f32d423624f48fe05] Merge branch 'pm-cpufreq'
git bisect good 0df03a30c333d67ee9b4c37f32d423624f48fe05
# bad: [5c5e854bc760a2e2c878df3cfcf2afa4febcd511] perf tools: Add attr->mmap2 support
git bisect bad 5c5e854bc760a2e2c878df3cfcf2afa4febcd511
# good: [41817815666e4a6f302dad1fea47cbe64cc45e40] perf trace: Check if MAP_32BIT is defined
git bisect good 41817815666e4a6f302dad1fea47cbe64cc45e40
# good: [ccf53eac2097fb47bc40875ffb22c2d10fa8c46c] perf trace: Handle perf.data files with no tracepoints
git bisect good ccf53eac2097fb47bc40875ffb22c2d10fa8c46c
# good: [e71aa28312b208a14cd87fa61e941ac8c85072f4] perf kvm: Fix sample_type manipulation
git bisect good e71aa28312b208a14cd87fa61e941ac8c85072f4
# first bad commit: [5c5e854bc760a2e2c878df3cfcf2afa4febcd511] perf tools: Add attr->mmap2 support


2013-10-08 09:23:38

by Stephane Eranian

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, Oct 8, 2013 at 10:41 AM, Mike Galbraith <[email protected]> wrote:
> Box: Q6600
>
> Reproducer:
> perf sched record -- sleep 1
> perf sched lat (boom)
>
I don't understand the test case here.
If I do this, perf sched lat complains of no trace records
and no kernel crash. Could you provide the full cmdline?


> The bisect winner:
>
> marge:/usr/local/src/kernel/linux-3.x.git # git bisect good
> 5c5e854bc760a2e2c878df3cfcf2afa4febcd511 is the first bad commit
> commit 5c5e854bc760a2e2c878df3cfcf2afa4febcd511
> Author: Stephane Eranian <[email protected]>
> Date: Wed Aug 21 12:10:25 2013 +0200
>
> perf tools: Add attr->mmap2 support
>
> This patch adds support for the new PERF_RECORD_MMAP2 record type
> exposed by the kernel. This is an extended PERF_RECORD_MMAP record.
>
> It adds for each file-backed mapping the device major, minor number and
> the inode number and generation.
>
> This triplet uniquely identifies the source of a file-backed mapping. It
> can be used to detect identical virtual mappings between processes, for
> instance.
>
> The patch will prefer MMAP2 over MMAP.
>
> Signed-off-by: Stephane Eranian <[email protected]>
> Cc: Andi Kleen <[email protected]>
> Cc: David Ahern <[email protected]>
> Cc: Ingo Molnar <[email protected]>
> Cc: Jiri Olsa <[email protected]>
> Cc: Namhyung Kim <[email protected]>
> Cc: Peter Zijlstra <[email protected]>
> Link: http://lkml.kernel.org/r/[email protected]
> [ Cope with 314add6 "Change machine__findnew_thread() to set thread pid",
> fix 'perf test' regression test entry affected,
> use perf_missing_features.mmap2 to fallback to not using .mmap2 in older kernels,
> so that new tools can work with kernels where this feature is not present ]
> Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
>
> :040000 040000 2d600afbdd11b323bbcd00a4c6b50ee82a604acc d2a81503d08aeea994e203245358ae939eb5e787 M tools
>
>
> git bisect start
> # bad: [8b5ede69d24db939f52b47effff2f6fe1e83e08b] powerpc/irq: Don't switch to irq stack from softirq stack
> git bisect bad 8b5ede69d24db939f52b47effff2f6fe1e83e08b
> # good: [6e4664525b1db28f8c4e1130957f70a94c19213e] Linux 3.11
> git bisect good 6e4664525b1db28f8c4e1130957f70a94c19213e
> # good: [57d730924d5cc2c3e280af16a9306587c3a511db] Merge branch 'timers-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
> git bisect good 57d730924d5cc2c3e280af16a9306587c3a511db
> # good: [d8cacd3a259bf522ea5e6c4c60eba67ba22f599c] Merge tag 'virtio-next-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/rusty/linux
> git bisect good d8cacd3a259bf522ea5e6c4c60eba67ba22f599c
> # good: [b55ee2816ed6d8f8a00d4badab0e3642ffbac19f] Merge branch 'sched-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
> git bisect good b55ee2816ed6d8f8a00d4badab0e3642ffbac19f
> # bad: [d45004f9947e521fc9e812bc7937ed6e0328793b] Merge tag 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mst/vhost
> git bisect bad d45004f9947e521fc9e812bc7937ed6e0328793b
> # bad: [9bf12df31f282e845b3dfaac1e5d5376a041da22] Merge git://git.kvack.org/~bcrl/aio-next
> git bisect bad 9bf12df31f282e845b3dfaac1e5d5376a041da22
> # bad: [26935fb06ee88f1188789807687c03041f3c70d9] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs
> git bisect bad 26935fb06ee88f1188789807687c03041f3c70d9
> # bad: [5223161dc0f5e44fbf3d5e42d23697b6796cdf4e] Merge branch 'for-next' of git://git.kernel.org/pub/scm/linux/kernel/git/cooloney/linux-leds
> git bisect bad 5223161dc0f5e44fbf3d5e42d23697b6796cdf4e
> # bad: [02b9735c12892e04d3e101b06e4c6d64a814f566] Merge tag 'pm+acpi-fixes-3.12-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
> git bisect bad 02b9735c12892e04d3e101b06e4c6d64a814f566
> # good: [0df03a30c333d67ee9b4c37f32d423624f48fe05] Merge branch 'pm-cpufreq'
> git bisect good 0df03a30c333d67ee9b4c37f32d423624f48fe05
> # bad: [5c5e854bc760a2e2c878df3cfcf2afa4febcd511] perf tools: Add attr->mmap2 support
> git bisect bad 5c5e854bc760a2e2c878df3cfcf2afa4febcd511
> # good: [41817815666e4a6f302dad1fea47cbe64cc45e40] perf trace: Check if MAP_32BIT is defined
> git bisect good 41817815666e4a6f302dad1fea47cbe64cc45e40
> # good: [ccf53eac2097fb47bc40875ffb22c2d10fa8c46c] perf trace: Handle perf.data files with no tracepoints
> git bisect good ccf53eac2097fb47bc40875ffb22c2d10fa8c46c
> # good: [e71aa28312b208a14cd87fa61e941ac8c85072f4] perf kvm: Fix sample_type manipulation
> git bisect good e71aa28312b208a14cd87fa61e941ac8c85072f4
> # first bad commit: [5c5e854bc760a2e2c878df3cfcf2afa4febcd511] perf tools: Add attr->mmap2 support
>
>

2013-10-08 10:14:31

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 11:23 +0200, Stephane Eranian wrote:
> On Tue, Oct 8, 2013 at 10:41 AM, Mike Galbraith <[email protected]> wrote:
> > Box: Q6600
> >
> > Reproducer:
> > perf sched record -- sleep 1
> > perf sched lat (boom)
> >
> I don't understand the test case here.
> If I do this, perf sched lat complains of no trace records
> and no kernel crash. Could you provide the full cmdline?

Hm. That was it, just like so.

marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched record -- sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.763 MB perf.data (~33348 samples) ]
marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched lat
Segmentation fault
marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #

-Mike

2013-10-08 10:21:09

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 12:14 +0200, Mike Galbraith wrote:
> On Tue, 2013-10-08 at 11:23 +0200, Stephane Eranian wrote:
> > On Tue, Oct 8, 2013 at 10:41 AM, Mike Galbraith <[email protected]> wrote:
> > > Box: Q6600
> > >
> > > Reproducer:
> > > perf sched record -- sleep 1
> > > perf sched lat (boom)
> > >
> > I don't understand the test case here.
> > If I do this, perf sched lat complains of no trace records
> > and no kernel crash. Could you provide the full cmdline?
>
> Hm. That was it, just like so.
>
> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched record -- sleep 1
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.763 MB perf.data (~33348 samples) ]
> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched lat
> Segmentation fault
> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #

commit 72f3bdf7fd1003373b454bf923d3a196bbc36600
Author: Mike Galbraith <[email protected]>
Date: Tue Oct 8 12:18:37 2013 +0200

Revert "perf tools: Add attr->mmap2 support"

This reverts commit 5c5e854bc760a2e2c878df3cfcf2afa4febcd511.

commit a8af8531d08d3edb37a7d67d1a4dc2e1f2f4da58
Author: Mike Galbraith <[email protected]>
Date: Tue Oct 8 12:18:23 2013 +0200

Revert "perf trace: Add mmap2 handler"

This reverts commit 384c671e33a7ddf905f2c60b433b9883f0e5a605.

marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched
record -- sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.647 MB perf.data (~28289 samples) ]
marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # perf sched lat
marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #

(emitted this)

---------------------------------------------------------------------------------------------------------------
Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |
---------------------------------------------------------------------------------------------------------------
kworker/3:2:383 | 0.073 ms | 1 | avg: 0.020 ms | max: 0.020 ms | max at: 7197.856052 s
sleep:24717 | 1.163 ms | 3 | avg: 0.011 ms | max: 0.022 ms | max at: 7196.884445 s
kworker/2:1:36 | 0.097 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 7197.796023 s
haveged:3547 | 0.023 ms | 2 | avg: 0.006 ms | max: 0.009 ms | max at: 7197.796345 s
rcu_sched:9 | 0.126 ms | 14 | avg: 0.006 ms | max: 0.021 ms | max at: 7196.897051 s
ntpd:4185 | 0.034 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.746409 s
kded4:4594 | 0.058 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.422130 s
evolution:15686 | 0.065 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7196.915715 s
pickup:21579 | 0.062 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.329185 s
JS Watchdog:20053 | 0.020 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.623752 s
perf:24716 | 3.330 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.885690 s
plasma-desktop:4685 | 1.632 ms | 2 | avg: 0.004 ms | max: 0.005 ms | max at: 7196.933762 s
master:4307 | 0.104 ms | 2 | avg: 0.004 ms | max: 0.005 ms | max at: 7197.329136 s
Xorg:4331 | 0.485 ms | 4 | avg: 0.003 ms | max: 0.005 ms | max at: 7197.010801 s
ksoftirqd/2:18 | 0.014 ms | 1 | avg: 0.003 ms | max: 0.003 ms | max at: 7196.897039 s
alsa-sink:5282 | 0.000 ms | 200 | avg: 0.003 ms | max: 0.003 ms | max at: 7196.905149 s
migration/3:22 | 0.000 ms | 1 | avg: 0.002 ms | max: 0.002 ms | max at: 7196.884423 s
-----------------------------------------------------------------------------------------
TOTAL: | 7.285 ms | 237 |
---------------------------------------------------

2013-10-08 10:25:19

by Stephane Eranian

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

Mike,

Ok, I missed the sched record, let me track this down.
Note that there was a second commit to fix this one
by Arnaldo. Do you also have it in your kernel?

51131c4 perf: Fix up MMAP2 buffer space reservation

I will try to reproduce your problem ASAP.


On Tue, Oct 8, 2013 at 12:20 PM, Mike Galbraith <[email protected]> wrote:
> On Tue, 2013-10-08 at 12:14 +0200, Mike Galbraith wrote:
>> On Tue, 2013-10-08 at 11:23 +0200, Stephane Eranian wrote:
>> > On Tue, Oct 8, 2013 at 10:41 AM, Mike Galbraith <[email protected]> wrote:
>> > > Box: Q6600
>> > >
>> > > Reproducer:
>> > > perf sched record -- sleep 1
>> > > perf sched lat (boom)
>> > >
>> > I don't understand the test case here.
>> > If I do this, perf sched lat complains of no trace records
>> > and no kernel crash. Could you provide the full cmdline?
>>
>> Hm. That was it, just like so.
>>
>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched record -- sleep 1
>> [ perf record: Woken up 1 times to write data ]
>> [ perf record: Captured and wrote 0.763 MB perf.data (~33348 samples) ]
>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched lat
>> Segmentation fault
>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #
>
> commit 72f3bdf7fd1003373b454bf923d3a196bbc36600
> Author: Mike Galbraith <[email protected]>
> Date: Tue Oct 8 12:18:37 2013 +0200
>
> Revert "perf tools: Add attr->mmap2 support"
>
> This reverts commit 5c5e854bc760a2e2c878df3cfcf2afa4febcd511.
>
> commit a8af8531d08d3edb37a7d67d1a4dc2e1f2f4da58
> Author: Mike Galbraith <[email protected]>
> Date: Tue Oct 8 12:18:23 2013 +0200
>
> Revert "perf trace: Add mmap2 handler"
>
> This reverts commit 384c671e33a7ddf905f2c60b433b9883f0e5a605.
>
> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched
> record -- sleep 1
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.647 MB perf.data (~28289 samples) ]
> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # perf sched lat
> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #
>
> (emitted this)
>
> ---------------------------------------------------------------------------------------------------------------
> Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |
> ---------------------------------------------------------------------------------------------------------------
> kworker/3:2:383 | 0.073 ms | 1 | avg: 0.020 ms | max: 0.020 ms | max at: 7197.856052 s
> sleep:24717 | 1.163 ms | 3 | avg: 0.011 ms | max: 0.022 ms | max at: 7196.884445 s
> kworker/2:1:36 | 0.097 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 7197.796023 s
> haveged:3547 | 0.023 ms | 2 | avg: 0.006 ms | max: 0.009 ms | max at: 7197.796345 s
> rcu_sched:9 | 0.126 ms | 14 | avg: 0.006 ms | max: 0.021 ms | max at: 7196.897051 s
> ntpd:4185 | 0.034 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.746409 s
> kded4:4594 | 0.058 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.422130 s
> evolution:15686 | 0.065 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7196.915715 s
> pickup:21579 | 0.062 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.329185 s
> JS Watchdog:20053 | 0.020 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.623752 s
> perf:24716 | 3.330 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.885690 s
> plasma-desktop:4685 | 1.632 ms | 2 | avg: 0.004 ms | max: 0.005 ms | max at: 7196.933762 s
> master:4307 | 0.104 ms | 2 | avg: 0.004 ms | max: 0.005 ms | max at: 7197.329136 s
> Xorg:4331 | 0.485 ms | 4 | avg: 0.003 ms | max: 0.005 ms | max at: 7197.010801 s
> ksoftirqd/2:18 | 0.014 ms | 1 | avg: 0.003 ms | max: 0.003 ms | max at: 7196.897039 s
> alsa-sink:5282 | 0.000 ms | 200 | avg: 0.003 ms | max: 0.003 ms | max at: 7196.905149 s
> migration/3:22 | 0.000 ms | 1 | avg: 0.002 ms | max: 0.002 ms | max at: 7196.884423 s
> -----------------------------------------------------------------------------------------
> TOTAL: | 7.285 ms | 237 |
> ---------------------------------------------------
>

2013-10-08 10:36:15

by Stephane Eranian

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

Mike,

I found the problem in perf. The tool->mmap2 pointer is NULL for sched tool.
Let me send you a patch to fix this.


On Tue, Oct 8, 2013 at 12:25 PM, Stephane Eranian <[email protected]> wrote:
> Mike,
>
> Ok, I missed the sched record, let me track this down.
> Note that there was a second commit to fix this one
> by Arnaldo. Do you also have it in your kernel?
>
> 51131c4 perf: Fix up MMAP2 buffer space reservation
>
> I will try to reproduce your problem ASAP.
>
>
> On Tue, Oct 8, 2013 at 12:20 PM, Mike Galbraith <[email protected]> wrote:
>> On Tue, 2013-10-08 at 12:14 +0200, Mike Galbraith wrote:
>>> On Tue, 2013-10-08 at 11:23 +0200, Stephane Eranian wrote:
>>> > On Tue, Oct 8, 2013 at 10:41 AM, Mike Galbraith <[email protected]> wrote:
>>> > > Box: Q6600
>>> > >
>>> > > Reproducer:
>>> > > perf sched record -- sleep 1
>>> > > perf sched lat (boom)
>>> > >
>>> > I don't understand the test case here.
>>> > If I do this, perf sched lat complains of no trace records
>>> > and no kernel crash. Could you provide the full cmdline?
>>>
>>> Hm. That was it, just like so.
>>>
>>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched record -- sleep 1
>>> [ perf record: Woken up 1 times to write data ]
>>> [ perf record: Captured and wrote 0.763 MB perf.data (~33348 samples) ]
>>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched lat
>>> Segmentation fault
>>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #
>>
>> commit 72f3bdf7fd1003373b454bf923d3a196bbc36600
>> Author: Mike Galbraith <[email protected]>
>> Date: Tue Oct 8 12:18:37 2013 +0200
>>
>> Revert "perf tools: Add attr->mmap2 support"
>>
>> This reverts commit 5c5e854bc760a2e2c878df3cfcf2afa4febcd511.
>>
>> commit a8af8531d08d3edb37a7d67d1a4dc2e1f2f4da58
>> Author: Mike Galbraith <[email protected]>
>> Date: Tue Oct 8 12:18:23 2013 +0200
>>
>> Revert "perf trace: Add mmap2 handler"
>>
>> This reverts commit 384c671e33a7ddf905f2c60b433b9883f0e5a605.
>>
>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # ./perf sched
>> record -- sleep 1
>> [ perf record: Woken up 1 times to write data ]
>> [ perf record: Captured and wrote 0.647 MB perf.data (~28289 samples) ]
>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf # perf sched lat
>> marge:/usr/local/src/kernel/linux-3.x.git/tools/perf #
>>
>> (emitted this)
>>
>> ---------------------------------------------------------------------------------------------------------------
>> Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |
>> ---------------------------------------------------------------------------------------------------------------
>> kworker/3:2:383 | 0.073 ms | 1 | avg: 0.020 ms | max: 0.020 ms | max at: 7197.856052 s
>> sleep:24717 | 1.163 ms | 3 | avg: 0.011 ms | max: 0.022 ms | max at: 7196.884445 s
>> kworker/2:1:36 | 0.097 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 7197.796023 s
>> haveged:3547 | 0.023 ms | 2 | avg: 0.006 ms | max: 0.009 ms | max at: 7197.796345 s
>> rcu_sched:9 | 0.126 ms | 14 | avg: 0.006 ms | max: 0.021 ms | max at: 7196.897051 s
>> ntpd:4185 | 0.034 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.746409 s
>> kded4:4594 | 0.058 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.422130 s
>> evolution:15686 | 0.065 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7196.915715 s
>> pickup:21579 | 0.062 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.329185 s
>> JS Watchdog:20053 | 0.020 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.623752 s
>> perf:24716 | 3.330 ms | 1 | avg: 0.004 ms | max: 0.004 ms | max at: 7197.885690 s
>> plasma-desktop:4685 | 1.632 ms | 2 | avg: 0.004 ms | max: 0.005 ms | max at: 7196.933762 s
>> master:4307 | 0.104 ms | 2 | avg: 0.004 ms | max: 0.005 ms | max at: 7197.329136 s
>> Xorg:4331 | 0.485 ms | 4 | avg: 0.003 ms | max: 0.005 ms | max at: 7197.010801 s
>> ksoftirqd/2:18 | 0.014 ms | 1 | avg: 0.003 ms | max: 0.003 ms | max at: 7196.897039 s
>> alsa-sink:5282 | 0.000 ms | 200 | avg: 0.003 ms | max: 0.003 ms | max at: 7196.905149 s
>> migration/3:22 | 0.000 ms | 1 | avg: 0.002 ms | max: 0.002 ms | max at: 7196.884423 s
>> -----------------------------------------------------------------------------------------
>> TOTAL: | 7.285 ms | 237 |
>> ---------------------------------------------------
>>

2013-10-08 10:42:04

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 12:25 +0200, Stephane Eranian wrote:
> Mike,
>
> Ok, I missed the sched record, let me track this down.
> Note that there was a second commit to fix this one
> by Arnaldo. Do you also have it in your kernel?
>
> 51131c4 perf: Fix up MMAP2 buffer space reservation

Not with that commit id, but..

commit d008d5258e9c1a1b7ee6547b8d444323aef331b3
Author: Arnaldo Carvalho de Melo <[email protected]>
Date: Tue Sep 10 10:24:05 2013 -0300

perf: Fix up MMAP2 buffer space reservation

-Mike

2013-10-08 10:50:29

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 12:36 +0200, Stephane Eranian wrote:
> Mike,
>
> I found the problem in perf. The tool->mmap2 pointer is NULL for sched tool.
> Let me send you a patch to fix this.

Ah, no need. It's probably something like so, which fixed it.

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index d8c51b2f263f..a60d14dd18e7 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -1658,6 +1658,7 @@ static struct perf_sched sched = {
.comm = perf_event__process_comm,
.lost = perf_event__process_lost,
.fork = perf_sched__process_fork_event,
+ .mmap2 = perf_event__process_mmap2,
.ordered_samples = true,
},
.cmp_pid = LIST_HEAD_INIT(sched.cmp_pid),

2013-10-08 10:51:17

by Stephane Eranian

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

Mike,

I posted the fix now. It was somewhere else. But you got the idea.
thanks for reporting the problem.

On Tue, Oct 8, 2013 at 12:50 PM, Mike Galbraith <[email protected]> wrote:
> On Tue, 2013-10-08 at 12:36 +0200, Stephane Eranian wrote:
>> Mike,
>>
>> I found the problem in perf. The tool->mmap2 pointer is NULL for sched tool.
>> Let me send you a patch to fix this.
>
> Ah, no need. It's probably something like so, which fixed it.
>
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index d8c51b2f263f..a60d14dd18e7 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -1658,6 +1658,7 @@ static struct perf_sched sched = {
> .comm = perf_event__process_comm,
> .lost = perf_event__process_lost,
> .fork = perf_sched__process_fork_event,
> + .mmap2 = perf_event__process_mmap2,
> .ordered_samples = true,
> },
> .cmp_pid = LIST_HEAD_INIT(sched.cmp_pid),
>
>

2013-10-08 10:56:56

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 12:51 +0200, Stephane Eranian wrote:
> Mike,
>
> I posted the fix now.

I tested it just in case, works fine.

-Mike

2013-10-08 10:57:16

by Stephane Eranian

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, Oct 8, 2013 at 12:56 PM, Mike Galbraith <[email protected]> wrote:
> On Tue, 2013-10-08 at 12:51 +0200, Stephane Eranian wrote:
>> Mike,
>>
>> I posted the fix now.
>
> I tested it just in case, works fine.
>
Thanks.

> -Mike
>

2013-10-08 12:17:21

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

Em Tue, Oct 08, 2013 at 10:41:55AM +0200, Mike Galbraith escreveu:
> Box: Q6600
>
> Reproducer:
> perf sched record -- sleep 1
> perf sched lat (boom)
>
> The bisect winner:

Can you try with today's tip/perf/urgent branch?

- Arnaldo

> marge:/usr/local/src/kernel/linux-3.x.git # git bisect good
> 5c5e854bc760a2e2c878df3cfcf2afa4febcd511 is the first bad commit
> commit 5c5e854bc760a2e2c878df3cfcf2afa4febcd511
> Author: Stephane Eranian <[email protected]>
> Date: Wed Aug 21 12:10:25 2013 +0200
>
> perf tools: Add attr->mmap2 support
>
> This patch adds support for the new PERF_RECORD_MMAP2 record type
> exposed by the kernel. This is an extended PERF_RECORD_MMAP record.
>
> It adds for each file-backed mapping the device major, minor number and
> the inode number and generation.
>
> This triplet uniquely identifies the source of a file-backed mapping. It
> can be used to detect identical virtual mappings between processes, for
> instance.
>
> The patch will prefer MMAP2 over MMAP.
>
> Signed-off-by: Stephane Eranian <[email protected]>
> Cc: Andi Kleen <[email protected]>
> Cc: David Ahern <[email protected]>
> Cc: Ingo Molnar <[email protected]>
> Cc: Jiri Olsa <[email protected]>
> Cc: Namhyung Kim <[email protected]>
> Cc: Peter Zijlstra <[email protected]>
> Link: http://lkml.kernel.org/r/[email protected]
> [ Cope with 314add6 "Change machine__findnew_thread() to set thread pid",
> fix 'perf test' regression test entry affected,
> use perf_missing_features.mmap2 to fallback to not using .mmap2 in older kernels,
> so that new tools can work with kernels where this feature is not present ]
> Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
>
> :040000 040000 2d600afbdd11b323bbcd00a4c6b50ee82a604acc d2a81503d08aeea994e203245358ae939eb5e787 M tools
>
>
> git bisect start
> # bad: [8b5ede69d24db939f52b47effff2f6fe1e83e08b] powerpc/irq: Don't switch to irq stack from softirq stack
> git bisect bad 8b5ede69d24db939f52b47effff2f6fe1e83e08b
> # good: [6e4664525b1db28f8c4e1130957f70a94c19213e] Linux 3.11
> git bisect good 6e4664525b1db28f8c4e1130957f70a94c19213e
> # good: [57d730924d5cc2c3e280af16a9306587c3a511db] Merge branch 'timers-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
> git bisect good 57d730924d5cc2c3e280af16a9306587c3a511db
> # good: [d8cacd3a259bf522ea5e6c4c60eba67ba22f599c] Merge tag 'virtio-next-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/rusty/linux
> git bisect good d8cacd3a259bf522ea5e6c4c60eba67ba22f599c
> # good: [b55ee2816ed6d8f8a00d4badab0e3642ffbac19f] Merge branch 'sched-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
> git bisect good b55ee2816ed6d8f8a00d4badab0e3642ffbac19f
> # bad: [d45004f9947e521fc9e812bc7937ed6e0328793b] Merge tag 'for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mst/vhost
> git bisect bad d45004f9947e521fc9e812bc7937ed6e0328793b
> # bad: [9bf12df31f282e845b3dfaac1e5d5376a041da22] Merge git://git.kvack.org/~bcrl/aio-next
> git bisect bad 9bf12df31f282e845b3dfaac1e5d5376a041da22
> # bad: [26935fb06ee88f1188789807687c03041f3c70d9] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs
> git bisect bad 26935fb06ee88f1188789807687c03041f3c70d9
> # bad: [5223161dc0f5e44fbf3d5e42d23697b6796cdf4e] Merge branch 'for-next' of git://git.kernel.org/pub/scm/linux/kernel/git/cooloney/linux-leds
> git bisect bad 5223161dc0f5e44fbf3d5e42d23697b6796cdf4e
> # bad: [02b9735c12892e04d3e101b06e4c6d64a814f566] Merge tag 'pm+acpi-fixes-3.12-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
> git bisect bad 02b9735c12892e04d3e101b06e4c6d64a814f566
> # good: [0df03a30c333d67ee9b4c37f32d423624f48fe05] Merge branch 'pm-cpufreq'
> git bisect good 0df03a30c333d67ee9b4c37f32d423624f48fe05
> # bad: [5c5e854bc760a2e2c878df3cfcf2afa4febcd511] perf tools: Add attr->mmap2 support
> git bisect bad 5c5e854bc760a2e2c878df3cfcf2afa4febcd511
> # good: [41817815666e4a6f302dad1fea47cbe64cc45e40] perf trace: Check if MAP_32BIT is defined
> git bisect good 41817815666e4a6f302dad1fea47cbe64cc45e40
> # good: [ccf53eac2097fb47bc40875ffb22c2d10fa8c46c] perf trace: Handle perf.data files with no tracepoints
> git bisect good ccf53eac2097fb47bc40875ffb22c2d10fa8c46c
> # good: [e71aa28312b208a14cd87fa61e941ac8c85072f4] perf kvm: Fix sample_type manipulation
> git bisect good e71aa28312b208a14cd87fa61e941ac8c85072f4
> # first bad commit: [5c5e854bc760a2e2c878df3cfcf2afa4febcd511] perf tools: Add attr->mmap2 support
>

2013-10-08 12:27:47

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 09:17 -0300, Arnaldo Carvalho de Melo wrote:
> Em Tue, Oct 08, 2013 at 10:41:55AM +0200, Mike Galbraith escreveu:
> > Box: Q6600
> >
> > Reproducer:
> > perf sched record -- sleep 1
> > perf sched lat (boom)
> >
> > The bisect winner:
>
> Can you try with today's tip/perf/urgent branch?

Works fine.

-Mike

2013-10-08 12:35:34

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 14:27 +0200, Mike Galbraith wrote:
> On Tue, 2013-10-08 at 09:17 -0300, Arnaldo Carvalho de Melo wrote:
> > Em Tue, Oct 08, 2013 at 10:41:55AM +0200, Mike Galbraith escreveu:
> > > Box: Q6600
> > >
> > > Reproducer:
> > > perf sched record -- sleep 1
> > > perf sched lat (boom)
> > >
> > > The bisect winner:
> >
> > Can you try with today's tip/perf/urgent branch?
>
> Works fine.

(except replay segfaults, but lord knows when that last worked)

2013-10-08 13:20:11

by David Ahern

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On 10/8/13 6:35 AM, Mike Galbraith wrote:
>
> (except replay segfaults, but lord knows when that last worked)

Fairly recently actually. I ran it early summer adding my timehist
command to builtin-sched.c. I'll take a look later today.

David

2013-10-08 13:44:44

by Mike Galbraith

[permalink] [raw]
Subject: Re: perf: perf sched lat segfault - bisected

On Tue, 2013-10-08 at 07:20 -0600, David Ahern wrote:
> On 10/8/13 6:35 AM, Mike Galbraith wrote:
> >
> > (except replay segfaults, but lord knows when that last worked)
>
> Fairly recently actually. I ran it early summer adding my timehist
> command to builtin-sched.c. I'll take a look later today.

pr_err() blows up in self_open_counters() when you hit 1024 fds. Too
many threads to play back after recording make in perf directory.
Playing a static load back works fine.

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffedbc8700 (LWP 5270)]
buffered_vfprintf (s=0x7ffff301f700, format=0x65b9e0 "Error: sys_perf_event_open() syscall returned with %d (%s)\n", args=0x7fffedbc7a90) at vfprintf.c:2265
2265 result = INTUSE(_IO_vfprintf) (hp, format, args);
(gdb) where
#0 buffered_vfprintf (s=0x7ffff301f700, format=0x65b9e0 "Error: sys_perf_event_open() syscall returned with %d (%s)\n", args=0x7fffedbc7a90) at vfprintf.c:2265
#1 0x00007ffff2cd9dbe in _IO_vfprintf_internal (s=0x7ffff301f700, format=0x65b9e0 "Error: sys_perf_event_open() syscall returned with %d (%s)\n", ap=0x7fffedbc7a90) at vfprintf.c:1291
#2 0x00007ffff2d84148 in ___vfprintf_chk (fp=0x7ffff301f700, flag=1, format=<optimized out>, ap=<optimized out>) at vfprintf_chk.c:35
#3 0x000000000048d4f8 in vfprintf (__ap=0x7fffedbc7a90, __fmt=<optimized out>, __stream=<optimized out>) at /usr/include/bits/stdio2.h:128
#4 eprintf (level=<optimized out>, fmt=<optimized out>) at util/debug.c:29
#5 0x000000000043aa10 in self_open_counters () at builtin-sched.c:441
#6 thread_func (ctx=<optimized out>) at builtin-sched.c:476
#7 0x00007ffff79b1f05 in start_thread (arg=0x7fffedbc8700) at pthread_create.c:301
#8 0x00007ffff2d7010d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb)