[LTP] [PATCH] Make getrusage04 be able to loop more times

[LTP] [PATCH] Make getrusage04 be able to loop more times

[Chunyu Hu]

The -i or -I will break when the tv_usec of timeval gets to
1000000, so usually we can't loop for too many times with -i
or -I. Approximately 1000 times loop will break with a false
positive failure:

getrusage04    0  TINFO  :  utime:       53636us; stime:      989510us
getrusage04    0  TINFO  :  utime:       53682us; stime:      999301us
getrusage04    0  TINFO  :  utime:       53718us; stime:        8906us
getrusage04    1  TFAIL  :  getrusage04.c:133: stime increased > 11000us:

Sometimes we need to run more than one second user/sys time,
here consider the carry-over to timeval.tv_sec when timeval.tv_usec
gets overflow, and print out the second info of utime and stime for
providing needed test info.

Also fix warn casused by the var types with '-Wsign-compare'

getrusage04.c:121:16: warning: comparison between signed and...
     if (udelta > 1000 + (BIAS_MAX * factor_nr)) {

Signed-off-by: Chunyu Hu <chuhu@redhat.com>
---
 testcases/kernel/syscalls/getrusage/getrusage04.c | 24 +++++++++++++++--------
 1 file changed, 16 insertions(+), 8 deletions(-)

diff --git a/testcases/kernel/syscalls/getrusage/getrusage04.c b/testcases/kernel/syscalls/getrusage/getrusage04.c
index a5b3f65..6b36cec 100644
--- a/testcases/kernel/syscalls/getrusage/getrusage04.c
+++ b/testcases/kernel/syscalls/getrusage/getrusage04.c
@@ -82,7 +82,8 @@ static void cleanup(void);
 int main(int argc, char *argv[])
 {
 	struct rusage usage;
-	unsigned long ulast, udelta, slast, sdelta;
+	unsigned long ulast, slast,  ulasts, slasts;
+	long udelta, sdelta, udeltas, sdeltas;
 	int i, lc;
 	char msg_string[BUFSIZ];
 
@@ -104,28 +105,33 @@ int main(int argc, char *argv[])
 		tst_count = 0;
 		i = 0;
 		SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
-		tst_resm(TINFO, "utime:%12luus; stime:%12luus",
-			 usage.ru_utime.tv_usec, usage.ru_stime.tv_usec);
+		tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
+			 usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
+				usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
 		ulast = usage.ru_utime.tv_usec;
 		slast = usage.ru_stime.tv_usec;
+		ulasts = usage.ru_utime.tv_sec;
+		slasts = usage.ru_stime.tv_sec;
 
 		while (i < RECORD_MAX) {
 			SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
 			udelta = usage.ru_utime.tv_usec - ulast;
 			sdelta = usage.ru_stime.tv_usec - slast;
+			udeltas = usage.ru_utime.tv_sec - ulasts;
+			sdeltas = usage.ru_stime.tv_sec - slasts;
 			if (udelta > 0 || sdelta > 0) {
 				i++;
-				tst_resm(TINFO, "utime:%12luus; stime:%12luus",
-					 usage.ru_utime.tv_usec,
-					 usage.ru_stime.tv_usec);
-				if (udelta > 1000 + (BIAS_MAX * factor_nr)) {
+				tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
+					usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
+					usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
+				if (udelta > 1000 + (BIAS_MAX * factor_nr) && !udeltas) {
 					sprintf(msg_string,
 						"utime increased > %ldus:",
 						1000 + BIAS_MAX * factor_nr);
 					tst_brkm(TFAIL, cleanup, msg_string,
 						 " delta = %luus", udelta);
 				}
-				if (sdelta > 1000 + (BIAS_MAX * factor_nr)) {
+				if (sdelta > 1000 + (BIAS_MAX * factor_nr) && !sdeltas) {
 					sprintf(msg_string,
 						"stime increased > %ldus:",
 						1000 + BIAS_MAX * factor_nr);
@@ -135,6 +141,8 @@ int main(int argc, char *argv[])
 			}
 			ulast = usage.ru_utime.tv_usec;
 			slast = usage.ru_stime.tv_usec;
+			ulasts = usage.ru_utime.tv_sec;
+			slasts = usage.ru_stime.tv_sec;
 			busyloop(100000);
 		}
 	}
-- 
1.8.3.1

[LTP] [PATCH] Make getrusage04 be able to loop more times

[Cyril Hrubis]

Hi!
>  int main(int argc, char *argv[])
>  {
>  	struct rusage usage;
> -	unsigned long ulast, udelta, slast, sdelta;
> +	unsigned long ulast, slast,  ulasts, slasts;
> +	long udelta, sdelta, udeltas, sdeltas;
>  	int i, lc;
>  	char msg_string[BUFSIZ];
>  
> @@ -104,28 +105,33 @@ int main(int argc, char *argv[])
>  		tst_count = 0;
>  		i = 0;
>  		SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
> -		tst_resm(TINFO, "utime:%12luus; stime:%12luus",
> -			 usage.ru_utime.tv_usec, usage.ru_stime.tv_usec);
> +		tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
> +			 usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
> +				usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
>  		ulast = usage.ru_utime.tv_usec;
>  		slast = usage.ru_stime.tv_usec;
> +		ulasts = usage.ru_utime.tv_sec;
> +		slasts = usage.ru_stime.tv_sec;

This is getting ugly. Why not just:

	struct timeval ulast = usage.ru_utime;
	struct timeval slast = usage.ru_stime;


>  		while (i < RECORD_MAX) {
>  			SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
>  			udelta = usage.ru_utime.tv_usec - ulast;
>  			sdelta = usage.ru_stime.tv_usec - slast;
> +			udeltas = usage.ru_utime.tv_sec - ulasts;
> +			sdeltas = usage.ru_stime.tv_sec - slasts;
>  			if (udelta > 0 || sdelta > 0) {
>  				i++;
> -				tst_resm(TINFO, "utime:%12luus; stime:%12luus",
> -					 usage.ru_utime.tv_usec,
> -					 usage.ru_stime.tv_usec);
> -				if (udelta > 1000 + (BIAS_MAX * factor_nr)) {
> +				tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
> +					usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
> +					usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
> +				if (udelta > 1000 + (BIAS_MAX * factor_nr) && !udeltas) {
>  					sprintf(msg_string,
>  						"utime increased > %ldus:",
>  						1000 + BIAS_MAX * factor_nr);
>  					tst_brkm(TFAIL, cleanup, msg_string,
>  						 " delta = %luus", udelta);
>  				}
> -				if (sdelta > 1000 + (BIAS_MAX * factor_nr)) {
> +				if (sdelta > 1000 + (BIAS_MAX * factor_nr) && !sdeltas) {

Also why do we skipp the comparsion if seconds has changed?

Computing difference for twom timeval structures is not that
complicated. I can add a helper into include/tst_timer.h if you want.

>  					sprintf(msg_string,
>  						"stime increased > %ldus:",
>  						1000 + BIAS_MAX * factor_nr);
> @@ -135,6 +141,8 @@ int main(int argc, char *argv[])
>  			}
>  			ulast = usage.ru_utime.tv_usec;
>  			slast = usage.ru_stime.tv_usec;
> +			ulasts = usage.ru_utime.tv_sec;
> +			slasts = usage.ru_stime.tv_sec;
>  			busyloop(100000);
>  		}
>  	}
> -- 
> 1.8.3.1
> 
> 
> -- 
> Mailing list info: https://lists.linux.it/listinfo/ltp

-- 
Cyril Hrubis
chrubis@suse.cz

[LTP] [PATCH] Make getrusage04 be able to loop more times

[Chunyu Hu]

----- Original Message -----
> From: "Cyril Hrubis" <chrubis@suse.cz>
> To: "Chunyu Hu" <chuhu@redhat.com>
> Cc: ltp@lists.linux.it
> Sent: Wednesday, June 7, 2017 11:13:15 PM
> Subject: Re: [LTP] [PATCH] Make getrusage04 be able to loop more times
> 
> Hi!
> >  int main(int argc, char *argv[])
> >  {
> >  	struct rusage usage;
> > -	unsigned long ulast, udelta, slast, sdelta;
> > +	unsigned long ulast, slast,  ulasts, slasts;
> > +	long udelta, sdelta, udeltas, sdeltas;
> >  	int i, lc;
> >  	char msg_string[BUFSIZ];
> >  
> > @@ -104,28 +105,33 @@ int main(int argc, char *argv[])
> >  		tst_count = 0;
> >  		i = 0;
> >  		SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
> > -		tst_resm(TINFO, "utime:%12luus; stime:%12luus",
> > -			 usage.ru_utime.tv_usec, usage.ru_stime.tv_usec);
> > +		tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
> > +			 usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
> > +				usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
> >  		ulast = usage.ru_utime.tv_usec;
> >  		slast = usage.ru_stime.tv_usec;
> > +		ulasts = usage.ru_utime.tv_sec;
> > +		slasts = usage.ru_stime.tv_sec;
> 
> This is getting ugly. Why not just:
> 
> 	struct timeval ulast = usage.ru_utime;
> 	struct timeval slast = usage.ru_stime;

OK. I'll post a V2 for this.

> 
> 
> >  		while (i < RECORD_MAX) {
> >  			SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
> >  			udelta = usage.ru_utime.tv_usec - ulast;
> >  			sdelta = usage.ru_stime.tv_usec - slast;
> > +			udeltas = usage.ru_utime.tv_sec - ulasts;
> > +			sdeltas = usage.ru_stime.tv_sec - slasts;
> >  			if (udelta > 0 || sdelta > 0) {
> >  				i++;
> > -				tst_resm(TINFO, "utime:%12luus; stime:%12luus",
> > -					 usage.ru_utime.tv_usec,
> > -					 usage.ru_stime.tv_usec);
> > -				if (udelta > 1000 + (BIAS_MAX * factor_nr)) {
> > +				tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
> > +					usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
> > +					usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
> > +				if (udelta > 1000 + (BIAS_MAX * factor_nr) && !udeltas) {
> >  					sprintf(msg_string,
> >  						"utime increased > %ldus:",
> >  						1000 + BIAS_MAX * factor_nr);
> >  					tst_brkm(TFAIL, cleanup, msg_string,
> >  						 " delta = %luus", udelta);
> >  				}
> > -				if (sdelta > 1000 + (BIAS_MAX * factor_nr)) {
> > +				if (sdelta > 1000 + (BIAS_MAX * factor_nr) && !sdeltas) {
> 
> Also why do we skipp the comparsion if seconds has changed?

OK. I'll try to consider second info in V2. 

> 
> Computing difference for twom timeval structures is not that
> complicated. I can add a helper into include/tst_timer.h if you want.

Do we have? I think we need something like below, not clear
about if this can be done with function or macro ;).

timval_minus(tv1, tv2) 
and
timeval_gt
timeval_lt
timeval_e

> 
> >  					sprintf(msg_string,
> >  						"stime increased > %ldus:",
> >  						1000 + BIAS_MAX * factor_nr);
> > @@ -135,6 +141,8 @@ int main(int argc, char *argv[])
> >  			}
> >  			ulast = usage.ru_utime.tv_usec;
> >  			slast = usage.ru_stime.tv_usec;
> > +			ulasts = usage.ru_utime.tv_sec;
> > +			slasts = usage.ru_stime.tv_sec;
> >  			busyloop(100000);
> >  		}
> >  	}
> > --
> > 1.8.3.1
> > 
> > 
> > --
> > Mailing list info: https://lists.linux.it/listinfo/ltp
> 
> --
> Cyril Hrubis
> chrubis@suse.cz
> 

-- 
Regards,
Chunyu Hu

[LTP] [PATCH] Make getrusage04 be able to loop more times

[Cyril Hrubis]

Hi!
> Do we have? I think we need something like below, not clear
> about if this can be done with function or macro ;).
> 
> timval_minus(tv1, tv2) 
> and
> timeval_gt
> timeval_lt
> timeval_e

We only need to add tst_timeval_diff_us() into tst_timer.h then we can
compare the resulting values in microsenconds. Which would mean adding
tst_timeval_to_us() and tst_timeval_diff(), then adding the
tst_timeval_diff_us() that combines these two.

It should be staturated difference though, i.e. the conversion from
timeval to microseconds should return LONG_LONG_MAX in a case that the
end result would overflow long long.

As I said I can add these into the tst_timer.h, and also fix the
timespec to us and ms conversions to be saturated.

-- 
Cyril Hrubis
chrubis@suse.cz

[LTP] [PATCH] Make getrusage04 be able to loop more times

[Chunyu Hu]

----- Original Message -----
> From: "Cyril Hrubis" <chrubis@suse.cz>
> To: "Chunyu Hu" <chuhu@redhat.com>
> Cc: ltp@lists.linux.it
> Sent: Monday, June 12, 2017 11:04:23 PM
> Subject: Re: [LTP] [PATCH] Make getrusage04 be able to loop more times
> 
> Hi!
> > Do we have? I think we need something like below, not clear
> > about if this can be done with function or macro ;).
> > 
> > timval_minus(tv1, tv2)
> > and
> > timeval_gt
> > timeval_lt
> > timeval_e
> 
> We only need to add tst_timeval_diff_us() into tst_timer.h then we can
> compare the resulting values in microsenconds. Which would mean adding
> tst_timeval_to_us() and tst_timeval_diff(), then adding the
> tst_timeval_diff_us() that combines these two.

This really sounds simpler than compare with timeval directly. But compare
with timeval directly would make it more difficult to overflow. 

> 
> It should be staturated difference though, i.e. the conversion from
> timeval to microseconds should return LONG_LONG_MAX in a case that the
> end result would overflow long long.

That makes sense. But how long would it overflow once? 

>>> print "%d" % 0xffffffffffffffff
18446744073709551615
>>> print 18446744073709551615 / 1000000
18446744073709
>>> print "%d" % 0xffffffff
4294967295
>>> print 4294967295 / 1000000
4294


> 
> As I said I can add these into the tst_timer.h, and also fix the
> timespec to us and ms conversions to be saturated.

OK. Thanks. I'll wait for your helpers before I submit a v2 for the test case.

In fact, I use the test case to reproduce an issue of getrusage on rhel-7.3
which needs about 60s.

getrusage04    0  TINFO  :  utime:6s       825358us; stime:38s       286683us
getrusage04    0  TINFO  :  utime:6s       825358us; stime:38s       287683us
getrusage04    0  TINFO  :  utime:6s       825358us; stime:38s       288683us
getrusage04    0  TINFO  :  utime:6s       825358us; stime:38s       288745us
getrusage04    0  TINFO  :  utime:6s       825362us; stime:38s       288763us
getrusage04    0  TINFO  :  utime:6s       825365us; stime:38s       290782us
getrusage04    1  TFAIL  :  getrusage04.c:195: stime increased > 2000us:


And I tried with comparing with timeval directly, I paste it here just hoping
it can provide a little idea.( just for fun) :)


diff --git a/testcases/kernel/syscalls/getrusage/getrusage04.c b/testcases/kernel/syscalls/getrusage/getrusage04.c
index a5b3f65..583b6ea 100644
--- a/testcases/kernel/syscalls/getrusage/getrusage04.c
+++ b/testcases/kernel/syscalls/getrusage/getrusage04.c
@@ -79,10 +79,65 @@ static void busyloop(long wait);
 static void setup(void);
 static void cleanup(void);
 
+#ifndef bool
+ #define bool int
+ #ifndef false
+  #define false 0
+ #endif
+ #ifndef true
+  #define true 1
+ #endif
+#endif
+
+static inline struct timeval timeval_minus(struct timeval t1, struct timeval t2)
+{
+        struct timeval result;
+        result.tv_sec = t1.tv_sec - t2.tv_sec;
+
+        result.tv_usec = t1.tv_usec >= t2.tv_usec ?
+                (t1.tv_usec - t2.tv_usec) :
+                result.tv_sec > 0 ?
+                (result.tv_sec--,t1.tv_usec + 1000000) - t2.tv_usec:
+                t1.tv_usec - t2.tv_usec;
+        return result;
+}
+
+static inline bool timeval_cmp_gt(struct timeval t1, struct timeval t2)
+{
+        return t1.tv_sec > t2.tv_sec ?
+                true : t1.tv_sec < t2.tv_sec ?
+                false : t1.tv_usec > t2.tv_usec;
+}
+
+struct timeval mk_timeval(long long sec, long long usec)
+{
+        struct timeval t = {0};
+        t.tv_sec = sec;
+        t.tv_sec += usec / 1000000;
+        t.tv_usec = usec % 1000000;
+        return t;
+}
+
+#define TIMEVAL_POSITIVE(tv) \
+({ \
+        int r;                \
+        r = (tv.tv_sec >= 0 && tv.tv_usec > 0); \
+        r; \
+})
+
+
+#define TIMEVAL_NON_NEGATIVE(tv) \
+({                                                        \
+        int r; \
+        r = (tv.tv_sec >= 0 && tv.tv_usec >= 0); \
+        r; \
+ })
+
 int main(int argc, char *argv[])
 {
         struct rusage usage;
-        unsigned long ulast, udelta, slast, sdelta;
+        struct timeval ulast, slast;
+        struct timeval udelta, sdelta;
         int i, lc;
         char msg_string[BUFSIZ];
 
@@ -104,28 +159,32 @@ int main(int argc, char *argv[])
                 tst_count = 0;
                 i = 0;
                 SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
-                tst_resm(TINFO, "utime:%12luus; stime:%12luus",
-                         usage.ru_utime.tv_usec, usage.ru_stime.tv_usec);
-                ulast = usage.ru_utime.tv_usec;
-                slast = usage.ru_stime.tv_usec;
+                tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
+                         usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
+                                usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
+
+                ulast = usage.ru_utime;
+                slast = usage.ru_stime;
 
                 while (i < RECORD_MAX) {
                         SAFE_GETRUSAGE(cleanup, RUSAGE_THREAD, &usage);
-                        udelta = usage.ru_utime.tv_usec - ulast;
-                        sdelta = usage.ru_stime.tv_usec - slast;
-                        if (udelta > 0 || sdelta > 0) {
+                        udelta = timeval_minus(usage.ru_utime, ulast);
+                        sdelta = timeval_minus(usage.ru_stime, slast);
+                        if (TIMEVAL_POSITIVE(udelta) || TIMEVAL_POSITIVE(sdelta)) {
                                 i++;
-                                tst_resm(TINFO, "utime:%12luus; stime:%12luus",
-                                         usage.ru_utime.tv_usec,
-                                         usage.ru_stime.tv_usec);
-                                if (udelta > 1000 + (BIAS_MAX * factor_nr)) {
+                                tst_resm(TINFO, "utime:%lus %12luus; stime:%lus %12luus",
+                                        usage.ru_utime.tv_sec, usage.ru_utime.tv_usec,
+                                        usage.ru_stime.tv_sec, usage.ru_stime.tv_usec);
+                                if (timeval_cmp_gt(udelta,
+                                                        mk_timeval(0, 1000 + (BIAS_MAX * factor_nr)))) {
                                         sprintf(msg_string,
                                                 "utime increased > %ldus:",
                                                 1000 + BIAS_MAX * factor_nr);
                                         tst_brkm(TFAIL, cleanup, msg_string,
                                                  " delta = %luus", udelta);
                                 }
-                                if (sdelta > 1000 + (BIAS_MAX * factor_nr)) {
+                                if (timeval_cmp_gt(sdelta,
+                                                        mk_timeval(0, 1000 + (BIAS_MAX * factor_nr)))) {
                                         sprintf(msg_string,
                                                 "stime increased > %ldus:",
                                                 1000 + BIAS_MAX * factor_nr);
@@ -133,8 +192,8 @@ int main(int argc, char *argv[])
                                                  " delta = %luus", sdelta);
                                 }
                         }
-                        ulast = usage.ru_utime.tv_usec;
-                        slast = usage.ru_stime.tv_usec;
+                        ulast = usage.ru_utime;
+                        slast = usage.ru_stime;
                         busyloop(100000);
                 }
         }
-- 
1.8.3.1



> 
> --
> Cyril Hrubis
> chrubis@suse.cz
> 

-- 
Regards,
Chunyu Hu

[LTP] [PATCH] Make getrusage04 be able to loop more times

[Cyril Hrubis]

Hi!
> > We only need to add tst_timeval_diff_us() into tst_timer.h then we can
> > compare the resulting values in microsenconds. Which would mean adding
> > tst_timeval_to_us() and tst_timeval_diff(), then adding the
> > tst_timeval_diff_us() that combines these two.
> 
> This really sounds simpler than compare with timeval directly. But compare
> with timeval directly would make it more difficult to overflow. 
> 
> > 
> > It should be staturated difference though, i.e. the conversion from
> > timeval to microseconds should return LONG_LONG_MAX in a case that the
> > end result would overflow long long.
> 
> That makes sense. But how long would it overflow once? 
> 
> >>> print "%d" % 0xffffffffffffffff
> 18446744073709551615
> >>> print 18446744073709551615 / 1000000
> 18446744073709
> >>> print "%d" % 0xffffffff
> 4294967295
> >>> print 4294967295 / 1000000
> 4294

The time_t in struct timespec and struct timeval are 64bit types on
64bit architectures, hence we can overflow 64 bit long long in a case
that the difference between two tv_sec is greater than
LLONG_MAX/1000000. It's extremly unlikely but may happen for instance if
the structures are overwritten with random mess for some reason.

-- 
Cyril Hrubis
chrubis@suse.cz