trace-cmd fails with many cpus

trace-cmd fails with many cpus

[Phil Auld]

Hi,

I was trying to get some sched traces on a 160 cpu box yesterday. Trace-cmd 
failed with 

# ./tracecmd/trace-cmd record -e "sched:*" sleep 2
none
trace-cmd: Invalid argument
  Failed filter of /sys/kernel/tracing/events/sched/sched_switch/filter

trace-cmd: No such file or directory
  can not stat 'trace.dat.cpu0'
#


Which can be seen better with strace

[pid 97653] open("/sys/kernel/tracing/events/sched/sched_swap_numa/filter", O_WRONLY|O_TRUNC) = 5
[pid 97653] write(5, "(common_pid!=97652)&&(common_pid"..., 3358) = 3358
[pid 97653] close(5)                    = 0
[pid 97653] open("/sys/kernel/tracing/events/sched/sched_switch/filter", O_WRONLY|O_TRUNC) = 5
[pid 97653] write(5, "(common_pid!=97652)&&(common_pid"..., 6398) = -1 EINVAL (Invalid argument)
[pid 97653] close(5)                    = 0

The filter file can only take a max write of length PAGE_SIZE. 

The extra pid filtering added for "next_pid"  more or less doubles length
and pushes it over the 4k limit. 

WRITE: /sys/kernel/tracing/events/sched/sched_switch/filter, len 6718, data "(common_pid!=100199)&&(common_pid!=100198)&&(common_pid!=100197)&&(common_pid!=100196)&&(common_pid!=100195)&&(common_pid!=100194)&&(common_pid!=100193)&&(common_pid!=100192)&&(common_pid!=100191) ... 160 of these ...
&&(common_pid!=100040)||(next_pid!=100199)&&(next_pid!=100198)&&(next_pid!=100197)&&(next_pid!=100196)&&(next_pid!=100195)&&(next_pid!=100194)&&(next_pid!=100193)&&(next_pid!=100192)...  160 of these...


I suppose the answer is don't run on a system with that many cpus  :)

But I wonder if it would be possible to have the threads each handle say 8 cpu
files or something.

Or maybe have the kernel filter accept an "all_pid" that covered common_pid, next_pid, pid to reduce
the number of items needed in there? 



Thanks,

Phil



-- 

Re: trace-cmd fails with many cpus

[Steven Rostedt]

On Fri, 12 Apr 2019 09:53:33 -0400
Phil Auld <pauld@redhat.com> wrote:

> Hi,
> 
> I was trying to get some sched traces on a 160 cpu box yesterday. Trace-cmd 
> failed with 

Thanks for the report!

> 
> # ./tracecmd/trace-cmd record -e "sched:*" sleep 2
> none
> trace-cmd: Invalid argument
>   Failed filter of /sys/kernel/tracing/events/sched/sched_switch/filter
> 
> trace-cmd: No such file or directory
>   can not stat 'trace.dat.cpu0'
> #
> 
> 
> Which can be seen better with strace
> 
> [pid 97653] open("/sys/kernel/tracing/events/sched/sched_swap_numa/filter", O_WRONLY|O_TRUNC) = 5
> [pid 97653] write(5, "(common_pid!=97652)&&(common_pid"..., 3358) = 3358
> [pid 97653] close(5)                    = 0
> [pid 97653] open("/sys/kernel/tracing/events/sched/sched_switch/filter", O_WRONLY|O_TRUNC) = 5
> [pid 97653] write(5, "(common_pid!=97652)&&(common_pid"..., 6398) = -1 EINVAL (Invalid argument)
> [pid 97653] close(5)                    = 0
> 
> The filter file can only take a max write of length PAGE_SIZE. 

Ah yeah. By default we try not to trace the recorders. Newer kernels
have a set_event_pid which is used for only tracing specific tasks for
the events. I wonder if we should allow for "!pid" to be sent to that
file as something to not be traced?

But that doesn't help you now.

Hmm, I thought we had an option to disable this, but I don't see one.
That's the first thing we should do. Add an option such that you record
all events, even the threads (which is something I would definitely
want!).

> 
> The extra pid filtering added for "next_pid"  more or less doubles length
> and pushes it over the 4k limit. 
> 
> WRITE: /sys/kernel/tracing/events/sched/sched_switch/filter, len 6718, data "(common_pid!=100199)&&(common_pid!=100198)&&(common_pid!=100197)&&(common_pid!=100196)&&(common_pid!=100195)&&(common_pid!=100194)&&(common_pid!=100193)&&(common_pid!=100192)&&(common_pid!=100191) ... 160 of these ...
> &&(common_pid!=100040)||(next_pid!=100199)&&(next_pid!=100198)&&(next_pid!=100197)&&(next_pid!=100196)&&(next_pid!=100195)&&(next_pid!=100194)&&(next_pid!=100193)&&(next_pid!=100192)...  160 of these...
> 
> 
> I suppose the answer is don't run on a system with that many cpus  :)
> 
> But I wonder if it would be possible to have the threads each handle say 8 cpu
> files or something.

Actually, I think another solution is to consolidate the pids that are
to be excluded and sort them. Thus if we have (which is very likely the
case)

 (common_pid!=1000)&&(common_pid!=1001)&&(common_pid!=1002)

That we change that to:

  !((common_pid>=1000)||(common_pid<=1002))

Which would also have the affect of improving the filter logic within
the kernel as well.

Tzvetomir or Slavomir, would either of you be able to implement the
above? Both adding an option to disable this (--no-filter) and the
sorting of the excluded pids?

Thanks!

-- Steve


> 
> Or maybe have the kernel filter accept an "all_pid" that covered common_pid, next_pid, pid to reduce
> the number of items needed in there? 
> 

Re: trace-cmd fails with many cpus

[Steven Rostedt]

On Fri, 12 Apr 2019 11:15:46 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > 
> > 
> > I suppose the answer is don't run on a system with that many cpus  :)
> > 
> > But I wonder if it would be possible to have the threads each handle say 8 cpu
> > files or something.  
> 
> Actually, I think another solution is to consolidate the pids that are
> to be excluded and sort them. Thus if we have (which is very likely the
> case)
> 
>  (common_pid!=1000)&&(common_pid!=1001)&&(common_pid!=1002)
> 
> That we change that to:
> 
>   !((common_pid>=1000)||(common_pid<=1002))  

> > WRITE: /sys/kernel/tracing/events/sched/sched_switch/filter, len 6718, data "(common_pid!=100199)&&(common_pid!=100198)&&(common_pid!=100197)&&(common_pid!=100196)&&(common_pid!=100195)&&(common_pid!=100194)&&(common_pid!=100193)&&(common_pid!=100192)&&(common_pid!=100191) ... 160 of these ...
> > &&(common_pid!=100040)||(next_pid!=100199)&&(next_pid!=100198)&&(next_pid!=100197)&&(next_pid!=100196)&&(next_pid!=100195)&&(next_pid!=100194)&&(next_pid!=100193)&&(next_pid!=100192)...  160 of these...

Yes this would definitely help. From your output that is shown, we
could convert that to:

 !((common_pid>=100040)||(common_pid<=100199))&&!((next_pid>=100040)||(next_pid<=100199))


-- Steve

Re: trace-cmd fails with many cpus

[Phil Auld]

On Fri, Apr 12, 2019 at 11:35:47AM -0400 Steven Rostedt wrote:
> On Fri, 12 Apr 2019 11:15:46 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > > 
> > > 
> > > I suppose the answer is don't run on a system with that many cpus  :)
> > > 
> > > But I wonder if it would be possible to have the threads each handle say 8 cpu
> > > files or something.  
> > 
> > Actually, I think another solution is to consolidate the pids that are
> > to be excluded and sort them. Thus if we have (which is very likely the
> > case)
> > 
> >  (common_pid!=1000)&&(common_pid!=1001)&&(common_pid!=1002)
> > 
> > That we change that to:
> > 
> >   !((common_pid>=1000)||(common_pid<=1002))  
> 
> > > WRITE: /sys/kernel/tracing/events/sched/sched_switch/filter, len 6718, data "(common_pid!=100199)&&(common_pid!=100198)&&(common_pid!=100197)&&(common_pid!=100196)&&(common_pid!=100195)&&(common_pid!=100194)&&(common_pid!=100193)&&(common_pid!=100192)&&(common_pid!=100191) ... 160 of these ...
> > > &&(common_pid!=100040)||(next_pid!=100199)&&(next_pid!=100198)&&(next_pid!=100197)&&(next_pid!=100196)&&(next_pid!=100195)&&(next_pid!=100194)&&(next_pid!=100193)&&(next_pid!=100192)...  160 of these...
> 
> Yes this would definitely help. From your output that is shown, we
> could convert that to:
> 
>  !((common_pid>=100040)||(common_pid<=100199))&&!((next_pid>=100040)||(next_pid<=100199))
> 

That'll be interesting to code given how the code works now, but does look 
like it would help. Probably save a lot of instructions when filtering too.


Thanks for looking at it. 


I can just find a smaller machine.


Cheers,
Phil


> 
> -- Steve

-- 

Re: trace-cmd fails with many cpus

[Steven Rostedt]

On Fri, 12 Apr 2019 14:13:13 -0400
Phil Auld <pauld@redhat.com> wrote:


> I can just find a smaller machine.
> 

Or apply this hack ;-)

-- Steve

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 76ca92dc..fe300401 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -2988,8 +2988,10 @@ void start_threads(enum trace_type type, struct common_record_context *ctx)
 			pid = pids[i++].pid = create_recorder(instance, x, type, brass);
 			if (brass)
 				close(brass[1]);
+#if 0
 			if (pid > 0)
 				add_filter_pid(pid, 1);
+#endif
 		}
 	}
 	recorder_threads = i;

Re: trace-cmd fails with many cpus

[Steven Rostedt]

On Fri, 12 Apr 2019 11:15:46 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Tzvetomir or Slavomir, would either of you be able to implement the
> above? Both adding an option to disable this (--no-filter) and the
> sorting of the excluded pids?

I created two bugzillas for these:

 https://bugzilla.kernel.org/show_bug.cgi?id=203291
 https://bugzilla.kernel.org/show_bug.cgi?id=203293

-- Steve

[PATCH] .

[Slavomir Kaslev]

On Fri, 2019-04-12 at 11:15 -0400, Steven Rostedt wrote:
> Actually, I think another solution is to consolidate the pids that
> are
> to be excluded and sort them. Thus if we have (which is very likely
> the
> case)
> 
>  (common_pid!=1000)&&(common_pid!=1001)&&(common_pid!=1002)
> 
> That we change that to:
> 
>   !((common_pid>=1000)||(common_pid<=1002))
> 
> Which would also have the affect of improving the filter logic within
> the kernel as well.
> 
> Tzvetomir or Slavomir, would either of you be able to implement the
> above? Both adding an option to disable this (--no-filter) and the
> sorting of the excluded pids?

Do you mean something like this? The comment for make_pid_filter() needs be
updated too. I'll send a proper patch tomorrow if this fixes the issue.

---
 tracecmd/trace-record.c | 110 +++++++++++++++++++++++++++-------------
 1 file changed, 74 insertions(+), 36 deletions(-)

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 76ca92d..102e5ab 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -950,6 +950,57 @@ static void update_ftrace_pids(int reset)
 static void update_event_filters(struct buffer_instance *instance);
 static void update_pid_event_filters(struct buffer_instance *instance);
 
+static void append_filter_pid_range(char **filter, int *curr_len,
+				    const char *field,
+				    int start_pid, int end_pid, bool exclude)
+{
+	char *op, *op1, *op2, *op3;
+	int len;
+
+	op = *filter && **filter ? "||" : "";
+
+	// Handle thus case explicitly so that we get `pid==3` instead of
+	// `pid>=3&&pid<=3` for singleton ranges
+	if (start_pid == end_pid) {
+#define FMT	"%s(%s%s%d)"
+		len = snprintf(NULL, 0, FMT, op,
+			       field, exclude ? "!=" : "==", start_pid);
+		*filter = realloc(*filter, *curr_len + len + 1);
+		if (!*filter)
+			die("realloc");
+
+		len = snprintf(*filter + *curr_len, len + 1, FMT, op,
+			       field, exclude ? "!=" : "==", start_pid);
+		*curr_len += len;
+
+		return;
+#undef FMT
+	}
+
+	if (exclude) {
+		op1 = "<";
+		op2 = "||";
+		op3 = ">";
+	} else {
+		op1 = ">=";
+		op2 = "&&";
+		op3 = "<=";
+	}
+
+#define FMT	"%s(%s%s%d%s%s%s%d)"
+	len = snprintf(NULL, 0, FMT, op,
+		       field, op1, start_pid, op2,
+		       field, op3, end_pid);
+	*filter = realloc(*filter, *curr_len + len + 1);
+	if (!*filter)
+		die("realloc");
+
+	len = snprintf(*filter + *curr_len, len + 1, FMT, op,
+		       field, op1, start_pid, op2,
+		       field, op3, end_pid);
+	*curr_len += len;
+}
+
 /**
  * make_pid_filter - create a filter string to all pids against @field
  * @curr_filter: Append to a previous filter (may realloc). Can be NULL
@@ -963,54 +1014,41 @@ static void update_pid_event_filters(struct buffer_instance *instance);
  */
 static char *make_pid_filter(char *curr_filter, const char *field)
 {
+	int curr_len = 0, last_exclude = -1;
+	int start_pid = -1, last_pid = -1;
+	char *filter = NULL, *save;
 	struct filter_pids *p;
-	char *filter;
-	char *orit;
-	char *match;
-	char *str;
-	int curr_len = 0;
-	int len;
 
 	/* Use the new method if possible */
 	if (have_set_event_pid)
 		return NULL;
 
-	len = len_filter_pids + (strlen(field) + strlen("(==)||")) * nr_filter_pids;
-
-	if (curr_filter) {
-		curr_len = strlen(curr_filter);
-		filter = realloc(curr_filter, curr_len + len + strlen("(&&())"));
-		if (!filter)
-			die("realloc");
-		memmove(filter+1, curr_filter, curr_len);
-		filter[0] = '(';
-		strcat(filter, ")&&(");
-		curr_len = strlen(filter);
-	} else
-		filter = malloc(len);
-	if (!filter)
-		die("Failed to allocate pid filter");
-
-	/* Last '||' that is not used will cover the \0 */
-	str = filter + curr_len;
+	if (!filter_pids)
+		return curr_filter;
 
 	for (p = filter_pids; p; p = p->next) {
-		if (p->exclude) {
-			match = "!=";
-			orit = "&&";
-		} else {
-			match = "==";
-			orit = "||";
+		if (p->pid == last_pid - 1 && p->exclude == last_exclude) {
+			last_pid = p->pid;
+			continue;
 		}
-		if (p == filter_pids)
-			orit = "";
 
-		len = sprintf(str, "%s(%s%s%d)", orit, field, match, p->pid);
-		str += len;
+		if (start_pid != -1)
+			append_filter_pid_range(&filter, &curr_len, field,
+						start_pid, last_pid,
+						last_exclude);
+
+		start_pid = last_pid = p->pid;
+		last_exclude = p->exclude;
+
 	}
+	append_filter_pid_range(&filter, &curr_len, field,
+				start_pid, last_pid, last_exclude);
 
-	if (curr_len)
-		sprintf(str, ")");
+	if (curr_filter) {
+		save = filter;
+		asprintf(&filter, "(%s)&&(%s)", curr_filter, filter);
+		free(save);
+	}
 
 	return filter;
 }
-- 
2.19.1

[PATCH] .

[Slavomir Kaslev]

Signed-off-by: Slavomir Kaslev <kaslevs@vmware.com>
---
 tracecmd/trace-record.c | 110 +++++++++++++++++++++++++++-------------
 1 file changed, 74 insertions(+), 36 deletions(-)

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 76ca92d..102e5ab 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -950,6 +950,57 @@ static void update_ftrace_pids(int reset)
 static void update_event_filters(struct buffer_instance *instance);
 static void update_pid_event_filters(struct buffer_instance *instance);
 
+static void append_filter_pid_range(char **filter, int *curr_len,
+				    const char *field,
+				    int start_pid, int end_pid, bool exclude)
+{
+	char *op, *op1, *op2, *op3;
+	int len;
+
+	op = *filter && **filter ? "||" : "";
+
+	// Handle thus case explicitly so that we get `pid==3` instead of
+	// `pid>=3&&pid<=3` for singleton ranges
+	if (start_pid == end_pid) {
+#define FMT	"%s(%s%s%d)"
+		len = snprintf(NULL, 0, FMT, op,
+			       field, exclude ? "!=" : "==", start_pid);
+		*filter = realloc(*filter, *curr_len + len + 1);
+		if (!*filter)
+			die("realloc");
+
+		len = snprintf(*filter + *curr_len, len + 1, FMT, op,
+			       field, exclude ? "!=" : "==", start_pid);
+		*curr_len += len;
+
+		return;
+#undef FMT
+	}
+
+	if (exclude) {
+		op1 = "<";
+		op2 = "||";
+		op3 = ">";
+	} else {
+		op1 = ">=";
+		op2 = "&&";
+		op3 = "<=";
+	}
+
+#define FMT	"%s(%s%s%d%s%s%s%d)"
+	len = snprintf(NULL, 0, FMT, op,
+		       field, op1, start_pid, op2,
+		       field, op3, end_pid);
+	*filter = realloc(*filter, *curr_len + len + 1);
+	if (!*filter)
+		die("realloc");
+
+	len = snprintf(*filter + *curr_len, len + 1, FMT, op,
+		       field, op1, start_pid, op2,
+		       field, op3, end_pid);
+	*curr_len += len;
+}
+
 /**
  * make_pid_filter - create a filter string to all pids against @field
  * @curr_filter: Append to a previous filter (may realloc). Can be NULL
@@ -963,54 +1014,41 @@ static void update_pid_event_filters(struct buffer_instance *instance);
  */
 static char *make_pid_filter(char *curr_filter, const char *field)
 {
+	int curr_len = 0, last_exclude = -1;
+	int start_pid = -1, last_pid = -1;
+	char *filter = NULL, *save;
 	struct filter_pids *p;
-	char *filter;
-	char *orit;
-	char *match;
-	char *str;
-	int curr_len = 0;
-	int len;
 
 	/* Use the new method if possible */
 	if (have_set_event_pid)
 		return NULL;
 
-	len = len_filter_pids + (strlen(field) + strlen("(==)||")) * nr_filter_pids;
-
-	if (curr_filter) {
-		curr_len = strlen(curr_filter);
-		filter = realloc(curr_filter, curr_len + len + strlen("(&&())"));
-		if (!filter)
-			die("realloc");
-		memmove(filter+1, curr_filter, curr_len);
-		filter[0] = '(';
-		strcat(filter, ")&&(");
-		curr_len = strlen(filter);
-	} else
-		filter = malloc(len);
-	if (!filter)
-		die("Failed to allocate pid filter");
-
-	/* Last '||' that is not used will cover the \0 */
-	str = filter + curr_len;
+	if (!filter_pids)
+		return curr_filter;
 
 	for (p = filter_pids; p; p = p->next) {
-		if (p->exclude) {
-			match = "!=";
-			orit = "&&";
-		} else {
-			match = "==";
-			orit = "||";
+		if (p->pid == last_pid - 1 && p->exclude == last_exclude) {
+			last_pid = p->pid;
+			continue;
 		}
-		if (p == filter_pids)
-			orit = "";
 
-		len = sprintf(str, "%s(%s%s%d)", orit, field, match, p->pid);
-		str += len;
+		if (start_pid != -1)
+			append_filter_pid_range(&filter, &curr_len, field,
+						start_pid, last_pid,
+						last_exclude);
+
+		start_pid = last_pid = p->pid;
+		last_exclude = p->exclude;
+
 	}
+	append_filter_pid_range(&filter, &curr_len, field,
+				start_pid, last_pid, last_exclude);
 
-	if (curr_len)
-		sprintf(str, ")");
+	if (curr_filter) {
+		save = filter;
+		asprintf(&filter, "(%s)&&(%s)", curr_filter, filter);
+		free(save);
+	}
 
 	return filter;
 }
-- 
2.19.1