[PATCH v2] perf tool: Fix ppid for synthesized fork events

[PATCH v2] perf tool: Fix ppid for synthesized fork events

[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

Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Don Zickus <dzickus@redhat.com>
Cc: Joe Mario <jmario@redhat.com>
Cc: Jiri Olsa <jolsa@redhat.com>
---
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(-)

diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
index d5efa5092ce6..e98cbba56033 100644
--- a/tools/perf/util/event.c
+++ b/tools/perf/util/event.c
@@ -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
-- 
2.1.0

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Don Zickus]

On Wed, Mar 25, 2015 at 10:51:10AM -0600, David Ahern wrote:
> 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 <dsahern@gmail.com>
> Cc: Don Zickus <dzickus@redhat.com>
> Cc: Joe Mario <jmario@redhat.com>
> Cc: Jiri Olsa <jolsa@redhat.com>
> ---
> 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.

I still think something is strange in the sense perf wasn't supposed to read
the /proc filesystem again for threads.  It was supposed to inherit the
thread data from the parent (the original intent and big speed up of my
patch).  I believe your patch breaks that and goes back to reading the /proc
filesystem again. :-(  Though I haven't had a chance to figure out why.

Cheers,
Don



> 
>  tools/perf/util/event.c | 178 ++++++++++++++++++++++++++++++------------------
>  1 file changed, 110 insertions(+), 68 deletions(-)
> 
> diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
> index d5efa5092ce6..e98cbba56033 100644
> --- a/tools/perf/util/event.c
> +++ b/tools/perf/util/event.c
> @@ -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
> -- 
> 2.1.0
> 

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[David Ahern]

On 3/25/15 1:15 PM, Don Zickus wrote:
> On Wed, Mar 25, 2015 at 10:51:10AM -0600, David Ahern wrote:
>> 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 <dsahern@gmail.com>
>> Cc: Don Zickus <dzickus@redhat.com>
>> Cc: Joe Mario <jmario@redhat.com>
>> Cc: Jiri Olsa <jolsa@redhat.com>
>> ---
>> 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.
>

 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?

Thanks,

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Don Zickus]

On Wed, Mar 25, 2015 at 01:55:44PM -0600, David Ahern wrote:
> On 3/25/15 1:15 PM, Don Zickus wrote:
> >On Wed, Mar 25, 2015 at 10:51:10AM -0600, David Ahern wrote:
> >>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 <dsahern@gmail.com>
> >>Cc: Don Zickus <dzickus@redhat.com>
> >>Cc: Joe Mario <jmario@redhat.com>
> >>Cc: Jiri Olsa <jolsa@redhat.com>
> >>---
> >>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.
> >
> 
> 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?

Yes.  I believe Joe will try to find time on Thursday to run this.

Cheers,
Don

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Don Zickus]

On Wed, Mar 25, 2015 at 01:55:44PM -0600, David Ahern wrote:
> >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?

Hi David,

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.

Cheers,
Don

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[David Ahern]

On 3/26/15 3:11 PM, Don Zickus wrote:
> 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.

>
> 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.

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Don Zickus]

On Thu, Mar 26, 2015 at 03:37:29PM -0600, David Ahern wrote:
> On 3/26/15 3:11 PM, Don Zickus wrote:
> >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.
> 
> >
> >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?

Cheers,
Don

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[David Ahern]

On 3/27/15 7:10 AM, Don Zickus wrote:
> 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.

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?

>
> 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?

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.

David

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Arnaldo Carvalho de Melo]

Em Fri, Mar 27, 2015 at 08:03:28AM -0600, David Ahern escreveu:
> On 3/27/15 7:10 AM, Don Zickus wrote:
> >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.
 
> 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?

    -N, --no-buildid-cache
                          do not update the buildid cache
    -B, --no-buildid      do not collect buildids in perf.data

-B implies -N.

If you say just -N it will, at the end of the record session, process
and the samples in the just generated file, creating an rbtree of
threads nad mmaps in those threads, so that if can figure out which DSOs
associated with those maps had hits.

For those it will read the on disk file looking for an ELF session where
it'll find the build-id (few bytes) and will stash the resulting table
in the perf.data header.

If you instead (or in addition to) specify -B, it will not traverse the
just generated perf.data file, greatly reducing the overhead _at the
end_ of the record session.

With that said, lemme read again what is that is being measured...

> >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.

Humm, it is definetely strange, I would run 'perf record -o
some-other-file' to investigate that...

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

... which is what David is suggesting here:
 
> 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.

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.

- Arnaldo

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Don Zickus]

On Fri, Mar 27, 2015 at 11:20:36AM -0300, Arnaldo Carvalho de Melo wrote:
> ... which is what David is suggesting here:
>  
> > 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.
> 
> 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:

diff --git a/tools/perf/util/thread.c b/tools/perf/util/thread.c
index 1c8fbc9..7ee3823 100644
--- a/tools/perf/util/thread.c
+++ b/tools/perf/util/thread.c
@@ -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?

Cheers,
Don

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Arnaldo Carvalho de Melo]

Em Fri, Mar 27, 2015 at 03:49:41PM -0400, Don Zickus escreveu:
> On Fri, Mar 27, 2015 at 11:20:36AM -0300, Arnaldo Carvalho de Melo wrote:
> > ... which is what David is suggesting here:
> >  
> > > 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.
> > 
> > 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:
> 
> diff --git a/tools/perf/util/thread.c b/tools/perf/util/thread.c
> index 1c8fbc9..7ee3823 100644
> --- a/tools/perf/util/thread.c
> +++ b/tools/perf/util/thread.c
> @@ -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?

ok, so if in perf_event__synthesize_fork we correctly set up
event->fork.ppid, when we call process() there it will end up calling:

	perf_event__process_fork()
		machine__process_fork_event()

And that will call:

        struct thread *thread = machine__find_thread(machine,
                                                     event->fork.pid,
                                                     event->fork.tid);
        struct thread *parent = machine__findnew_thread(machine,
                                                        event->fork.ppid,
                                                        event->fork.ptid);

Without David's patch the second will pass -1 to both ppid and ptid,
right? That will find a fake thread with ppid == -1 and ptid == -1, that
has no mmaps.

Next thing perf_event__synthesize_fork() will do is to call:

  thread__fork(thread, parent, sample->time)

And that is what will end up calling:

	thread__clone_map_groups(thread, parent)
		map_groups__clone(thread->mg, parent->mg, i)

So, assuming the parent was synthesized first and got its mmaps, then
when the child is processed it will find and will clone its mmaps.

- Arnaldo

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[David Ahern]

On 3/27/15 1:49 PM, Don Zickus wrote:
> diff --git a/tools/perf/util/thread.c b/tools/perf/util/thread.c
> index 1c8fbc9..7ee3823 100644
> --- a/tools/perf/util/thread.c
> +++ b/tools/perf/util/thread.c
> @@ -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.

>
> +	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.

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:

diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
index d5efa5092ce6..ce4ca061c2e5 100644
--- a/tools/perf/util/event.c
+++ b/tools/perf/util/event.c
@@ -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

Re: [PATCH v2] perf tool: Fix ppid for synthesized fork events

[Don Zickus]

On Fri, Mar 27, 2015 at 02:10:54PM -0600, David Ahern wrote:
> On 3/27/15 1:49 PM, Don Zickus wrote:
> >diff --git a/tools/perf/util/thread.c b/tools/perf/util/thread.c
> >index 1c8fbc9..7ee3823 100644
> >--- a/tools/perf/util/thread.c
> >+++ b/tools/perf/util/thread.c
> >@@ -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.
> 
> >
> >+	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.
> 
> 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.

Actually, we originally intended the opposite I think.  We were trying to
get perf to avoid reading /proc/<pid>/maps and do the slow and painful ascii
to binary parsing by re-using a similar map (from a forked parent).

Our speed up may have been implemented incorrectly and dumb luck got us a
speed up, but we didn't mean to assume ppid != tgid, IIRC. :-)

I think your's and acme's explaination makes sense.  As a result, we are ok
with this patch.

You mentioned a v2, splitting up the patch.  I will wait for that patch and
ack it.

Thanks!

Cheers,
Don


> 
> Before ppid was getting initialized to -1. If you just make that
> change to revert to the -1:
> 
> diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
> index d5efa5092ce6..ce4ca061c2e5 100644
> --- a/tools/perf/util/event.c
> +++ b/tools/perf/util/event.c
> @@ -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