[PATCH 0/5] rt-tests: Mostly signaltest clean up

[PATCH 0/5] rt-tests: Mostly signaltest clean up

[Sebastian Andrzej Siewior]

Patch #1 is old, I noticed it it is still uncommited from last time.

Patch #2 - #4 is cleanup of signaltest to get it to work with the break
value argument so I could trace.

Patch #5 is only for Daniel and not for merging.

[PATCH 1/5] cyclictest: Only report the first incident

[Sebastian Andrzej Siewior]

Record only the first inciding inlcuding tid, value and trace event.
If multiple threads exceed the limit then the reported `tid' might not
match the reported value.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 src/cyclictest/cyclictest.c | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)

diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
index 34aa9be583f85..777da26d7bdc3 100644
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -718,13 +718,14 @@ static void *timerthread(void *param)
 
 		if (!stopped && tracelimit && (diff > tracelimit)) {
 			stopped++;
-			tracemark("hit latency threshold (%llu > %d)",
-				  (unsigned long long) diff, tracelimit);
 			shutdown++;
 			pthread_mutex_lock(&break_thread_id_lock);
-			if (break_thread_id == 0)
+			if (break_thread_id == 0) {
 				break_thread_id = stat->tid;
-			break_thread_value = diff;
+				tracemark("hit latency threshold (%llu > %d)",
+					  (unsigned long long) diff, tracelimit);
+				break_thread_value = diff;
+			}
 			pthread_mutex_unlock(&break_thread_id_lock);
 		}
 		stat->act = diff;
-- 
2.29.2

Re: [PATCH 1/5] cyclictest: Only report the first incident

[John Kacur]

On Tue, 10 Nov 2020, Sebastian Andrzej Siewior wrote:

> Record only the first inciding inlcuding tid, value and trace event.
> If multiple threads exceed the limit then the reported `tid' might not
> match the reported value.
> 
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
>  src/cyclictest/cyclictest.c | 9 +++++----
>  1 file changed, 5 insertions(+), 4 deletions(-)
> 
> diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
> index 34aa9be583f85..777da26d7bdc3 100644
> --- a/src/cyclictest/cyclictest.c
> +++ b/src/cyclictest/cyclictest.c
> @@ -718,13 +718,14 @@ static void *timerthread(void *param)
>  
>  		if (!stopped && tracelimit && (diff > tracelimit)) {
>  			stopped++;
> -			tracemark("hit latency threshold (%llu > %d)",
> -				  (unsigned long long) diff, tracelimit);
>  			shutdown++;
>  			pthread_mutex_lock(&break_thread_id_lock);
> -			if (break_thread_id == 0)
> +			if (break_thread_id == 0) {
>  				break_thread_id = stat->tid;
> -			break_thread_value = diff;
> +				tracemark("hit latency threshold (%llu > %d)",
> +					  (unsigned long long) diff, tracelimit);
> +				break_thread_value = diff;
> +			}
>  			pthread_mutex_unlock(&break_thread_id_lock);
>  		}
>  		stat->act = diff;
> -- 
> 2.29.2
> 
> 
  - minor grammar and spelling edit
    Signed-off-by: John Kacur <jkacur@redhat.com>

[PATCH 2/5] signaltest: Remove drunk code

[Sebastian Andrzej Siewior]

`oldtrace' is set for kernels prior 2.6.18. Remove "support" for them.

The alternative code (for new kernels) issues
	prctl(0, [01]);

which is not valid the kernel returns an error. I have no idea what its
purpose is, remove it.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 src/signaltest/signaltest.c | 29 -----------------------------
 1 file changed, 29 deletions(-)

diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
index 1cc3236a8f377..aceb714d3e9d3 100644
--- a/src/signaltest/signaltest.c
+++ b/src/signaltest/signaltest.c
@@ -62,7 +62,6 @@ struct thread_stat {
 
 static int shutdown;
 static int tracelimit;
-static int oldtrace;
 
 
 /*
@@ -105,13 +104,6 @@ void *signalthread(void *param)
 
 	stat->threadstarted++;
 
-	if (tracelimit) {
-		if (oldtrace)
-			gettimeofday(0, (struct timezone *)1);
-		else
-			prctl(0, 1);
-	}
-
 	clock_gettime(CLOCK_MONOTONIC, &before);
 
 	while (!shutdown) {
@@ -152,10 +144,6 @@ void *signalthread(void *param)
 
 		if (!stopped && tracelimit && (diff > tracelimit)) {
 			stopped++;
-			if (oldtrace)
-				gettimeofday(0, 0);
-			else
-				prctl(0, 0);
 			shutdown++;
 		}
 		stat->act = diff;
@@ -260,21 +248,6 @@ static void process_options(int argc, char *argv[])
 		display_help(error);
 }
 
-static void check_kernel(void)
-{
-	size_t len;
-	char ver[256];
-	int fd, maj, min, sub;
-
-	fd = open("/proc/version", O_RDONLY, 0666);
-	len = read(fd, ver, 255);
-	close(fd);
-	ver[len-1] = 0x0;
-	sscanf(ver, "Linux version %d.%d.%d", &maj, &min, &sub);
-	if (maj == 2 && min == 6 && sub < 18)
-		oldtrace = 1;
-}
-
 static void sighand(int sig)
 {
 	shutdown = 1;
@@ -323,8 +296,6 @@ int main(int argc, char **argv)
 			goto out;
 		}
 
-	check_kernel();
-
 	sigemptyset(&sigset);
 	sigaddset(&sigset, signum);
 	sigprocmask(SIG_BLOCK, &sigset, NULL);
-- 
2.29.2

Re: [PATCH 2/5] signaltest: Remove drunk code

[John Kacur]

On Tue, 10 Nov 2020, Sebastian Andrzej Siewior wrote:

> `oldtrace' is set for kernels prior 2.6.18. Remove "support" for them.
> 
> The alternative code (for new kernels) issues
> 	prctl(0, [01]);
> 
> which is not valid the kernel returns an error. I have no idea what its
> purpose is, remove it.
> 
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
>  src/signaltest/signaltest.c | 29 -----------------------------
>  1 file changed, 29 deletions(-)
> 
> diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
> index 1cc3236a8f377..aceb714d3e9d3 100644
> --- a/src/signaltest/signaltest.c
> +++ b/src/signaltest/signaltest.c
> @@ -62,7 +62,6 @@ struct thread_stat {
>  
>  static int shutdown;
>  static int tracelimit;
> -static int oldtrace;
>  
>  
>  /*
> @@ -105,13 +104,6 @@ void *signalthread(void *param)
>  
>  	stat->threadstarted++;
>  
> -	if (tracelimit) {
> -		if (oldtrace)
> -			gettimeofday(0, (struct timezone *)1);
> -		else
> -			prctl(0, 1);
> -	}
> -
>  	clock_gettime(CLOCK_MONOTONIC, &before);
>  
>  	while (!shutdown) {
> @@ -152,10 +144,6 @@ void *signalthread(void *param)
>  
>  		if (!stopped && tracelimit && (diff > tracelimit)) {
>  			stopped++;
> -			if (oldtrace)
> -				gettimeofday(0, 0);
> -			else
> -				prctl(0, 0);
>  			shutdown++;
>  		}
>  		stat->act = diff;
> @@ -260,21 +248,6 @@ static void process_options(int argc, char *argv[])
>  		display_help(error);
>  }
>  
> -static void check_kernel(void)
> -{
> -	size_t len;
> -	char ver[256];
> -	int fd, maj, min, sub;
> -
> -	fd = open("/proc/version", O_RDONLY, 0666);
> -	len = read(fd, ver, 255);
> -	close(fd);
> -	ver[len-1] = 0x0;
> -	sscanf(ver, "Linux version %d.%d.%d", &maj, &min, &sub);
> -	if (maj == 2 && min == 6 && sub < 18)
> -		oldtrace = 1;
> -}
> -
>  static void sighand(int sig)
>  {
>  	shutdown = 1;
> @@ -323,8 +296,6 @@ int main(int argc, char **argv)
>  			goto out;
>  		}
>  
> -	check_kernel();
> -
>  	sigemptyset(&sigset);
>  	sigaddset(&sigset, signum);
>  	sigprocmask(SIG_BLOCK, &sigset, NULL);
> -- 
> 2.29.2
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

[PATCH 3/5] signaltest: Don't expect trace interface at /proc

[Sebastian Andrzej Siewior]

This was never merged.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 src/signaltest/signaltest.c | 13 -------------
 1 file changed, 13 deletions(-)

diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
index aceb714d3e9d3..84eb8827faa5e 100644
--- a/src/signaltest/signaltest.c
+++ b/src/signaltest/signaltest.c
@@ -79,19 +79,6 @@ void *signalthread(void *param)
 	int stopped = 0;
 	int first = 1;
 
-	if (tracelimit) {
-		system("echo 1 > /proc/sys/kernel/trace_all_cpus");
-		system("echo 1 > /proc/sys/kernel/trace_enabled");
-		system("echo 1 > /proc/sys/kernel/trace_freerunning");
-		system("echo 0 > /proc/sys/kernel/trace_print_at_crash");
-		system("echo 1 > /proc/sys/kernel/trace_user_triggered");
-		system("echo -1 > /proc/sys/kernel/trace_user_trigger_irq");
-		system("echo 0 > /proc/sys/kernel/trace_verbose");
-		system("echo 0 > /proc/sys/kernel/preempt_thresh");
-		system("echo 0 > /proc/sys/kernel/wakeup_timing");
-		system("echo 0 > /proc/sys/kernel/preempt_max_latency");
-	}
-
 	stat->tid = gettid();
 
 	sigemptyset(&sigset);
-- 
2.29.2

Re: [PATCH 3/5] signaltest: Don't expect trace interface at /proc

[John Kacur]

On Tue, 10 Nov 2020, Sebastian Andrzej Siewior wrote:

> This was never merged.
> 
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
>  src/signaltest/signaltest.c | 13 -------------
>  1 file changed, 13 deletions(-)
> 
> diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
> index aceb714d3e9d3..84eb8827faa5e 100644
> --- a/src/signaltest/signaltest.c
> +++ b/src/signaltest/signaltest.c
> @@ -79,19 +79,6 @@ void *signalthread(void *param)
>  	int stopped = 0;
>  	int first = 1;
>  
> -	if (tracelimit) {
> -		system("echo 1 > /proc/sys/kernel/trace_all_cpus");
> -		system("echo 1 > /proc/sys/kernel/trace_enabled");
> -		system("echo 1 > /proc/sys/kernel/trace_freerunning");
> -		system("echo 0 > /proc/sys/kernel/trace_print_at_crash");
> -		system("echo 1 > /proc/sys/kernel/trace_user_triggered");
> -		system("echo -1 > /proc/sys/kernel/trace_user_trigger_irq");
> -		system("echo 0 > /proc/sys/kernel/trace_verbose");
> -		system("echo 0 > /proc/sys/kernel/preempt_thresh");
> -		system("echo 0 > /proc/sys/kernel/wakeup_timing");
> -		system("echo 0 > /proc/sys/kernel/preempt_max_latency");
> -	}
> -
>  	stat->tid = gettid();
>  
>  	sigemptyset(&sigset);
> -- 
> 2.29.2
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

[PATCH 4/5] signaltest: Fix break value argument

[Sebastian Andrzej Siewior]

The break value '-b' is not working properly:
- Every thread may hit the break value. This is expected for thread
  number > 0 because thread number 0 sleeps every 16 iterations to give
  the system time to breath. This delay may wrongly trigger as the break
  value.

- If a thread hits the break value then it returns signaling "shutdown".
  The main thread will then SIGTERM to each of the remaining threads.
  This is a nop because this signal is blocked.
  Send SIGUSR1 instead which is waited for.

While doing all of this, report the actual `max' value.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 src/signaltest/signaltest.c | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
index 84eb8827faa5e..dacaa63673c48 100644
--- a/src/signaltest/signaltest.c
+++ b/src/signaltest/signaltest.c
@@ -58,6 +58,7 @@ struct thread_stat {
 	pthread_t tothread;
 	int threadstarted;
 	int tid;
+	int interrupted;
 };
 
 static int shutdown;
@@ -123,13 +124,16 @@ void *signalthread(void *param)
 
 		diff = calcdiff(after, before);
 		before = now;
+
 		if (diff < stat->min)
 			stat->min = diff;
 		if (diff > stat->max)
 			stat->max = diff;
 		stat->avg += (double) diff;
 
-		if (!stopped && tracelimit && (diff > tracelimit)) {
+		if (!stopped && tracelimit && !par->id  && (diff > tracelimit)) {
+			stat->act = diff;
+			stat->interrupted = 1;
 			stopped++;
 			shutdown++;
 		}
@@ -376,11 +380,12 @@ int main(int argc, char **argv)
 		quiet = 2;
 	for (i = 0; i < num_threads; i++) {
 		if (stat[i].threadstarted > 0)
-			pthread_kill(stat[i].thread, SIGTERM);
+			pthread_kill(stat[i].thread, SIGUSR1);
+		if (stat[i].interrupted)
+			printf("Thread %d exceeded trace limit.\n", i);
 		if (stat[i].threadstarted) {
 			pthread_join(stat[i].thread, NULL);
-			if (quiet && (i == 0))
-				print_stat(&par[i], i, 0);
+			print_stat(&par[i], i, 0);
 		}
 		if (stat[i].values)
 			free(stat[i].values);
-- 
2.29.2

Re: [PATCH 4/5] signaltest: Fix break value argument

[John Kacur]

On Tue, 10 Nov 2020, Sebastian Andrzej Siewior wrote:

> The break value '-b' is not working properly:
> - Every thread may hit the break value. This is expected for thread
>   number > 0 because thread number 0 sleeps every 16 iterations to give
>   the system time to breath. This delay may wrongly trigger as the break
>   value.
> 
> - If a thread hits the break value then it returns signaling "shutdown".
>   The main thread will then SIGTERM to each of the remaining threads.
>   This is a nop because this signal is blocked.
>   Send SIGUSR1 instead which is waited for.
> 
> While doing all of this, report the actual `max' value.
> 
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
>  src/signaltest/signaltest.c | 13 +++++++++----
>  1 file changed, 9 insertions(+), 4 deletions(-)
> 
> diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
> index 84eb8827faa5e..dacaa63673c48 100644
> --- a/src/signaltest/signaltest.c
> +++ b/src/signaltest/signaltest.c
> @@ -58,6 +58,7 @@ struct thread_stat {
>  	pthread_t tothread;
>  	int threadstarted;
>  	int tid;
> +	int interrupted;
>  };
>  
>  static int shutdown;
> @@ -123,13 +124,16 @@ void *signalthread(void *param)
>  
>  		diff = calcdiff(after, before);
>  		before = now;
> +
>  		if (diff < stat->min)
>  			stat->min = diff;
>  		if (diff > stat->max)
>  			stat->max = diff;
>  		stat->avg += (double) diff;
>  
> -		if (!stopped && tracelimit && (diff > tracelimit)) {
> +		if (!stopped && tracelimit && !par->id  && (diff > tracelimit)) {
> +			stat->act = diff;
> +			stat->interrupted = 1;
>  			stopped++;
>  			shutdown++;
>  		}
> @@ -376,11 +380,12 @@ int main(int argc, char **argv)
>  		quiet = 2;
>  	for (i = 0; i < num_threads; i++) {
>  		if (stat[i].threadstarted > 0)
> -			pthread_kill(stat[i].thread, SIGTERM);
> +			pthread_kill(stat[i].thread, SIGUSR1);
> +		if (stat[i].interrupted)
> +			printf("Thread %d exceeded trace limit.\n", i);
>  		if (stat[i].threadstarted) {
>  			pthread_join(stat[i].thread, NULL);
> -			if (quiet && (i == 0))
> -				print_stat(&par[i], i, 0);
> +			print_stat(&par[i], i, 0);
>  		}
>  		if (stat[i].values)
>  			free(stat[i].values);
> -- 
> 2.29.2
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

[PATCH 5/5] signaltest: Add tracing bits

[Sebastian Andrzej Siewior]

This isn't intended for merging.
This is just for Daniel to help him with tracing.

The intention:
- TH0 waits for a signal
- TH1 waits for a signal
- main thread sends a signal to TH1
- TH0 wakes up, sends a signal to TH1, waits for SIGNAL
- TH1 wakes up, sends a signal to TH0, waits for SIGNAL
- loop begin.
  - TH0 wakes up, measures the delay between sending a signal and
    receiving a signal. Sends a signal to TH1.
  - TH1 wakes up, sends a signal to TH0, waits for SIGNAL
  - loop end.

There is nothing that pins the two threads. So the scheduler might be
busy to move them from CPU to another. Pinning everything to one CPU
might make a difference.

  taskset -c 1 ~/signaltest -m -p 98 -b 400

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 src/signaltest/signaltest.c | 47 ++++++++++++++++++++++++++++++++++++-
 1 file changed, 46 insertions(+), 1 deletion(-)

diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
index dacaa63673c48..b504eef149cd9 100644
--- a/src/signaltest/signaltest.c
+++ b/src/signaltest/signaltest.c
@@ -65,6 +65,25 @@ static int shutdown;
 static int tracelimit;
 
 
+static int trace_marker = -1;
+
+static void trace_log(const char *s)
+{
+	write(trace_marker, s, strlen(s));
+}
+
+
+static int trace_switch = -1;
+
+static void trace_on(void)
+{
+	write(trace_switch, "1", 1);
+}
+
+static void trace_off(void)
+{
+	write(trace_switch, "0", 1);
+}
 /*
  * signal thread
  *
@@ -99,8 +118,10 @@ void *signalthread(void *param)
 		long diff;
 		int sigs;
 
+		trace_log("Before sigwait\n");
 		if (sigwait(&sigset, &sigs) < 0)
 			goto out;
+		trace_log("After sigwait\n");
 
 		clock_gettime(CLOCK_MONOTONIC, &after);
 
@@ -108,12 +129,17 @@ void *signalthread(void *param)
 		 * If it is the first thread, sleep after every 16
 		 * round trips.
 		 */
-		if (!par->id && !(stat->cycles & 0x0F))
+		if (!par->id && !(stat->cycles & 0x0F)) {
+			trace_log("Before sleep\n");
 			usleep(10000);
+			trace_log("After sleep\n");
+		}
 
 		/* Get current time */
 		clock_gettime(CLOCK_MONOTONIC, &now);
+		trace_log("Before phtread_kill\n");
 		pthread_kill(stat->tothread, SIGUSR1);
+		trace_log("After phtread_kill\n");
 
 		/* Skip the first cycle */
 		if (first) {
@@ -136,6 +162,7 @@ void *signalthread(void *param)
 			stat->interrupted = 1;
 			stopped++;
 			shutdown++;
+			trace_log("trace_limit\n");
 		}
 		stat->act = diff;
 		stat->cycles++;
@@ -154,6 +181,7 @@ void *signalthread(void *param)
 
 	stat->threadstarted = -1;
 
+	trace_off();
 	return NULL;
 }
 
@@ -242,6 +270,7 @@ static void process_options(int argc, char *argv[])
 static void sighand(int sig)
 {
 	shutdown = 1;
+	trace_off();
 }
 
 static void print_stat(struct thread_param *par, int index, int verbose)
@@ -287,6 +316,18 @@ int main(int argc, char **argv)
 			goto out;
 		}
 
+	trace_marker = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY);
+	if (trace_marker < 0) {
+		printf("Failed to open trace_marker: %m\n");
+		exit(1);
+	}
+
+	trace_switch = open("/sys/kernel/debug/tracing/tracing_on", O_WRONLY);
+	if (trace_switch < 0) {
+		printf("Failed to open trace_marker: %m\n");
+		exit(1);
+	}
+
 	sigemptyset(&sigset);
 	sigaddset(&sigset, signum);
 	sigprocmask(SIG_BLOCK, &sigset, NULL);
@@ -305,6 +346,7 @@ int main(int argc, char **argv)
 	if (!stat)
 		goto outpar;
 
+	trace_on();
 	for (i = 0; i < num_threads; i++) {
 		if (verbose) {
 			stat[i].values = calloc(VALBUF_SIZE, sizeof(long));
@@ -348,7 +390,9 @@ int main(int argc, char **argv)
 		stat[i].tothread = stat[0].thread;
 		break;
 	}
+	trace_log("Main phtread_kill\n");
 	pthread_kill(stat[0].thread, signum);
+	trace_log("Main phtread_kill post\n");
 
 	while (!shutdown) {
 		char lavg[256];
@@ -374,6 +418,7 @@ int main(int argc, char **argv)
 	}
 	ret = 0;
  outall:
+	trace_off();
 	shutdown = 1;
 	usleep(50000);
 	if (quiet)
-- 
2.29.2