Make getrusage04 be able to loop more times

PATCH New Chunyu Hu 2 participants 6 messages Jun 2, 2017 – Jun 13, 2017

Share & tools

Chunyu Hu

author

2017-06-02 07:28 UTC #0 lore raw

PATCH 1/1 Make getrusage04 be able to loop more times

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 <[email protected]>

---
 testcases/kernel/syscalls/getrusage/getrusage04.c | 24 +++++++++++++++--------
 1 file changed, 16 insertions(+), 8 deletions(-)

testcases/kernel/syscalls/getrusage/getrusage04.c +16 -8

index a5b3f65..6b36cec 100644
@@ -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);
 		}
 	}

Signature · 1 line

1.8.3.1

Cyril Hrubis

2017-06-07 15:13 UTC #1 lore raw

PATCH 1/1 Make getrusage04 be able to loop more times

Hi!

Quoted 12 lines

int main(int argc, char *argv[])
{

testcases/kernel/syscalls/getrusage/getrusage04.c +2 -1

 	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;

testcases/kernel/syscalls/getrusage/getrusage04.c int main(int argc, char *argv[]) · line 114

Quoted 10 lines

testcases/kernel/syscalls/getrusage/getrusage04.c +5 -2

 		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;

Quoted 14 lines

testcases/kernel/syscalls/getrusage/getrusage04.c +4 -4

 		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,

testcases/kernel/syscalls/getrusage/getrusage04.c int main(int argc, char *argv[]) · line 134

Quoted 10 lines

testcases/kernel/syscalls/getrusage/getrusage04.c +3 -1

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

Quoted 18 lines

testcases/kernel/syscalls/getrusage/getrusage04.c +2 -0

 					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);
 		}
 	}

Signature · 5 lines

1.8.3.1


-- 
Mailing list info: https://lists.linux.it/listinfo/ltp

Signature · 2 lines

Cyril Hrubis
[email protected]

Chunyu Hu

author

2017-06-09 07:42 UTC #2 lore raw

PATCH 1/1 Make getrusage04 be able to loop more times

----- Original Message -----

Quoted 32 lines

From: "Cyril Hrubis" <[email protected]>
To: "Chunyu Hu" <[email protected]>
Cc: [email protected]
Sent: Wednesday, June 7, 2017 11:13:15 PM
Subject: Re: [LTP] [PATCH] Make getrusage04 be able to loop more times
Hi!
Quoted 12 lines
int main(int argc, char *argv[])
{
testcases/kernel/syscalls/getrusage/getrusage04.c +2 -1
 	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;
testcases/kernel/syscalls/getrusage/getrusage04.c int main(int argc, char *argv[]) · line 114
Quoted 10 lines
testcases/kernel/syscalls/getrusage/getrusage04.c +5 -2
 		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:

Quoted 2 lines

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

OK. I'll post a V2 for this.

Quoted 20 lines

testcases/kernel/syscalls/getrusage/getrusage04.c +6 -4

 		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:",

Quoted 8 lines

testcases/kernel/syscalls/getrusage/getrusage04.c int main(int argc, char *argv[]) · line 134
Quoted 6 lines
testcases/kernel/syscalls/getrusage/getrusage04.c +1 -1
 						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.

Quoted 3 lines

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

Quoted 24 lines

Quoted 17 lines

testcases/kernel/syscalls/getrusage/getrusage04.c +2 -1

 					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

Quoted 2 lines

--
Mailing list info: https://lists.linux.it/listinfo/ltp

--
Cyril Hrubis
[email protected]

Signature · 2 lines

Regards,
Chunyu Hu

Cyril Hrubis

2017-06-12 15:04 UTC #3 lore raw

PATCH 1/1 Make getrusage04 be able to loop more times

Hi!

Quoted 8 lines

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.

Signature · 2 lines

Cyril Hrubis
[email protected]

Chunyu Hu

author

2017-06-13 11:47 UTC #4 lore raw

PATCH 1/1 Make getrusage04 be able to loop more times

----- Original Message -----

Quoted 16 lines

From: "Cyril Hrubis" <[email protected]>
To: "Chunyu Hu" <[email protected]>
Cc: [email protected]
Sent: Monday, June 12, 2017 11:04:23 PM
Subject: Re: [LTP] [PATCH] Make getrusage04 be able to loop more times
Hi!
Quoted 8 lines
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

Quoted 4 lines

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.

Quoted 4 lines

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?

Quoted 1 line

Quoted 1 line
Quoted 1 line
print "%d" % 0xffffffffffffffff

18446744073709551615

Quoted 1 line

Quoted 1 line
Quoted 1 line
print 18446744073709551615 / 1000000

18446744073709

Quoted 1 line

Quoted 1 line
Quoted 1 line
print "%d" % 0xffffffff

4294967295

Quoted 1 line

Quoted 1 line
Quoted 1 line
print 4294967295 / 1000000

4294

Quoted 3 lines

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) :)

testcases/kernel/syscalls/getrusage/getrusage04.c +74 ~~-15~~

index a5b3f65..583b6ea 100644
@@ -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);
                 }
         }

Signature · 1 line

1.8.3.1

Quoted 5 lines

--
Cyril Hrubis
[email protected]

Signature · 2 lines

Regards,
Chunyu Hu

Cyril Hrubis

2017-06-13 12:58 UTC #5 lore raw

PATCH 1/1 Make getrusage04 be able to loop more times

Hi!

Quoted 15 lines

Quoted 4 lines
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.
Quoted 4 lines
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?

Quoted 8 lines

Quoted 1 line
Quoted 1 line
Quoted 1 line
print "%d" % 0xffffffffffffffff
18446744073709551615
Quoted 1 line
Quoted 1 line
Quoted 1 line
print 18446744073709551615 / 1000000
18446744073709
Quoted 1 line
Quoted 1 line
Quoted 1 line
print "%d" % 0xffffffff
4294967295
Quoted 1 line
Quoted 1 line
Quoted 1 line
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.

Signature · 2 lines

Cyril Hrubis
[email protected]