perf tool: Fix ppid for synthesized fork events

363b785f38 added synthesized fork events and set a thread's parent id to itself. Since we are already processing /proc/<pid>/status the ppid can be determined properly. Make it so.

Performance impact measured on a sparc based T5-8 (1024 CPUs):

$ ps -efL | wc -l
20185

Current code:

$ time perf record -o perf-no-ppid.data -e cpu-clock -F 1000 -a -v -BN -- usleep 1
mmap size 532480B
[ perf record: Woken up 0 times to write data ]
failed to write feature 9
[ perf record: Captured and wrote 0.000 MB perf-no-ppid.data ]

real 0m26.144s
user 0m0.452s
sys 0m25.564s

With PPID patch:

$ time ./perf_ppid record -o perf-ppid.data -e cpu-clock -F 1000 -a -v -BN -- usleep 1
mmap size 532480B
[ perf record: Woken up 0 times to write data ]
failed to write feature 9
[ perf record: Captured and wrote 0.000 MB perf-ppid.data ]

real 0m25.743s
user 0m0.268s
sys 0m25.368s

Signed-off-by David Ahern <[email protected]>

Cc Don Zickus <[email protected]>

Cc Joe Mario <[email protected]>

Cc Jiri Olsa <[email protected]>

---
v2:
- removed loop in place of 1 read and processing a buffer

 tools/perf/util/event.c | 178 ++++++++++++++++++++++++++++++------------------
 1 file changed, 110 insertions(+), 68 deletions(-)

tools/perf/util/event.c +110 -68

index d5efa5092ce6..e98cbba56033 100644
@@ -49,70 +49,115 @@ static struct perf_sample synth_sample = {
 	.period	   = 1,
 };
 
-static pid_t perf_event__get_comm_tgid(pid_t pid, char *comm, size_t len)
+/*
+ * Assumes that the first 4095 bytes of /proc/pid/stat contains
+ * the comm, tgid and ppid.
+ */
+static int perf_event__get_comm_ids(pid_t pid, char *comm, size_t len,
+				    pid_t *tgid, pid_t *ppid)
 {
 	char filename[PATH_MAX];
-	char bf[BUFSIZ];
-	FILE *fp;
-	size_t size = 0;
-	pid_t tgid = -1;
+	char bf[4096];
+	int fd;
+	size_t size = 0, n;
+	char *nl, *name, *tgids, *ppids;
+
+	*tgid = -1;
+	*ppid = -1;
 
 	snprintf(filename, sizeof(filename), "/proc/%d/status", pid);
 
-	fp = fopen(filename, "r");
-	if (fp == NULL) {
+	fd = open(filename, O_RDONLY);
+	if (fd < 0) {
 		pr_debug("couldn't open %s\n", filename);
-		return 0;
+		return -1;
 	}
 
-	while (!comm[0] || (tgid < 0)) {
-		if (fgets(bf, sizeof(bf), fp) == NULL) {
-			pr_warning("couldn't get COMM and pgid, malformed %s\n",
-				   filename);
-			break;
-		}
-
-		if (memcmp(bf, "Name:", 5) == 0) {
-			char *name = bf + 5;
-			while (*name && isspace(*name))
-				++name;
-			size = strlen(name) - 1;
-			if (size >= len)
-				size = len - 1;
-			memcpy(comm, name, size);
-			comm[size] = '\0';
-
-		} else if (memcmp(bf, "Tgid:", 5) == 0) {
-			char *tgids = bf + 5;
-			while (*tgids && isspace(*tgids))
-				++tgids;
-			tgid = atoi(tgids);
-		}
+	n = read(fd, bf, sizeof(bf) - 1);
+	close(fd);
+	if (n <= 0) {
+		pr_warning("Couldn't get COMM, tigd and ppid for pid %d\n",
+			   pid);
+		return -1;
 	}
+	bf[n] = '\0';
 
-	fclose(fp);
+	name = strstr(bf, "Name:");
+	tgids = strstr(bf, "Tgid:");
+	ppids = strstr(bf, "PPid:");
+
+	if (name) {
+		name += 5;  /* strlen("Name:") */
+
+		while (*name && isspace(*name))
+			++name;
+
+		nl = strchr(name, '\n');
+		if (nl)
+			*nl = '\0';
+
+		size = strlen(name);
+		if (size >= len)
+			size = len - 1;
+		memcpy(comm, name, size);
+		comm[size] = '\0';
+	} else
+		pr_debug("Name: string not found for pid %d\n", pid);
+
+	if (tgids) {
+		tgids += 5;  /* strlen("Tgid:") */
+		while (*tgids && isspace(*tgids))
+			++tgids;
+
+		nl = strchr(tgids, '\n');
+		if (nl)
+			*nl = '\0';
+
+		*tgid = atoi(tgids);
+
+	} else
+		pr_debug("Tgid: string not found for pid %d\n", pid);
+
+	if (ppids) {
+		ppids += 5;  /* strlen("PPid:") */
+
+		while (*ppids && isspace(*ppids))
+			++ppids;
+
+		nl = strchr(ppids, '\n');
+		if (nl)
+			*nl = '\0';
+
+		*ppid = atoi(ppids);
+	} else
+		pr_debug("PPid: string not found for pid %d\n", pid);
 
-	return tgid;
+	return 0;
 }
 
-static pid_t perf_event__prepare_comm(union perf_event *event, pid_t pid,
-					 struct machine *machine)
+static int perf_event__prepare_comm(union perf_event *event, pid_t pid,
+				    struct machine *machine,
+				    pid_t *tgid, pid_t *ppid)
 {
 	size_t size;
-	pid_t tgid;
+
+	*ppid = -1;
 
 	memset(&event->comm, 0, sizeof(event->comm));
 
-	if (machine__is_host(machine))
-		tgid = perf_event__get_comm_tgid(pid, event->comm.comm,
-						 sizeof(event->comm.comm));
-	else
-		tgid = machine->pid;
+	if (machine__is_host(machine)) {
+		if (perf_event__get_comm_ids(pid, event->comm.comm,
+					     sizeof(event->comm.comm),
+					     tgid, ppid) != 0) {
+			return -1;
+		}
+	} else
+		*tgid = machine->pid;
 
-	if (tgid < 0)
-		goto out;
+	if (*tgid < 0)
+		return -1;
 
-	event->comm.pid = tgid;
+	event->comm.pid = *tgid;
 	event->comm.header.type = PERF_RECORD_COMM;
 
 	size = strlen(event->comm.comm) + 1;

@@ -122,36 +167,35 @@ static pid_t perf_event__prepare_comm(union perf_event *event, pid_t pid,
 				(sizeof(event->comm.comm) - size) +
 				machine->id_hdr_size);
 	event->comm.tid = pid;
-out:
-	return tgid;
+
+	return 0;
 }
 
-static pid_t perf_event__synthesize_comm(struct perf_tool *tool,
-					 union perf_event *event, pid_t pid,
-					 perf_event__handler_t process,
-					 struct machine *machine)
+static int perf_event__synthesize_comm(struct perf_tool *tool,
+				       union perf_event *event, pid_t pid,
+				       perf_event__handler_t process,
+				       struct machine *machine,
+				       pid_t *tgid, pid_t *ppid)
 {
-	pid_t tgid = perf_event__prepare_comm(event, pid, machine);
-
-	if (tgid == -1)
-		goto out;
+	if (perf_event__prepare_comm(event, pid, machine, tgid, ppid) != 0)
+		return -1;
 
 	if (process(tool, event, &synth_sample, machine) != 0)
 		return -1;
 
-out:
-	return tgid;
+	return 0;
 }
 
 static int perf_event__synthesize_fork(struct perf_tool *tool,
-				       union perf_event *event, pid_t pid,
-				       pid_t tgid, perf_event__handler_t process,
+				       union perf_event *event,
+				       pid_t pid, pid_t tgid, pid_t ppid,
+				       perf_event__handler_t process,
 				       struct machine *machine)
 {
 	memset(&event->fork, 0, sizeof(event->fork) + machine->id_hdr_size);
 
-	event->fork.ppid = tgid;
-	event->fork.ptid = tgid;
+	event->fork.ppid = ppid;
+	event->fork.ptid = ppid;
 	event->fork.pid  = tgid;
 	event->fork.tid  = pid;
 	event->fork.header.type = PERF_RECORD_FORK;

@@ -343,14 +387,12 @@ static int __event__synthesize_thread(union perf_event *comm_event,
 	char filename[PATH_MAX];
 	DIR *tasks;
 	struct dirent dirent, *next;
-	pid_t tgid;
+	pid_t tgid, ppid;
 
 	/* special case: only send one comm event using passed in pid */
 	if (!full) {
-		tgid = perf_event__synthesize_comm(tool, comm_event, pid,
-						   process, machine);
-
-		if (tgid == -1)
+		if (perf_event__synthesize_comm(tool, comm_event, pid,
+						process, machine, &tgid, &ppid) != 0)
 			return -1;
 
 		return perf_event__synthesize_mmap_events(tool, mmap_event, pid, tgid,

@@ -378,12 +420,12 @@ static int __event__synthesize_thread(union perf_event *comm_event,
 		if (*end)
 			continue;
 
-		tgid = perf_event__prepare_comm(comm_event, _pid, machine);
-		if (tgid == -1)
+		if (perf_event__prepare_comm(comm_event, _pid, machine,
+					     &tgid, &ppid) != 0)
 			return -1;
 
 		if (perf_event__synthesize_fork(tool, fork_event, _pid, tgid,
-						process, machine) < 0)
+						ppid, process, machine) < 0)
 			return -1;
 		/*
 		 * Send the prepared comm event

Signature · 1 line

2.1.0

Quoted 30 lines · David Ahern

363b785f38 added synthesized fork events and set a thread's parent id to itself. Since we are already processing /proc/<pid>/status the ppid can be determined properly. Make it so.

Performance impact measured on a sparc based T5-8 (1024 CPUs):

$ ps -efL | wc -l
20185

Current code:

$ time perf record -o perf-no-ppid.data -e cpu-clock -F 1000 -a -v -BN -- usleep 1
mmap size 532480B
[ perf record: Woken up 0 times to write data ]
failed to write feature 9
[ perf record: Captured and wrote 0.000 MB perf-no-ppid.data ]

real 0m26.144s
user 0m0.452s
sys 0m25.564s

With PPID patch:

$ time ./perf_ppid record -o perf-ppid.data -e cpu-clock -F 1000 -a -v -BN -- usleep 1
mmap size 532480B
[ perf record: Woken up 0 times to write data ]
failed to write feature 9
[ perf record: Captured and wrote 0.000 MB perf-ppid.data ]

real 0m25.743s
user 0m0.268s
sys 0m25.368s

Quoted 7 lines

Signed-off-by David Ahern <[email protected]>

Cc Don Zickus <[email protected]>

Cc Joe Mario <[email protected]>

Cc Jiri Olsa <[email protected]>

---
v2:
- removed loop in place of 1 read and processing a buffer

Hmm, I am not entirely sure this is correct. You made an optimization that hides the negative impact your patch does. I would prefer you split this patch into two pieces. One with the read loop optimization (which I think is great) and the second is your ppid change.

I would then like to redo our test with the first patch applied and then both patches applied.

Quoted 39 lines · Don Zickus

Quoted 30 lines · David Ahern

363b785f38 added synthesized fork events and set a thread's parent id to itself. Since we are already processing /proc/<pid>/status the ppid can be determined properly. Make it so.

Performance impact measured on a sparc based T5-8 (1024 CPUs):

$ ps -efL | wc -l
20185

Current code:

$ time perf record -o perf-no-ppid.data -e cpu-clock -F 1000 -a -v -BN -- usleep 1
mmap size 532480B
[ perf record: Woken up 0 times to write data ]
failed to write feature 9
[ perf record: Captured and wrote 0.000 MB perf-no-ppid.data ]

real 0m26.144s
user 0m0.452s
sys 0m25.564s

With PPID patch:

$ time ./perf_ppid record -o perf-ppid.data -e cpu-clock -F 1000 -a -v -BN -- usleep 1
mmap size 532480B
[ perf record: Woken up 0 times to write data ]
failed to write feature 9
[ perf record: Captured and wrote 0.000 MB perf-ppid.data ]

real 0m25.743s
user 0m0.268s
sys 0m25.368s

Quoted 7 lines

Signed-off-by David Ahern <[email protected]>

Cc Don Zickus <[email protected]>

Cc Joe Mario <[email protected]>

Cc Jiri Olsa <[email protected]>

---
v2:
- removed loop in place of 1 read and processing a buffer

Quoted 8 lines

Hmm, I am not entirely sure this is correct. You made an optimization that hides the negative impact your patch does. I would prefer you split this patch into two pieces. One with the read loop optimization (which I think is great) and the second is your ppid change.

I would then like to redo our test with the first patch applied and then both patches applied.

From your other response I take it you understand the patch now? It is a matter of semantics to break this single into 2 -- optimize the existing code and then add the ppid. End result will be what this patch shows. Before I do that can you /Joe confirm the performance is acceptable?

Quoted 8 lines

Hmm, I am not entirely sure this is correct. You made an optimization that hides the negative impact your patch does. I would prefer you split this patch into two pieces. One with the read loop optimization (which I think is great) and the second is your ppid change.

I would then like to redo our test with the first patch applied and then both patches applied.

From your other response I take it you understand the patch now? It is a matter of semantics to break this single into 2 -- optimize the existing code and then add the ppid. End result will be what this patch shows. Before I do that can you /Joe confirm the performance is acceptable?

Sorry for drawing this out. Originally the performance still seemed off. But as we split the patch up to see where the perf impact was, the problem seemed to have disappeared. So we are testing the original patch again.

The only difference now is we were playing with the -BN option in perf based on your changelog, just because we never used it before. :-)

One last test without the -BN option and if that looks fine, then we have no objections. Again sorry for dragging this out. I will let you know tomorrow EST.

Quoted 6 lines · Don Zickus

Sorry for drawing this out. Originally the performance still seemed off. But as we split the patch up to see where the perf impact was, the problem seemed to have disappeared. So we are testing the original patch again.

The only difference now is we were playing with the -BN option in perf based on your changelog, just because we never used it before. :-)

I was beyond surprised that you were measuring a 50% hit with the first patch. As mentioned in a previous response it only adds the processing of 3 additional lines to the already opened and read /proc/pid/status file. So, when I wrote this second version I wanted to make sure we are only measuring the impact of this change. The /proc/pid/status files are read on startup of the record -- before any samples are taken.

The intent of '-e cpu-clock -F 1000 -- usleep 1' is to avoid any samples since we don't care about them. Really the -a should be dropped as well -- no need to open per-cpu events.

-B impacts processing done at the end of the run:

builin-record.c, __cmd_record():

                if (!rec->no_buildid)
                        process_buildids(rec);

and -N says don't copying anything to ~/.debug. All together it tries to focus the measurement to /proc walking.

Quoted 1 line

Quoted 3 lines

One last test without the -BN option and if that looks fine, then we have no objections. Again sorry for dragging this out. I will let you know tomorrow EST.

no problem; appreciate the heads up.

I talked with Joe on my way out the door yesterday and he confirmed, just removing -BN from our test showed a performance hit with your patch. With the -BN option, there is no performance hit and we are perfectly fine with your patch.

So, I guess I am confused how the -BN and your patch could change behaviour.

Just to re-iterate what we did, Joe kicked off a specJBB run and he did 20 captures of two runs (one with the unpatched binary and one with a pached binary).

for i in {1..20}
do
time perf.unpatched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10
time perf.patched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10
done

then we repeat the above test but with -BN in both runs. We compare the log sizes to make sure they are similar for the random snapshots and compare the times. With the -BN option, the times are generally within +/- 0.5 seconds of each. Without the -BN option the patched perf binary is generally +20-40 seconds slower.

However, based on your description above about what the -BN option does, I am scratching my head about our results. Thoughts?

Quoted 4 lines

I talked with Joe on my way out the door yesterday and he confirmed, just removing -BN from our test showed a performance hit with your patch. With the -BN option, there is no performance hit and we are perfectly fine with your patch.

Quoted 1 line

So, I guess I am confused how the -BN and your patch could change behaviour.

I am too. This change has nothing to do with buildid's and scanning the buildid code setting the ppid correctly should not cause any extra work.

Arnaldo: any thoughts?

Quoted 9 lines

Just to re-iterate what we did, Joe kicked off a specJBB run and he did 20 captures of two runs (one with the unpatched binary and one with a pached binary).

for i in {1..20}
do
time perf.unpatched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10
time perf.patched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10
done

Quoted 5 lines

then we repeat the above test but with -BN in both runs. We compare the log sizes to make sure they are similar for the random snapshots and compare the times. With the -BN option, the times are generally within +/- 0.5 seconds of each. Without the -BN option the patched perf binary is generally +20-40 seconds slower.

Quoted 2 lines

However, based on your description above about what the -BN option does, I am scratching my head about our results. Thoughts?

Try this:
perf record -o unpatched.data -g -- perf.unpatched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10

perf record -o patched.data -g -- perf.patched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10

And then compare the reports for each.

... which is what David is suggesting here:

Quoted 7 lines

Try this:
perf record -o unpatched.data -g -- perf.unpatched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10

perf record -o patched.data -g -- perf.patched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10

Quoted 1 line

And then compare the reports for each.

Cache effects, i.e. OS FS caches for the files accessed when doing the build id table could be responsible for part of the difference at some point, but further investigation by using 'perf record' patched/unpatched will give us more clues.

Quoted 9 lines

... which is what David is suggesting here:

Quoted 7 lines

Try this:
perf record -o unpatched.data -g -- perf.unpatched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10

perf record -o patched.data -g -- perf.patched mem record -a -e cpu/mem-loads,ldlat=50/pp -e cpu/mem-stores/pp sleep 10

Quoted 6 lines

Quoted 1 line

And then compare the reports for each.

Cache effects, i.e. OS FS caches for the files accessed when doing the build id table could be responsible for part of the difference at some point, but further investigation by using 'perf record' patched/unpatched will give us more clues.

Alright, Joe and I poked some more and as I thought, David's patch does something subtle which may have inadvertently undid my original patch. Though the threading model isn't clear in my head right now.

Here is the patch I added to test a theory:

tools/perf/util/thread.c +1 -0

index 1c8fbc9..7ee3823 100644
@@ -187,6 +187,7 @@ static int thread__clone_map_groups(struct thread *thread,
 	if (thread->pid_ == parent->pid_)
 		return 0;
 
+	printf("DON:\n");
 	/* But this one is new process, copy maps. */
 	for (i = 0; i < MAP__NR_TYPES; ++i)
 		if (map_groups__clone(thread->mg, parent->mg, i) < 0)

before David's patch, we do _not_ see any DON markers. After David's patch we see a 1:1 match of DON markers to the number of threads currently running in the system.

As a result the perf record -g command David recommended showed a spike in rb_next and map_groups__clone which is the result of the above discovery.

So the next question is, is this correct? On the surface I would say no because it doesn't seem like we are not being smart any more and taking advantage of the existing thread maps created. But I guess the idea behind cloning is that we are.

I can't think right now what is the correct behaviour, thoughts?

tools/perf/util/thread.c +1 -0

+	printf("DON:\n");
  	/* But this one is new process, copy maps. */
  	for (i = 0; i < MAP__NR_TYPES; ++i)
  		if (map_groups__clone(thread->mg, parent->mg, i) < 0)
 

before David's patch, we do _not_ see any DON markers. After David's patch we see a 1:1 match of DON markers to the number of threads currently running in the system.

tools/perf/util/thread.c static int thread__clone_map_groups(struct thread *thread, · line 188

Quoted 7 lines · Don Zickus

tools/perf/util/thread.c +0 -0

index 1c8fbc9..7ee3823 100644
@@ -187,6 +187,7 @@ static int thread__clone_map_groups(struct thread *thread,
 	if (thread->pid_ == parent->pid_)
 		return 0;

There's your answer ... the 2 lines above.

Quoted 6 lines

tools/perf/util/thread.c +1 -0

+	printf("DON:\n");
 	/* But this one is new process, copy maps. */
 	for (i = 0; i < MAP__NR_TYPES; ++i)
 		if (map_groups__clone(thread->mg, parent->mg, i) < 0)
 

Quoted 3 lines

before David's patch, we do _not_ see any DON markers. After David's patch we see a 1:1 match of DON markers to the number of threads currently running in the system.

Your "speed up" is based on the assumption that all synthesized threads are their own parent which is wrong. ie., ppid != tgid of the process.

Before ppid was getting initialized to -1. If you just make that change to revert to the -1:

tools/perf/util/event.c +2 -2

index d5efa5092ce6..ce4ca061c2e5 100644
@@ -150,8 +150,8 @@ static int perf_event__synthesize_fork(struct
 perf_tool *tool,
 {
    memset(&event->fork, 0, sizeof(event->fork) + machine->id_hdr_size);
 
-   event->fork.ppid = tgid;
-   event->fork.ptid = tgid;
+   event->fork.ppid = -1;
+   event->fork.ptid = -1;
    event->fork.pid  = tgid;
    event->fork.tid  = pid;

    event->fork.header.type = PERF_RECORD_FORK;

You see the "DON" messages.

David