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

[Morton, Derek J]

>
>
>-----Original Message-----
>From: Chris Wilson [mailto:chris at chris-wilson.co.uk] 
>Sent: Tuesday, November 3, 2015 4:40 PM
>To: Morton, Derek J
>Cc: intel-gfx at 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 at 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
>