[PATCH rt-tests v1 0/2] Fix for start timestamp

[PATCH rt-tests v1 0/2] Fix for start timestamp

[Daniel Wagner]

As Mike reported, the rt_test_start() was not placed cleverly. Let's
move the code to rt_init() and avoid any further problems with it.

Daniel Wagner (2):
  rt-utils: Call get_timestmap() in rt_init()
  rt-utils: Remove empty rt_test_start()

 src/cyclictest/cyclictest.c           |  1 -
 src/include/rt-utils.h                |  2 --
 src/lib/rt-utils.c                    | 29 ++++++++++++---------------
 src/oslat/oslat.c                     |  1 -
 src/pi_tests/pi_stress.c              |  1 -
 src/pmqtest/pmqtest.c                 |  1 -
 src/ptsematest/ptsematest.c           |  1 -
 src/rt-migrate-test/rt-migrate-test.c |  1 -
 src/sched_deadline/cyclicdeadline.c   |  1 -
 src/signaltest/signaltest.c           |  1 -
 src/sigwaittest/sigwaittest.c         |  1 -
 src/ssdd/ssdd.c                       |  1 -
 src/svsematest/svsematest.c           |  1 -
 13 files changed, 13 insertions(+), 29 deletions(-)

-- 
2.32.0

[PATCH rt-tests v1 1/2] rt-utils: Call get_timestmap() in rt_init()

[Daniel Wagner]

Move the get_timestamp() from rt_test_start() to rt_init(). The idea
of rt_test_start() was to get the start timestamp right before the
'main loop' for the test starts. At least for cyclictest the
rt_test_start() was placed wrongly so that the first test cycle could
hit the pagefault when strftime() wrote into the tsbuf.

We don't have an exact semantic description what start test timestamp
means, so the simplest thing to avoid any further problems with it, is
to take the timestamp right at the beginning when the program
starts. Most test programs have a very short setup phase anyway.

Reported-by: Mike Galbraith <efault@gmx.de>
Signed-off-by: Daniel Wagner <dwagner@suse.de>
---
 src/lib/rt-utils.c | 27 ++++++++++++++-------------
 1 file changed, 14 insertions(+), 13 deletions(-)

diff --git a/src/lib/rt-utils.c b/src/lib/rt-utils.c
index d264c348ad42..11f386098867 100644
--- a/src/lib/rt-utils.c
+++ b/src/lib/rt-utils.c
@@ -490,6 +490,19 @@ void disable_trace_mark(void)
 	close_tracemark_fd();
 }
 
+static void get_timestamp(char *tsbuf)
+{
+	struct timeval tv;
+	struct tm *tm;
+	time_t t;
+
+	gettimeofday(&tv, NULL);
+	t = tv.tv_sec;
+	tm = localtime(&t);
+	/* RFC 2822-compliant date format */
+	strftime(tsbuf, MAX_TS_SIZE, "%a, %d %b %Y %T %z", tm);
+}
+
 void rt_init(int argc, char *argv[])
 {
 	int offset = 0;
@@ -514,24 +527,12 @@ void rt_init(int argc, char *argv[])
 
 		offset += len + 1;
 	}
-}
 
-static void get_timestamp(char *tsbuf)
-{
-	struct timeval tv;
-	struct tm *tm;
-	time_t t;
-
-	gettimeofday(&tv, NULL);
-	t = tv.tv_sec;
-	tm = localtime(&t);
-	/* RFC 2822-compliant date format */
-	strftime(tsbuf, MAX_TS_SIZE, "%a, %d %b %Y %T %z", tm);
+	get_timestamp(ts_start);
 }
 
 void rt_test_start(void)
 {
-	get_timestamp(ts_start);
 }
 
 void rt_write_json(const char *filename, int return_code,
-- 
2.32.0

[PATCH rt-tests v1 2/2] rt-utils: Remove empty rt_test_start()

[Daniel Wagner]

rt_test_start() is unused, remove it.

Signed-off-by: Daniel Wagner <dwagner@suse.de>
---
 src/cyclictest/cyclictest.c           | 1 -
 src/include/rt-utils.h                | 2 --
 src/lib/rt-utils.c                    | 4 ----
 src/oslat/oslat.c                     | 1 -
 src/pi_tests/pi_stress.c              | 1 -
 src/pmqtest/pmqtest.c                 | 1 -
 src/ptsematest/ptsematest.c           | 1 -
 src/rt-migrate-test/rt-migrate-test.c | 1 -
 src/sched_deadline/cyclicdeadline.c   | 1 -
 src/signaltest/signaltest.c           | 1 -
 src/sigwaittest/sigwaittest.c         | 1 -
 src/ssdd/ssdd.c                       | 1 -
 src/svsematest/svsematest.c           | 1 -
 13 files changed, 17 deletions(-)

diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
index be8285a072b4..a08c91d9f4ca 100644
--- a/src/cyclictest/cyclictest.c
+++ b/src/cyclictest/cyclictest.c
@@ -615,7 +615,6 @@ static void *timerthread(void *param)
 		setitimer(ITIMER_REAL, &itimer, NULL);
 	}
 
-	rt_test_start();
 	stat->threadstarted++;
 
 	while (!shutdown) {
diff --git a/src/include/rt-utils.h b/src/include/rt-utils.h
index f07b57d5f7c1..f6b3fede06f7 100644
--- a/src/include/rt-utils.h
+++ b/src/include/rt-utils.h
@@ -82,8 +82,6 @@ static inline int64_t calctime(struct timespec t)
 
 void rt_init(int argc, char *argv[]);
 
-void rt_test_start(void);
-
 void rt_write_json(const char *filename, int return_code,
 		   void (*cb)(FILE *, void *),
 		   void *data);
diff --git a/src/lib/rt-utils.c b/src/lib/rt-utils.c
index 11f386098867..6c0235d0d2e0 100644
--- a/src/lib/rt-utils.c
+++ b/src/lib/rt-utils.c
@@ -531,10 +531,6 @@ void rt_init(int argc, char *argv[])
 	get_timestamp(ts_start);
 }
 
-void rt_test_start(void)
-{
-}
-
 void rt_write_json(const char *filename, int return_code,
 		  void (*cb)(FILE *, void *),
 		  void *data)
diff --git a/src/oslat/oslat.c b/src/oslat/oslat.c
index 32de951f27c0..6108fede039c 100644
--- a/src/oslat/oslat.c
+++ b/src/oslat/oslat.c
@@ -854,7 +854,6 @@ int main(int argc, char *argv[])
 		printf("Test starts...\n");
 	/* Reset n_threads to always run on all the cores */
 	g.n_threads = g.n_threads_total;
-	rt_test_start();
 	run_expt(threads, g.runtime);
 
 	if (!g.quiet)
diff --git a/src/pi_tests/pi_stress.c b/src/pi_tests/pi_stress.c
index 7782ea717c55..53c6af15afac 100644
--- a/src/pi_tests/pi_stress.c
+++ b/src/pi_tests/pi_stress.c
@@ -304,7 +304,6 @@ int main(int argc, char **argv)
 	}
 	/* report */
 	banner();
-	rt_test_start();
 	start = time(NULL);
 
 	/* turn loose the threads */
diff --git a/src/pmqtest/pmqtest.c b/src/pmqtest/pmqtest.c
index edda7c69652e..6ad0a92ffb5c 100644
--- a/src/pmqtest/pmqtest.c
+++ b/src/pmqtest/pmqtest.c
@@ -582,7 +582,6 @@ int main(int argc, char *argv[])
 	sigemptyset(&sigset);
 	pthread_sigmask(SIG_SETMASK, &sigset, NULL);
 
-	rt_test_start();
 	do {
 		int newsamples = 0, newtimeoutcount = 0;
 		int minsamples = INT_MAX;
diff --git a/src/ptsematest/ptsematest.c b/src/ptsematest/ptsematest.c
index 5822164386de..821e58428e6d 100644
--- a/src/ptsematest/ptsematest.c
+++ b/src/ptsematest/ptsematest.c
@@ -468,7 +468,6 @@ int main(int argc, char *argv[])
 	maindelay.tv_sec = 0;
 	maindelay.tv_nsec = 50000000; /* 50 ms */
 
-	rt_test_start();
 	while (!shutdown) {
 		for (i = 0; i < num_threads; i++)
 			shutdown |= receiver[i].shutdown | sender[i].shutdown;
diff --git a/src/rt-migrate-test/rt-migrate-test.c b/src/rt-migrate-test/rt-migrate-test.c
index 0c4dabeee249..62cc603c983b 100644
--- a/src/rt-migrate-test/rt-migrate-test.c
+++ b/src/rt-migrate-test/rt-migrate-test.c
@@ -621,7 +621,6 @@ int main (int argc, char **argv)
 
 	setup_ftrace_marker();
 
-	rt_test_start();
 	for (loop=0; loop < nr_runs; loop++) {
 		unsigned long long end;
 
diff --git a/src/sched_deadline/cyclicdeadline.c b/src/sched_deadline/cyclicdeadline.c
index 4c81891bbe63..ffefa9e6fecb 100644
--- a/src/sched_deadline/cyclicdeadline.c
+++ b/src/sched_deadline/cyclicdeadline.c
@@ -1213,7 +1213,6 @@ int main(int argc, char **argv)
 	if (duration)
 		alarm(duration);
 
-	rt_test_start();
 	loop(sched_data, nr_threads);
 
 	for (i = 0; i < nr_threads; i++) {
diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
index 2dd22070cb5d..6e8f6b51b003 100644
--- a/src/signaltest/signaltest.c
+++ b/src/signaltest/signaltest.c
@@ -500,7 +500,6 @@ int main(int argc, char **argv)
 			      strerror(status));
 	}
 
-	rt_test_start();
 	while (!shutdown) {
 		int allstarted = 1;
 
diff --git a/src/sigwaittest/sigwaittest.c b/src/sigwaittest/sigwaittest.c
index 98a740d2cce2..d0d79df940de 100644
--- a/src/sigwaittest/sigwaittest.c
+++ b/src/sigwaittest/sigwaittest.c
@@ -652,7 +652,6 @@ int main(int argc, char *argv[])
 			    &sender[i]);
 	}
 
-	rt_test_start();
 	while (!mustshutdown) {
 		for (i = 0; i < num_threads; i++)
 			mustshutdown |= receiver[i].shutdown |
diff --git a/src/ssdd/ssdd.c b/src/ssdd/ssdd.c
index 421688c7f47c..c5307648a82d 100644
--- a/src/ssdd/ssdd.c
+++ b/src/ssdd/ssdd.c
@@ -357,7 +357,6 @@ int main(int argc, char **argv)
 			forktests(i);
 	}
 
-	rt_test_start();
 	for (i = 0; i < nforks; i++) {
 		status = do_wait(&wait_pid, &ret_sig);
 		if (status != STATE_EXITED) {
diff --git a/src/svsematest/svsematest.c b/src/svsematest/svsematest.c
index 8c55b6b7c48d..22ea7bcb7374 100644
--- a/src/svsematest/svsematest.c
+++ b/src/svsematest/svsematest.c
@@ -724,7 +724,6 @@ int main(int argc, char *argv[])
 			    &sender[i]);
 	}
 
-	rt_test_start();
 	while (!mustshutdown) {
 		for (i = 0; i < num_threads; i++)
 			mustshutdown |= receiver[i].shutdown |
-- 
2.32.0

Re: [PATCH rt-tests v1 1/2] rt-utils: Call get_timestmap() in rt_init()

[Kurt Kanzenbach]

[-- Attachment #1: Type: text/plain, Size: 854 bytes --]

Hi Daniel,

On Mon Jun 28 2021, Daniel Wagner wrote:
> Move the get_timestamp() from rt_test_start() to rt_init(). The idea
> of rt_test_start() was to get the start timestamp right before the
> 'main loop' for the test starts. At least for cyclictest the
> rt_test_start() was placed wrongly so that the first test cycle could
> hit the pagefault when strftime() wrote into the tsbuf.
>
> We don't have an exact semantic description what start test timestamp
> means, so the simplest thing to avoid any further problems with it, is
> to take the timestamp right at the beginning when the program
> starts. Most test programs have a very short setup phase anyway.
>
> Reported-by: Mike Galbraith <efault@gmx.de>
> Signed-off-by: Daniel Wagner <dwagner@suse.de>

This fixes the issue for me:

Tested-by: Kurt Kanzenbach <kurt@linutronix.de>

Thanks,
Kurt

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 861 bytes --]

Re: [PATCH rt-tests v1 1/2] rt-utils: Call get_timestmap() in rt_init()

[John Kacur]

On Mon, 28 Jun 2021, Daniel Wagner wrote:

> Move the get_timestamp() from rt_test_start() to rt_init(). The idea
> of rt_test_start() was to get the start timestamp right before the
> 'main loop' for the test starts. At least for cyclictest the
> rt_test_start() was placed wrongly so that the first test cycle could
> hit the pagefault when strftime() wrote into the tsbuf.
> 
> We don't have an exact semantic description what start test timestamp
> means, so the simplest thing to avoid any further problems with it, is
> to take the timestamp right at the beginning when the program
> starts. Most test programs have a very short setup phase anyway.
> 
> Reported-by: Mike Galbraith <efault@gmx.de>
> Signed-off-by: Daniel Wagner <dwagner@suse.de>
> ---
>  src/lib/rt-utils.c | 27 ++++++++++++++-------------
>  1 file changed, 14 insertions(+), 13 deletions(-)
> 
> diff --git a/src/lib/rt-utils.c b/src/lib/rt-utils.c
> index d264c348ad42..11f386098867 100644
> --- a/src/lib/rt-utils.c
> +++ b/src/lib/rt-utils.c
> @@ -490,6 +490,19 @@ void disable_trace_mark(void)
>  	close_tracemark_fd();
>  }
>  
> +static void get_timestamp(char *tsbuf)
> +{
> +	struct timeval tv;
> +	struct tm *tm;
> +	time_t t;
> +
> +	gettimeofday(&tv, NULL);
> +	t = tv.tv_sec;
> +	tm = localtime(&t);
> +	/* RFC 2822-compliant date format */
> +	strftime(tsbuf, MAX_TS_SIZE, "%a, %d %b %Y %T %z", tm);
> +}
> +
>  void rt_init(int argc, char *argv[])
>  {
>  	int offset = 0;
> @@ -514,24 +527,12 @@ void rt_init(int argc, char *argv[])
>  
>  		offset += len + 1;
>  	}
> -}
>  
> -static void get_timestamp(char *tsbuf)
> -{
> -	struct timeval tv;
> -	struct tm *tm;
> -	time_t t;
> -
> -	gettimeofday(&tv, NULL);
> -	t = tv.tv_sec;
> -	tm = localtime(&t);
> -	/* RFC 2822-compliant date format */
> -	strftime(tsbuf, MAX_TS_SIZE, "%a, %d %b %Y %T %z", tm);
> +	get_timestamp(ts_start);
>  }
>  
>  void rt_test_start(void)
>  {
> -	get_timestamp(ts_start);
>  }
>  
>  void rt_write_json(const char *filename, int return_code,
> -- 
> 2.32.0
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

Re: [PATCH rt-tests v1 2/2] rt-utils: Remove empty rt_test_start()

[John Kacur]

On Mon, 28 Jun 2021, Daniel Wagner wrote:

> rt_test_start() is unused, remove it.
> 
> Signed-off-by: Daniel Wagner <dwagner@suse.de>
> ---
>  src/cyclictest/cyclictest.c           | 1 -
>  src/include/rt-utils.h                | 2 --
>  src/lib/rt-utils.c                    | 4 ----
>  src/oslat/oslat.c                     | 1 -
>  src/pi_tests/pi_stress.c              | 1 -
>  src/pmqtest/pmqtest.c                 | 1 -
>  src/ptsematest/ptsematest.c           | 1 -
>  src/rt-migrate-test/rt-migrate-test.c | 1 -
>  src/sched_deadline/cyclicdeadline.c   | 1 -
>  src/signaltest/signaltest.c           | 1 -
>  src/sigwaittest/sigwaittest.c         | 1 -
>  src/ssdd/ssdd.c                       | 1 -
>  src/svsematest/svsematest.c           | 1 -
>  13 files changed, 17 deletions(-)
> 
> diff --git a/src/cyclictest/cyclictest.c b/src/cyclictest/cyclictest.c
> index be8285a072b4..a08c91d9f4ca 100644
> --- a/src/cyclictest/cyclictest.c
> +++ b/src/cyclictest/cyclictest.c
> @@ -615,7 +615,6 @@ static void *timerthread(void *param)
>  		setitimer(ITIMER_REAL, &itimer, NULL);
>  	}
>  
> -	rt_test_start();
>  	stat->threadstarted++;
>  
>  	while (!shutdown) {
> diff --git a/src/include/rt-utils.h b/src/include/rt-utils.h
> index f07b57d5f7c1..f6b3fede06f7 100644
> --- a/src/include/rt-utils.h
> +++ b/src/include/rt-utils.h
> @@ -82,8 +82,6 @@ static inline int64_t calctime(struct timespec t)
>  
>  void rt_init(int argc, char *argv[]);
>  
> -void rt_test_start(void);
> -
>  void rt_write_json(const char *filename, int return_code,
>  		   void (*cb)(FILE *, void *),
>  		   void *data);
> diff --git a/src/lib/rt-utils.c b/src/lib/rt-utils.c
> index 11f386098867..6c0235d0d2e0 100644
> --- a/src/lib/rt-utils.c
> +++ b/src/lib/rt-utils.c
> @@ -531,10 +531,6 @@ void rt_init(int argc, char *argv[])
>  	get_timestamp(ts_start);
>  }
>  
> -void rt_test_start(void)
> -{
> -}
> -
>  void rt_write_json(const char *filename, int return_code,
>  		  void (*cb)(FILE *, void *),
>  		  void *data)
> diff --git a/src/oslat/oslat.c b/src/oslat/oslat.c
> index 32de951f27c0..6108fede039c 100644
> --- a/src/oslat/oslat.c
> +++ b/src/oslat/oslat.c
> @@ -854,7 +854,6 @@ int main(int argc, char *argv[])
>  		printf("Test starts...\n");
>  	/* Reset n_threads to always run on all the cores */
>  	g.n_threads = g.n_threads_total;
> -	rt_test_start();
>  	run_expt(threads, g.runtime);
>  
>  	if (!g.quiet)
> diff --git a/src/pi_tests/pi_stress.c b/src/pi_tests/pi_stress.c
> index 7782ea717c55..53c6af15afac 100644
> --- a/src/pi_tests/pi_stress.c
> +++ b/src/pi_tests/pi_stress.c
> @@ -304,7 +304,6 @@ int main(int argc, char **argv)
>  	}
>  	/* report */
>  	banner();
> -	rt_test_start();
>  	start = time(NULL);
>  
>  	/* turn loose the threads */
> diff --git a/src/pmqtest/pmqtest.c b/src/pmqtest/pmqtest.c
> index edda7c69652e..6ad0a92ffb5c 100644
> --- a/src/pmqtest/pmqtest.c
> +++ b/src/pmqtest/pmqtest.c
> @@ -582,7 +582,6 @@ int main(int argc, char *argv[])
>  	sigemptyset(&sigset);
>  	pthread_sigmask(SIG_SETMASK, &sigset, NULL);
>  
> -	rt_test_start();
>  	do {
>  		int newsamples = 0, newtimeoutcount = 0;
>  		int minsamples = INT_MAX;
> diff --git a/src/ptsematest/ptsematest.c b/src/ptsematest/ptsematest.c
> index 5822164386de..821e58428e6d 100644
> --- a/src/ptsematest/ptsematest.c
> +++ b/src/ptsematest/ptsematest.c
> @@ -468,7 +468,6 @@ int main(int argc, char *argv[])
>  	maindelay.tv_sec = 0;
>  	maindelay.tv_nsec = 50000000; /* 50 ms */
>  
> -	rt_test_start();
>  	while (!shutdown) {
>  		for (i = 0; i < num_threads; i++)
>  			shutdown |= receiver[i].shutdown | sender[i].shutdown;
> diff --git a/src/rt-migrate-test/rt-migrate-test.c b/src/rt-migrate-test/rt-migrate-test.c
> index 0c4dabeee249..62cc603c983b 100644
> --- a/src/rt-migrate-test/rt-migrate-test.c
> +++ b/src/rt-migrate-test/rt-migrate-test.c
> @@ -621,7 +621,6 @@ int main (int argc, char **argv)
>  
>  	setup_ftrace_marker();
>  
> -	rt_test_start();
>  	for (loop=0; loop < nr_runs; loop++) {
>  		unsigned long long end;
>  
> diff --git a/src/sched_deadline/cyclicdeadline.c b/src/sched_deadline/cyclicdeadline.c
> index 4c81891bbe63..ffefa9e6fecb 100644
> --- a/src/sched_deadline/cyclicdeadline.c
> +++ b/src/sched_deadline/cyclicdeadline.c
> @@ -1213,7 +1213,6 @@ int main(int argc, char **argv)
>  	if (duration)
>  		alarm(duration);
>  
> -	rt_test_start();
>  	loop(sched_data, nr_threads);
>  
>  	for (i = 0; i < nr_threads; i++) {
> diff --git a/src/signaltest/signaltest.c b/src/signaltest/signaltest.c
> index 2dd22070cb5d..6e8f6b51b003 100644
> --- a/src/signaltest/signaltest.c
> +++ b/src/signaltest/signaltest.c
> @@ -500,7 +500,6 @@ int main(int argc, char **argv)
>  			      strerror(status));
>  	}
>  
> -	rt_test_start();
>  	while (!shutdown) {
>  		int allstarted = 1;
>  
> diff --git a/src/sigwaittest/sigwaittest.c b/src/sigwaittest/sigwaittest.c
> index 98a740d2cce2..d0d79df940de 100644
> --- a/src/sigwaittest/sigwaittest.c
> +++ b/src/sigwaittest/sigwaittest.c
> @@ -652,7 +652,6 @@ int main(int argc, char *argv[])
>  			    &sender[i]);
>  	}
>  
> -	rt_test_start();
>  	while (!mustshutdown) {
>  		for (i = 0; i < num_threads; i++)
>  			mustshutdown |= receiver[i].shutdown |
> diff --git a/src/ssdd/ssdd.c b/src/ssdd/ssdd.c
> index 421688c7f47c..c5307648a82d 100644
> --- a/src/ssdd/ssdd.c
> +++ b/src/ssdd/ssdd.c
> @@ -357,7 +357,6 @@ int main(int argc, char **argv)
>  			forktests(i);
>  	}
>  
> -	rt_test_start();
>  	for (i = 0; i < nforks; i++) {
>  		status = do_wait(&wait_pid, &ret_sig);
>  		if (status != STATE_EXITED) {
> diff --git a/src/svsematest/svsematest.c b/src/svsematest/svsematest.c
> index 8c55b6b7c48d..22ea7bcb7374 100644
> --- a/src/svsematest/svsematest.c
> +++ b/src/svsematest/svsematest.c
> @@ -724,7 +724,6 @@ int main(int argc, char *argv[])
>  			    &sender[i]);
>  	}
>  
> -	rt_test_start();
>  	while (!mustshutdown) {
>  		for (i = 0; i < num_threads; i++)
>  			mustshutdown |= receiver[i].shutdown |
> -- 
> 2.32.0
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

Re: [PATCH rt-tests v1 1/2] rt-utils: Call get_timestmap() in rt_init()

[John Kacur]

On Tue, 29 Jun 2021, Kurt Kanzenbach wrote:

> Hi Daniel,
> 
> On Mon Jun 28 2021, Daniel Wagner wrote:
> > Move the get_timestamp() from rt_test_start() to rt_init(). The idea
> > of rt_test_start() was to get the start timestamp right before the
> > 'main loop' for the test starts. At least for cyclictest the
> > rt_test_start() was placed wrongly so that the first test cycle could
> > hit the pagefault when strftime() wrote into the tsbuf.
> >
> > We don't have an exact semantic description what start test timestamp
> > means, so the simplest thing to avoid any further problems with it, is
> > to take the timestamp right at the beginning when the program
> > starts. Most test programs have a very short setup phase anyway.
> >
> > Reported-by: Mike Galbraith <efault@gmx.de>
> > Signed-off-by: Daniel Wagner <dwagner@suse.de>
> 
> This fixes the issue for me:
> 
> Tested-by: Kurt Kanzenbach <kurt@linutronix.de>
> 
> Thanks,
> Kurt
> 

thanks, added