Skip to contentSkip to conversation

perf/record: make perf_event__synthesize_mmap_events() scale

PATCH Superseded Stephane Eranian 5 participants 9 messages Mar 15, 2017 – Mar 16, 2017 perf events

lore
Share & tools
lore

Stephane Eranian

author
#0 lore raw

PATCH 1/1 perf/record: make perf_event__synthesize_mmap_events() scale

This patch significantly improves the execution time of
perf_event__synthesize_mmap_events() when running perf record
on systems where processes have lots of threads. It just happens
that cat /proc/pid/maps support uses a O(N^2) algorithm to generate
each map line in the maps file. If you have 1000 threads, then you have
necessarily 1000 stacks. For each vma, you need to check if it corresponds
to a thread's stack. With a large number of threads, this can take a very long time. I have seen latencies >> 10mn.

As of today, perf does not use the fact that a mapping is a stack, therefore we can work around the issue by using /proc/pid/tasks/pid/maps. This entry does not try to map a vma to stack and is thus much faster with no loss of functonality.

The proc-map-timeout logic is kept in case user still want some uppre limit.

Signed-off-by Stephane Eranian <[email protected]>
---
 tools/perf/util/event.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/util/event.c +2 -2
index 4ea7ce7..b137566 100644
@@ -255,8 +255,8 @@ int perf_event__synthesize_mmap_events(struct perf_tool *tool,
 	if (machine__is_default_guest(machine))
 		return 0;
 
-	snprintf(filename, sizeof(filename), "%s/proc/%d/maps",
-		 machine->root_dir, pid);
+	snprintf(filename, sizeof(filename), "%s/proc/%d/tasks/%d/maps",
+		 machine->root_dir, pid, pid);
 
 	fp = fopen(filename, "r");
 	if (fp == NULL) {
Signature · 1 line
2.5.0
Acked-by on v1 1/1
#1 lore raw
Quoted 38 lines · Stephane Eranian

This patch significantly improves the execution time of
perf_event__synthesize_mmap_events() when running perf record
on systems where processes have lots of threads. It just happens
that cat /proc/pid/maps support uses a O(N^2) algorithm to generate
each map line in the maps file. If you have 1000 threads, then you have
necessarily 1000 stacks. For each vma, you need to check if it corresponds
to a thread's stack. With a large number of threads, this can take a very long time. I have seen latencies >> 10mn.

As of today, perf does not use the fact that a mapping is a stack, therefore we can work around the issue by using /proc/pid/tasks/pid/maps. This entry does not try to map a vma to stack and is thus much faster with no loss of functonality.

The proc-map-timeout logic is kept in case user still want some uppre limit.

Signed-off-by Stephane Eranian <[email protected]>
---
 tools/perf/util/event.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/util/event.c +2 -2
index 4ea7ce7..b137566 100644
@@ -255,8 +255,8 @@ int perf_event__synthesize_mmap_events(struct perf_tool *tool,
 	if (machine__is_default_guest(machine))
 		return 0;
 
-	snprintf(filename, sizeof(filename), "%s/proc/%d/maps",
-		 machine->root_dir, pid);
+	snprintf(filename, sizeof(filename), "%s/proc/%d/tasks/%d/maps",
+		 machine->root_dir, pid, pid);
 
 	fp = fopen(filename, "r");
 	if (fp == NULL) {
Signature · 1 line
2.5.0

nice..

Acked-by Jiri Olsa <[email protected]>

thanks,
jirka

Acked-by Thomas Gleixner on v1 1/1
#2 lore raw
In reply to Stephane Eranian

Em Tue, Mar 14, 2017 at 11:57:21PM -0700, Stephane Eranian escreveu:

Quoted 25 lines

This patch significantly improves the execution time of
perf_event__synthesize_mmap_events() when running perf record
on systems where processes have lots of threads. It just happens
that cat /proc/pid/maps support uses a O(N^2) algorithm to generate
each map line in the maps file. If you have 1000 threads, then you have
necessarily 1000 stacks. For each vma, you need to check if it corresponds
to a thread's stack. With a large number of threads, this can take a very long time. I have seen latencies >> 10mn.

As of today, perf does not use the fact that a mapping is a stack, therefore we can work around the issue by using /proc/pid/tasks/pid/maps. This entry does not try to map a vma to stack and is thus much faster with no loss of functonality.

The proc-map-timeout logic is kept in case user still want some uppre limit.

Signed-off-by Stephane Eranian <[email protected]>
---
 tools/perf/util/event.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/util/event.c +0 -0
index 4ea7ce7..b137566 100644

tools/perf/util/event.c int perf_event__synthesize_mmap_events(struct perf_tool *tool, · line 259

Quoted 7 lines
tools/perf/util/event.c +2 -2
@@ -255,8 +255,8 @@ int perf_event__synthesize_mmap_events(struct perf_tool *tool,
 	if (machine__is_default_guest(machine))
 		return 0;
 
-	snprintf(filename, sizeof(filename), "%s/proc/%d/maps",
-		 machine->root_dir, pid);
+	snprintf(filename, sizeof(filename), "%s/proc/%d/tasks/%d/maps",
+		 machine->root_dir, pid, pid);

Humm...

[root@jouet ~]# ps -C firefox -L
PID LWP TTY TIME CMD

25023 25023 tty2     01:32:10 firefox
25023 25048 tty2     00:00:00 gmain
25023 25049 tty2     00:00:00 gdbus
25023 25056 tty2     00:00:00 Gecko_IOThread
25023 25058 tty2     00:00:00 Link Monitor
25023 25059 tty2     00:03:52 Socket Thread
25023 25060 tty2     00:00:00 JS Watchdog
25023 25061 tty2     00:00:12 JS Helper
25023 25062 tty2     00:00:12 JS Helper
25023 25063 tty2     00:00:13 JS Helper
25023 25064 tty2     00:00:12 JS Helper
25023 25065 tty2     00:00:13 JS Helper
25023 25066 tty2     00:00:12 JS Helper
25023 25067 tty2     00:00:13 JS Helper
25023 25068 tty2     00:00:13 JS Helper
25023 25069 tty2     00:00:00 Hang Monitor
25023 25070 tty2     00:00:00 BgHangManager
25023 25117 tty2     00:00:12 Cache2 I/O
25023 25118 tty2     00:05:37 Timer
25023 25146 tty2     00:00:00 DataStorage
25023 25150 tty2     00:00:00 GMPThread
25023 25152 tty2     00:04:12 Compositor
25023 25156 tty2     00:00:02 ImgDecoder #1
25023 25157 tty2     00:00:02 ImgDecoder #2
25023 25158 tty2     00:00:02 ImgDecoder #3
25023 25159 tty2     00:00:00 ImageIO
25023 25160 tty2     00:02:26 SoftwareVsyncTh
25023 25202 tty2     00:00:00 HTML5 Parser
25023 25204 tty2     00:00:00 IPDL Background
25023 25212 tty2     00:00:22 DOM Worker
25023 25219 tty2     00:00:23 URL Classifier
25023 25220 tty2     00:00:05 ImageBridgeChil
25023 25221 tty2     00:00:04 mozStorage #1
25023 25222 tty2     00:00:00 Proxy R~olution
25023 25223 tty2     00:00:00 DataStorage
25023 25234 tty2     00:00:00 Cache I/O
25023 25235 tty2     00:00:01 mozStorage #2
25023 25236 tty2     00:00:00 mozStorage #3
25023 25252 tty2     00:00:20 DOM Worker
25023 25256 tty2     00:00:00 mozStorage #4
25023 25257 tty2     00:00:00 localStorage DB
25023 25260 tty2     00:00:00 mozStorage #5
25023  2066 tty2     00:00:19 DOM Worker
25023  5988 tty2     00:00:00 threaded-ml
25023  6757 tty2     00:00:00 firefox
25023  6999 tty2     00:00:00 mozStorage #6
25023 19239 tty2     00:00:02 mozStorage #7
25023 12038 tty2     00:00:05 threaded-ml
25023 19301 tty2     00:00:00 firefox

[root@jouet ~]#

[root@jouet ~]# file /proc/25023/tasks
/proc/25023/tasks: cannot open `/proc/25023/tasks' (No such file or directory) [root@jouet ~]#

But...

[root@jouet ~]# file /proc/25023/task
/proc/25023/task: directory
[root@jouet ~]# wc -l /proc/25023/task/25023/maps
1200 /proc/25023/task/25023/maps
[root@jouet ~]# wc -l /proc/25023/task/25048/maps
1201 /proc/25023/task/25048/maps
[root@jouet ~]# wc -l /proc/25048/task/25048/maps
1201 /proc/25048/task/25048/maps
[root@jouet ~]#

[acme@jouet linux]$ grep \"tasks\" fs/proc/*.c
[acme@jouet linux]$ grep \"task\" fs/proc/*.c
fs/proc/base.c: DIR("task", S_IRUGO|S_IXUGO, proc_task_inode_operations, proc_task_operations),
fs/proc/base.c: name.name = "task";
[acme@jouet linux]$

These end up mapping to the later of these two:

const struct file_operations proc_pid_maps_operations = {

        .open           = pid_maps_open,
        .read           = seq_read,
        .llseek         = seq_lseek,
        .release        = proc_map_release,

};

const struct file_operations proc_tid_maps_operations = {

        .open           = tid_maps_open,
        .read           = seq_read, 
        .llseek         = seq_lseek,
        .release        = proc_map_release,

};

Which ends up going down to:

show_map_vma(struct seq_file *m, struct vm_area_struct *vma, int is_pid)

with that is_pid respectively true and false, but then show_map_vma() doesn't use 'is_pid' at all :-\

/me scratches head, what am I missing?

The following commit, that appeared circa v4.9-rc2. So, fixing up the "tasks" -> "tasks" we end up with something safe and that avoids this by now non-existing problem, on older kernels, ok?

commit b18cb64ead400c01bf1580eeba330ace51f8087d

Author: Andy Lutomirski <[email protected]>
Date:   Fri Sep 30 10:58:57 2016 -0700

fs/proc: Stop trying to report thread stacks

This reverts more of:

b76437579d13 ("procfs: mark thread stack correctly in proc/<pid>/maps")

... which was partially reverted by:

65376df58217 ("proc: revert /proc/<pid>/maps [stack:TID] annotation")

Originally, /proc/PID/task/TID/maps was the same as /proc/TID/maps.

In current kernels, /proc/PID/maps (or /proc/TID/maps even for threads) shows "[stack]" for VMAs in the mm's stack address range.

In contrast, /proc/PID/task/TID/maps uses KSTK_ESP to guess the target thread's stack's VMA. This is racy, probably returns garbage and, on arches with CONFIG_TASK_INFO_IN_THREAD=y, is also crash-prone:
KSTK_ESP is not safe to use on tasks that aren't known to be running ordinary process-context kernel code.

This patch removes the difference and just shows "[stack]" for VMAs in the mm's stack range. This is IMO much more sensible -- the actual "stack" address really is treated specially by the VM code, and the current thread stack isn't even well-defined for programs that frequently switch stacks on their own.

Reported-by Jann Horn <[email protected]>
Signed-off-by Andy Lutomirski <[email protected]>
Acked-by Thomas Gleixner <[email protected]>
Quoted 5 lines
tools/perf/util/event.c +0 -0
 	fp = fopen(filename, "r");
 	if (fp == NULL) {
Signature · 1 line
2.5.0
maintainer
#3 lore raw

Em Wed, Mar 15, 2017 at 10:50:59AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 2 lines

So, fixing up the "tasks" -> "tasks" we end up with something safe and that avoids this by now

"tasks" -> "task", grrr

- Arnaldo

author
#4 lore raw
Quoted 6 lines · Arnaldo Carvalho de Melo

Em Wed, Mar 15, 2017 at 10:50:59AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 2 lines

So, fixing up the "tasks" -> "tasks" we end up with something safe and that avoids this by now

"tasks" -> "task", grrr

Oops, yeah, sorry about that.
Let me submit a V2 with the fix.

maintainer
#5 lore raw

Em Wed, Mar 15, 2017 at 10:08:27AM -0700, Stephane Eranian escreveu:

Quoted 10 lines
Quoted 6 lines · Arnaldo Carvalho de Melo

Em Wed, Mar 15, 2017 at 10:50:59AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 2 lines

So, fixing up the "tasks" -> "tasks" we end up with something safe and that avoids this by now

"tasks" -> "task", grrr

Oops, yeah, sorry about that.
Let me submit a V2 with the fix.

Ok, but what about the other observations, what is the kernel you're using?

I think this will not make any difference for any kernel >= 4.9, which isn't to say the patch shouldn't be applied, I'm just curious.

- Arnaldo

author
#6 lore raw

Arnaldo,

Quoted 8 lines · Arnaldo Carvalho de Melo

Em Wed, Mar 15, 2017 at 10:08:27AM -0700, Stephane Eranian escreveu:

Quoted 6 lines
Quoted 4 lines · Arnaldo Carvalho de Melo

Em Wed, Mar 15, 2017 at 10:50:59AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 2 lines

So, fixing up the "tasks" -> "tasks" we end up with something safe and that avoids this by now

Quoted 8 lines
Quoted 4 lines
Quoted 2 lines

"tasks" -> "task", grrr

Oops, yeah, sorry about that.
Let me submit a V2 with the fix.

Ok, but what about the other observations, what is the kernel you're using?

Ok, yeah, I was using an older kernel which still had [stack:tid] annotations. With more recent kernel, it seems this optimization is not needed. I guess it would only be useful to people running a new perf on a older kernel.

Quoted 4 lines

I think this will not make any difference for any kernel >= 4.9, which isn't to say the patch shouldn't be applied, I'm just curious.

correct, see above.

Quoted 2 lines

- Arnaldo

author
#7 lore raw

PATCH v2 1/1 perf/record: make perf_event__synthesize_mmap_events() scale

This patch significantly improves the execution time of
perf_event__synthesize_mmap_events() when running perf record
on systems where processes have lots of threads. It just happens
that cat /proc/pid/maps support uses a O(N^2) algorithm to generate
each map line in the maps file. If you have 1000 threads, then you have
necessarily 1000 stacks. For each vma, you need to check if it corresponds
to a thread's stack. With a large number of threads, this can take a very long time. I have seen latencies >> 10mn.

As of today, perf does not use the fact that a mapping is a stack, therefore we can work around the issue by using /proc/pid/tasks/pid/maps. This entry does not try to map a vma to stack and is thus much faster with no loss of functonality.

The proc-map-timeout logic is kept in case users still want some upper limit.

In V2, we fix the file path from /proc/pid/tasks/pid/maps to actual /proc/pid/task/pid/maps, tasks -> task. Thanks Arnaldo for catching this.

Signed-off-by Stephane Eranian <[email protected]>
---
 tools/perf/util/event.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/util/event.c +2 -2
index 4ea7ce7..b137566 100644
@@ -255,8 +255,8 @@ int perf_event__synthesize_mmap_events(struct perf_tool *tool,
 	if (machine__is_default_guest(machine))
 		return 0;
 
-	snprintf(filename, sizeof(filename), "%s/proc/%d/maps",
-		 machine->root_dir, pid);
+	snprintf(filename, sizeof(filename), "%s/proc/%d/task/%d/maps",
+		 machine->root_dir, pid, pid);
 
 	fp = fopen(filename, "r");
 	if (fp == NULL) {
Signature · 1 line
2.5.0
merge bot
#8 lore raw

[tip:perf/core] perf tools: Make perf_event__synthesize_mmap_events() scale

perf tools: Make perf_event__synthesize_mmap_events() scale
Commit-ID:  88b897a30c525c2eee6e7f16e1e8d0f18830845e
Gitweb:     http://git.kernel.org/tip/88b897a30c525c2eee6e7f16e1e8d0f18830845e
Author:     Stephane Eranian <[email protected]>
AuthorDate: Wed, 15 Mar 2017 10:17:13 -0700
Committer:  Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Wed, 15 Mar 2017 17:48:37 -0300

perf tools: Make perf_event__synthesize_mmap_events() scale

This patch significantly improves the execution time of perf_event__synthesize_mmap_events() when running perf record on systems where processes have lots of threads.

It just happens that cat /proc/pid/maps support uses a O(N^2) algorithm to generate each map line in the maps file. If you have 1000 threads, then you have necessarily 1000 stacks. For each vma, you need to check if it corresponds to a thread's stack. With a large number of threads, this can take a very long time. I have seen latencies >> 10mn.

As of today, perf does not use the fact that a mapping is a stack, therefore we can work around the issue by using /proc/pid/tasks/pid/maps. This entry does not try to map a vma to stack and is thus much faster with no loss of functonality.

The proc-map-timeout logic is kept in case users still want some upper limit.

In V2, we fix the file path from /proc/pid/tasks/pid/maps to actual /proc/pid/task/pid/maps, tasks -> task. Thanks Arnaldo for catching this.

Committer note:

This problem seems to have been elliminated in the kernel since commit :
b18cb64ead40 ("fs/proc: Stop trying to report thread stacks").

Signed-off-by Stephane Eranian <[email protected]>
Acked-by Jiri Olsa <[email protected]>
Cc Andy Lutomirski <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Peter Zijlstra <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Arnaldo Carvalho de Melo <[email protected]>
---
 tools/perf/util/event.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/util/event.c +2 -2
index d082cb7..33fc2e9 100644
@@ -325,8 +325,8 @@ int perf_event__synthesize_mmap_events(struct perf_tool *tool,
 	if (machine__is_default_guest(machine))
 		return 0;
 
-	snprintf(filename, sizeof(filename), "%s/proc/%d/maps",
-		 machine->root_dir, pid);
+	snprintf(filename, sizeof(filename), "%s/proc/%d/task/%d/maps",
+		 machine->root_dir, pid, pid);
 
 	fp = fopen(filename, "r");
 	if (fp == NULL) {