diff mbox

[i-g-t] tests/gem_exec_nop: Improved test run time

Message ID 1446568185-675-1-git-send-email-derek.j.morton@intel.com (mailing list archive)
State New, archived
Headers show

Commit Message

Derek Morton Nov. 3, 2015, 4:29 p.m. UTC
Reduced the Sleep period to 200mS and reduced the repetition count to 7
to decrease the test run time significantly.

Also fixed a non ascii character that messed up the results table formatting.

Signed-off-by: Derek Morton <derek.j.morton@intel.com>
---
 tests/gem_exec_nop.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

Comments

Chris Wilson Nov. 3, 2015, 4:39 p.m. UTC | #1
On Tue, Nov 03, 2015 at 04:29:45PM +0000, Derek Morton wrote:
> Reduced the Sleep period to 200mS and reduced the repetition count to 7
> to decrease the test run time significantly.
> 
> Also fixed a non ascii character that messed up the results table formatting.

Pardon? Are you working around someone else's bug?
 
> Signed-off-by: Derek Morton <derek.j.morton@intel.com>
> ---
>  tests/gem_exec_nop.c | 6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/tests/gem_exec_nop.c b/tests/gem_exec_nop.c
> index a287d08..5028145 100644
> --- a/tests/gem_exec_nop.c
> +++ b/tests/gem_exec_nop.c
> @@ -133,7 +133,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>  	gem_sync(fd, handle);
>  
>  	for (count = 1; count <= SLOW_QUICK(1<<17, 1<<4); count <<= 1) {
> -		const int reps = 13;
> +		const int reps = 7;
>  		igt_stats_t stats;
>  		int n;
>  
> @@ -142,7 +142,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>  		for (n = 0; n < reps; n++) {
>  			struct timespec start, end;
>  			int loops = count;
> -			sleep(1); /* wait for the hw to go back to sleep */
> +			usleep(200000); /* wait 200mS for the hw to go back to sleep */
>  			clock_gettime(CLOCK_MONOTONIC, &start);
>  			while (loops--)
>  				do_ioctl(fd, DRM_IOCTL_I915_GEM_EXECBUFFER2, &execbuf);
> @@ -151,7 +151,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>  			igt_stats_push(&stats, elapsed(&start, &end, count));
>  		}
>  
> -		igt_info("Time to exec x %d:		%7.3fµs (ring=%s)\n",
> +		igt_info("Time to exec x %d:		%7.3fuS (ring=%s)\n",

Did SI change the standard unit of measurement for time?
-Chris
Derek Morton Nov. 4, 2015, 1:40 p.m. UTC | #2
>
>
>-----Original Message-----
>From: Chris Wilson [mailto:chris@chris-wilson.co.uk] 
>Sent: Tuesday, November 3, 2015 4:40 PM
>To: Morton, Derek J
>Cc: intel-gfx@lists.freedesktop.org; Wood, Thomas; Gore, Tim
>Subject: Re: [PATCH i-g-t] tests/gem_exec_nop: Improved test run time
>
>On Tue, Nov 03, 2015 at 04:29:45PM +0000, Derek Morton wrote:
>> Reduced the Sleep period to 200mS and reduced the repetition count to 
>> 7 to decrease the test run time significantly.
>> 
>> Also fixed a non ascii character that messed up the results table formatting.
>
>Pardon? Are you working around someone else's bug?

> 
>> Signed-off-by: Derek Morton <derek.j.morton@intel.com>
>> ---
>>  tests/gem_exec_nop.c | 6 +++---
>>  1 file changed, 3 insertions(+), 3 deletions(-)
>> 
>> diff --git a/tests/gem_exec_nop.c b/tests/gem_exec_nop.c index 
>> a287d08..5028145 100644
>> --- a/tests/gem_exec_nop.c
>> +++ b/tests/gem_exec_nop.c
>> @@ -133,7 +133,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>>  	gem_sync(fd, handle);
>>  
>>  	for (count = 1; count <= SLOW_QUICK(1<<17, 1<<4); count <<= 1) {
>> -		const int reps = 13;
>> +		const int reps = 7;
>>  		igt_stats_t stats;
>>  		int n;
>>  
>> @@ -142,7 +142,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>>  		for (n = 0; n < reps; n++) {
>>  			struct timespec start, end;
>>  			int loops = count;
>> -			sleep(1); /* wait for the hw to go back to sleep */
>> +			usleep(200000); /* wait 200mS for the hw to go back to sleep */
>>  			clock_gettime(CLOCK_MONOTONIC, &start);
>>  			while (loops--)
>>  				do_ioctl(fd, DRM_IOCTL_I915_GEM_EXECBUFFER2, &execbuf); @@ -151,7 
>> +151,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>>  			igt_stats_push(&stats, elapsed(&start, &end, count));
>>  		}
>>  
>> -		igt_info("Time to exec x %d:		%7.3fµs (ring=%s)\n",
>> +		igt_info("Time to exec x %d:		%7.3fuS (ring=%s)\n",
>
>Did SI change the standard unit of measurement for time?

Before my patch the test output looks like:
Starting subtest: render
RPS frequency range [200, 600]
Time to exec x 1:		535.017Time to exec x 2:		401.132Time to exec x 4:		291.106Time to exec x 8:		229.292Time to exec x 16:		219.579Time to exec x 32:		186.793Time to exec x 64:		185.509Time to exec x 128:		186.183Time to exec x 256:		166.506Time to exec x 512:		159.418Time to exec x 1024:		142.648Time to exec x 2048:		116.864Time to exec x 4096:		 91.829Time to exec x 8192:		 75.913Time to exec x 16384:		 70.119Time to exec x 32768:		 64.604Time to exec x 65536:		 64.213Time to exec x 131072:		 61.843Subtest render: SUCCESS (457.063s)
Test requirement passed: min > 0
Setting min/max to 200MHz
Test requirement passed: sysfs_write("gt_min_freq_mhz", min) == 0 && sysfs_write("gt_max_freq_mhz", min) == 0
Test requirement passed: max > 0
Setting min/max to 600MHz
Test requirement passed: sysfs_write("gt_max_freq_mhz", max) == 0 && sysfs_write("gt_min_freq_mhz", max) == 0


With my patch it looks like:
Starting subtest: render
RPS frequency range [200, 600]
Time to exec x 1:		693.088uS (ring=render)
Time to exec x 2:		435.635uS (ring=render)
Time to exec x 4:		333.473uS (ring=render)
Time to exec x 8:		286.832uS (ring=render)
Time to exec x 16:		168.929uS (ring=render)
Time to exec x 32:		169.966uS (ring=render)
Time to exec x 64:		202.545uS (ring=render)
Time to exec x 128:		198.233uS (ring=render)
Time to exec x 256:		165.126uS (ring=render)
Time to exec x 512:		155.830uS (ring=render)
Time to exec x 1024:		124.994uS (ring=render)
Time to exec x 2048:		 96.887uS (ring=render)
Time to exec x 4096:		 85.416uS (ring=render)
Time to exec x 8192:		 74.398uS (ring=render)
Time to exec x 16384:		 74.131uS (ring=render)
Time to exec x 32768:		 63.949uS (ring=render)
Time to exec x 65536:		 61.973uS (ring=render)
Time to exec x 131072:		 61.645uS (ring=render)
Subtest render: SUCCESS (143.826s)
Test requirement passed: min > 0
Setting min/max to 200MHz
Test requirement passed: sysfs_write("gt_min_freq_mhz", min) == 0 && sysfs_write("gt_max_freq_mhz", min) == 0
Test requirement passed: max > 0
Setting min/max to 600MHz
Test requirement passed: sysfs_write("gt_max_freq_mhz", max) == 0 && sysfs_write("gt_min_freq_mhz", max) == 0

So the 'µ' character is causing problems.

I have done some more investigations and have found a change you made to igt_core.c in June to be the cause.
You added:
	if (isatty(STDOUT_FILENO))
		setlocale(LC_ALL, "");
to common_init()

I added some debug and the setlocale() on android is returning 'C' so is forcing standard ascii to be used. As 'µ' is not an ascii character it causes problems.

So I think if you want to continue allow setting a locale to a lowest common denominator (ascii) then all the text printed by tests also needs to conform to ascii and this change is valid.

//Derek

>-Chris
>
>--
>Chris Wilson, Intel Open Source Technology Centre
>
Chris Wilson Nov. 4, 2015, 1:55 p.m. UTC | #3
On Wed, Nov 04, 2015 at 01:40:45PM +0000, Morton, Derek J wrote:
> >
> >
> >-----Original Message-----
> >From: Chris Wilson [mailto:chris@chris-wilson.co.uk] 
> >Sent: Tuesday, November 3, 2015 4:40 PM
> >To: Morton, Derek J
> >Cc: intel-gfx@lists.freedesktop.org; Wood, Thomas; Gore, Tim
> >Subject: Re: [PATCH i-g-t] tests/gem_exec_nop: Improved test run time
> >
> >On Tue, Nov 03, 2015 at 04:29:45PM +0000, Derek Morton wrote:
> >> Reduced the Sleep period to 200mS and reduced the repetition count to 
> >> 7 to decrease the test run time significantly.
> >> 
> >> Also fixed a non ascii character that messed up the results table formatting.
> >
> >Pardon? Are you working around someone else's bug?
> 
> > 
> >> Signed-off-by: Derek Morton <derek.j.morton@intel.com>
> >> ---
> >>  tests/gem_exec_nop.c | 6 +++---
> >>  1 file changed, 3 insertions(+), 3 deletions(-)
> >> 
> >> diff --git a/tests/gem_exec_nop.c b/tests/gem_exec_nop.c index 
> >> a287d08..5028145 100644
> >> --- a/tests/gem_exec_nop.c
> >> +++ b/tests/gem_exec_nop.c
> >> @@ -133,7 +133,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
> >>  	gem_sync(fd, handle);
> >>  
> >>  	for (count = 1; count <= SLOW_QUICK(1<<17, 1<<4); count <<= 1) {
> >> -		const int reps = 13;
> >> +		const int reps = 7;
> >>  		igt_stats_t stats;
> >>  		int n;
> >>  
> >> @@ -142,7 +142,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
> >>  		for (n = 0; n < reps; n++) {
> >>  			struct timespec start, end;
> >>  			int loops = count;
> >> -			sleep(1); /* wait for the hw to go back to sleep */
> >> +			usleep(200000); /* wait 200mS for the hw to go back to sleep */
> >>  			clock_gettime(CLOCK_MONOTONIC, &start);
> >>  			while (loops--)
> >>  				do_ioctl(fd, DRM_IOCTL_I915_GEM_EXECBUFFER2, &execbuf); @@ -151,7 
> >> +151,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
> >>  			igt_stats_push(&stats, elapsed(&start, &end, count));
> >>  		}
> >>  
> >> -		igt_info("Time to exec x %d:		%7.3fµs (ring=%s)\n",
> >> +		igt_info("Time to exec x %d:		%7.3fuS (ring=%s)\n",
> >
> >Did SI change the standard unit of measurement for time?
> 
> Before my patch the test output looks like:

GT-Version: 1.11-g0aa00ef (x86_64) (Linux: 4.2.0-rc6+ x86_64)
Time to exec x 1:		120.438µs (ring=render)
Time to exec x 2:		 72.689µs (ring=render)
...

> So the 'µ' character is causing problems.
> 
> I have done some more investigations and have found a change you made to igt_core.c in June to be the cause.
> You added:
> 	if (isatty(STDOUT_FILENO))
> 		setlocale(LC_ALL, "");
> to common_init()
> 
> I added some debug and the setlocale() on android is returning 'C' so is forcing standard ascii to be used. As 'µ' is not an ascii character it causes problems.

That's not the meaning of setlocale().
 
> So I think if you want to continue allow setting a locale to a lowest common denominator (ascii) then all the text printed by tests also needs to conform to ascii and this change is valid.

No, just android appears to be broken. I was actually complaining about
the use of 'S'.
-Chris
Derek Morton Nov. 4, 2015, 2:10 p.m. UTC | #4
>
>
>-----Original Message-----
>From: Chris Wilson [mailto:chris@chris-wilson.co.uk] 
>Sent: Wednesday, November 4, 2015 1:55 PM
>To: Morton, Derek J
>Cc: intel-gfx@lists.freedesktop.org; Wood, Thomas; Gore, Tim
>Subject: Re: [PATCH i-g-t] tests/gem_exec_nop: Improved test run time
>
>On Wed, Nov 04, 2015 at 01:40:45PM +0000, Morton, Derek J wrote:
>> >
>> >
>> >-----Original Message-----
>> >From: Chris Wilson [mailto:chris@chris-wilson.co.uk]
>> >Sent: Tuesday, November 3, 2015 4:40 PM
>> >To: Morton, Derek J
>> >Cc: intel-gfx@lists.freedesktop.org; Wood, Thomas; Gore, Tim
>> >Subject: Re: [PATCH i-g-t] tests/gem_exec_nop: Improved test run time
>> >
>> >On Tue, Nov 03, 2015 at 04:29:45PM +0000, Derek Morton wrote:
>> >> Reduced the Sleep period to 200mS and reduced the repetition count 
>> >> to
>> >> 7 to decrease the test run time significantly.
>> >> 
>> >> Also fixed a non ascii character that messed up the results table formatting.
>> >
>> >Pardon? Are you working around someone else's bug?
>> 
>> > 
>> >> Signed-off-by: Derek Morton <derek.j.morton@intel.com>
>> >> ---
>> >>  tests/gem_exec_nop.c | 6 +++---
>> >>  1 file changed, 3 insertions(+), 3 deletions(-)
>> >> 
>> >> diff --git a/tests/gem_exec_nop.c b/tests/gem_exec_nop.c index
>> >> a287d08..5028145 100644
>> >> --- a/tests/gem_exec_nop.c
>> >> +++ b/tests/gem_exec_nop.c
>> >> @@ -133,7 +133,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>> >>  	gem_sync(fd, handle);
>> >>  
>> >>  	for (count = 1; count <= SLOW_QUICK(1<<17, 1<<4); count <<= 1) {
>> >> -		const int reps = 13;
>> >> +		const int reps = 7;
>> >>  		igt_stats_t stats;
>> >>  		int n;
>> >>  
>> >> @@ -142,7 +142,7 @@ static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
>> >>  		for (n = 0; n < reps; n++) {
>> >>  			struct timespec start, end;
>> >>  			int loops = count;
>> >> -			sleep(1); /* wait for the hw to go back to sleep */
>> >> +			usleep(200000); /* wait 200mS for the hw to go back to sleep */
>> >>  			clock_gettime(CLOCK_MONOTONIC, &start);
>> >>  			while (loops--)
>> >>  				do_ioctl(fd, DRM_IOCTL_I915_GEM_EXECBUFFER2, &execbuf); @@ 
>> >> -151,7
>> >> +151,7 @@ static void loop(int fd, uint32_t handle, unsigned 
>> >> +ring_id, const char *ring_nam
>> >>  			igt_stats_push(&stats, elapsed(&start, &end, count));
>> >>  		}
>> >>  
>> >> -		igt_info("Time to exec x %d:		%7.3fµs (ring=%s)\n",
>> >> +		igt_info("Time to exec x %d:		%7.3fuS (ring=%s)\n",
>> >
>> >Did SI change the standard unit of measurement for time?
>> 
>> Before my patch the test output looks like:
>
>GT-Version: 1.11-g0aa00ef (x86_64) (Linux: 4.2.0-rc6+ x86_64)
>Time to exec x 1:		120.438µs (ring=render)
>Time to exec x 2:		 72.689µs (ring=render)
>...
>
>> So the 'µ' character is causing problems.
>> 
>> I have done some more investigations and have found a change you made to igt_core.c in June to be the cause.
>> You added:
>> 	if (isatty(STDOUT_FILENO))
>> 		setlocale(LC_ALL, "");
>> to common_init()
>> 
>> I added some debug and the setlocale() on android is returning 'C' so is forcing standard ascii to be used. As 'µ' is not an ascii character it causes problems.
>
>That's not the meaning of setlocale().
> 
>> So I think if you want to continue allow setting a locale to a lowest common denominator (ascii) then all the text printed by tests also needs to conform to ascii and this change is valid.
>
>No, just android appears to be broken. I was actually complaining about the use of 'S'.

What would you prefer to be printed?
us
usec
uSec
uSeconds
micro seconds

//Derek

>-Chris
>
>--
>Chris Wilson, Intel Open Source Technology Centre
>
Chris Wilson Nov. 4, 2015, 2:24 p.m. UTC | #5
On Wed, Nov 04, 2015 at 02:10:36PM +0000, Morton, Derek J wrote:
> >
> >
> >-----Original Message-----
> >From: Chris Wilson [mailto:chris@chris-wilson.co.uk] 
> >No, just android appears to be broken. I was actually complaining about the use of 'S'.
> 
> What would you prefer to be printed?

Prefer? µs. us if we must.
-Chris
Tvrtko Ursulin Nov. 4, 2015, 2:34 p.m. UTC | #6
On 04/11/15 14:24, Chris Wilson wrote:
> On Wed, Nov 04, 2015 at 02:10:36PM +0000, Morton, Derek J wrote:
>>>
>>>
>>> -----Original Message-----
>>> From: Chris Wilson [mailto:chris@chris-wilson.co.uk]
>>> No, just android appears to be broken. I was actually complaining about the use of 'S'.
>>
>> What would you prefer to be printed?
>
> Prefer? µs. us if we must.

Is this not just about the encoding supported by the terminal of the 
user running the test? In case of Android it is the adb shell them which 
does not support UTF-8?

Regards,

Tvrtko
Derek Morton Nov. 4, 2015, 2:46 p.m. UTC | #7
>

>

>-----Original Message-----

>From: Tvrtko Ursulin [mailto:tvrtko.ursulin@linux.intel.com] 

>Sent: Wednesday, November 4, 2015 2:34 PM

>To: Chris Wilson; Morton, Derek J; intel-gfx@lists.freedesktop.org; Wood, Thomas; Gore, Tim

>Subject: Re: [Intel-gfx] [PATCH i-g-t] tests/gem_exec_nop: Improved test run time

>

>

>On 04/11/15 14:24, Chris Wilson wrote:

>> On Wed, Nov 04, 2015 at 02:10:36PM +0000, Morton, Derek J wrote:

>>>>

>>>>

>>>> -----Original Message-----

>>>> From: Chris Wilson [mailto:chris@chris-wilson.co.uk] No, just 

>>>> android appears to be broken. I was actually complaining about the use of 'S'.

>>>

>>> What would you prefer to be printed?

>>

>> Prefer? µs. us if we must.

>

>Is this not just about the encoding supported by the terminal of the user running the test? In case of Android it is the adb shell them which does not support UTF-8?


Actually the µs works fine on android if setlocale() is not called. The problem is that when called on android it sets a very basic locale with ascii character set.

I am assuming it was added for a good reason and can't just be removed so the second best option is going to be to use 'us'. 

//Derek

>

>Regards,

>

>Tvrtko

>
Tvrtko Ursulin Nov. 4, 2015, 3:07 p.m. UTC | #8
On 04/11/15 14:46, Morton, Derek J wrote:
>>
>>
>> -----Original Message-----
>> From: Tvrtko Ursulin [mailto:tvrtko.ursulin@linux.intel.com]
>> Sent: Wednesday, November 4, 2015 2:34 PM
>> To: Chris Wilson; Morton, Derek J; intel-gfx@lists.freedesktop.org; Wood, Thomas; Gore, Tim
>> Subject: Re: [Intel-gfx] [PATCH i-g-t] tests/gem_exec_nop: Improved test run time
>>
>>
>> On 04/11/15 14:24, Chris Wilson wrote:
>>> On Wed, Nov 04, 2015 at 02:10:36PM +0000, Morton, Derek J wrote:
>>>>>
>>>>>
>>>>> -----Original Message-----
>>>>> From: Chris Wilson [mailto:chris@chris-wilson.co.uk] No, just
>>>>> android appears to be broken. I was actually complaining about the use of 'S'.
>>>>
>>>> What would you prefer to be printed?
>>>
>>> Prefer? µs. us if we must.
>>
>> Is this not just about the encoding supported by the terminal of the user running the test? In case of Android it is the adb shell them which does not support UTF-8?
>
> Actually the µs works fine on android if setlocale() is not called. The problem is that when called on android it sets a very basic locale with ascii character set.
>
> I am assuming it was added for a good reason and can't just be removed so the second best option is going to be to use 'us'.

It allows programs to respect some of the locale settings, but should 
not cause raw C strings to be modified I would have thought. So to me it 
also looks like a bug somewhere in the stack. A bit curious.

Regards,

Tvrtko
diff mbox

Patch

diff --git a/tests/gem_exec_nop.c b/tests/gem_exec_nop.c
index a287d08..5028145 100644
--- a/tests/gem_exec_nop.c
+++ b/tests/gem_exec_nop.c
@@ -133,7 +133,7 @@  static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
 	gem_sync(fd, handle);
 
 	for (count = 1; count <= SLOW_QUICK(1<<17, 1<<4); count <<= 1) {
-		const int reps = 13;
+		const int reps = 7;
 		igt_stats_t stats;
 		int n;
 
@@ -142,7 +142,7 @@  static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
 		for (n = 0; n < reps; n++) {
 			struct timespec start, end;
 			int loops = count;
-			sleep(1); /* wait for the hw to go back to sleep */
+			usleep(200000); /* wait 200mS for the hw to go back to sleep */
 			clock_gettime(CLOCK_MONOTONIC, &start);
 			while (loops--)
 				do_ioctl(fd, DRM_IOCTL_I915_GEM_EXECBUFFER2, &execbuf);
@@ -151,7 +151,7 @@  static void loop(int fd, uint32_t handle, unsigned ring_id, const char *ring_nam
 			igt_stats_push(&stats, elapsed(&start, &end, count));
 		}
 
-		igt_info("Time to exec x %d:		%7.3fµs (ring=%s)\n",
+		igt_info("Time to exec x %d:		%7.3fuS (ring=%s)\n",
 			 count, igt_stats_get_trimean(&stats)/1000, ring_name);
 		fflush(stdout);