-O option causing test jitter?

-O option causing test jitter?

[john stultz]

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

So I've been using the attached test case (a hacked up version of
sched_jitter, which can now be found in ltp) to measure jitter in a
cpu-bound workload. The idea being if nothing preempts us, we might get
some irq caused jitter, but it should be pretty minimal.

Only recently I had noticed it wasn't that minimal. For 2.5 seconds of
work, I was seeing up to 5-10ms of jitter, which seemed a bit high.

So I dug in and instrumented the kernel and logged any time we got
preempted by a process, or an irq blocked us, or even time spent waiting
on raw locks and seqlocks.

With all the instrumenting I could, I could only account for maybe 2% of
the jitter (in one case the jitter was 1.5ms, and I could only account
for 30us from interrupt overhead).

Finally I rebuilt the test using -O2, and suddenly the jitter dropped
way down, and was then 90% or so accounted for by the instrumentation.

The issue seems to be that building w/ -O1, the compiler is doing
something pretty badly that causes the execution time for a fixed amount
of work to be much more variable.

Anyway, I wanted to hit the list with this so folks could look at it and
let me know if such severe jitter was expected from just compile
options?

thanks
-john




To build:
gcc -lrt -O1 sched_jitter.c -o sched_jitter-O1
gcc -lrt -O2 sched_jitter.c -o sched_jitter-O2


Here's example output:

./sched_jitter-O1
delta: 2479.231934 ms
delta: 2476.494629 ms
delta: 2473.964355 ms
delta: 2474.239746 ms
delta: 2472.457275 ms
delta: 2476.843262 ms
delta: 2475.494141 ms
delta: 2478.266113 ms
delta: 2476.601074 ms
delta: 2475.466553 ms
max jitter: 6.774889 ms
average runtime: 2475.905762 ms



./sched_jitter-O2
delta: 2069.088867 ms
delta: 2069.086914 ms
delta: 2068.875977 ms
delta: 2068.900146 ms
delta: 2068.948242 ms
delta: 2068.889893 ms
delta: 2068.878906 ms
delta: 2068.915283 ms
delta: 2068.913086 ms
delta: 2068.939453 ms
max jitter: 212.876007 us
average runtime: 2068.943848 ms



[-- Attachment #2: sched_jitter.c --]
[-- Type: text/x-csrc, Size: 3425 bytes --]

/*    Filename: sched_jitter.c
 *      Author: John Stultz <johnstul@us.ibm.com>
 * Description: This test measures scheduling jitter w/ realtime
 * processes.  It spawns a realtime thread that repeatedly times how long
 * it takes to do a fixed amount of work. It then prints out the maximum
 * jitter seen (longest execution time - the shortest execution time).
 * It also spawns off a realtime thread of higher priority that simply
 * wakes up and goes back to sleep. This tries to measure how much
 * overhead the scheduler adds in switching quickly to another task and
 * back.
 *
 * This program is free software; you can redistribute it and/or modify
 * it under the terms of the GNU General Public License as published by
 * the Free Software Foundation; either version 2 of the License, or
 * (at your option) any later version.
 *
 * This program is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 * GNU General Public License for more details.
 *
 * You should have received a copy of the GNU General Public License
 * along with this program; if not, write to the Free Software
 * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
 *
 * Copyright (C) IBM Corporation, 2006, 2007
 *
 * 2006-May-05:	Initial version by John Stultz <johnstul@us.ibm.com>
 * 2007-July-18: Support to gather stats by Ankita Garg <ankita@in.ibm.com>
 */

#include <stdio.h>
#include <time.h>
#include <pthread.h>
#include <sched.h>
#include <unistd.h>
#include <sys/mman.h>
#include <sys/prctl.h>

#define PR_PREEMPT_TRACING	23

#define NUMRUNS 10
#define NUMLOOPS 10000000
#define NSEC_PER_SEC 1000000000
#define WORKLEN 64

char  array[WORKLEN];


unsigned long long ts_sub(struct timespec a , struct timespec b)
{
	unsigned long long first, second;
	
	first = (unsigned long long)a.tv_sec * NSEC_PER_SEC + a.tv_nsec;
	second = (unsigned long long)b.tv_sec * NSEC_PER_SEC + b.tv_nsec;
	return first - second;	
}

void print_unit(unsigned long long val)
{
	if (val > 1000000)
		printf("%f ms\n", (float)(val)/1000000);
	else if (val > 1000)
		printf("%f us\n", (float)(val)/1000);
	else
		printf("%f ns\n", (float)val); 

}

void do_work(int runs)
{
	int i, j;
	for (i=0; i < runs; i++) {
		for (j=0; j < WORKLEN-1; j++)
			array[j] = array[j]+array[j+1];
		for (j=0; j < WORKLEN-1; j++)
			array[j] = array[j]-array[j+1];
	}
}



int main(int argc, char *argv[])
{
	struct sched_param param;

	struct timespec start, stop;
	int i;
	unsigned long long delta;
	unsigned long long min=-1, max=0;
	unsigned long long avg=0;

	param.sched_priority = sched_get_priority_max(SCHED_FIFO);
	sched_setscheduler(0, SCHED_FIFO, &param);
	mlockall(MCL_CURRENT|MCL_FUTURE);

        for (i=0; i < NUMRUNS; i++) {

		do_work(1); /* warm cache */

		/* do test */
//		prctl(PR_PREEMPT_TRACING, 1);
		clock_gettime(CLOCK_MONOTONIC, &start);
		do_work(NUMLOOPS);
		clock_gettime(CLOCK_MONOTONIC, &stop);
//		prctl(PR_PREEMPT_TRACING, 0);

		/* calc delta, min and max */
		delta = ts_sub(stop, start);
		if (delta < min)
			min = delta;
		if (delta> max)
			max = delta;
		avg += delta;
		printf("delta: ");
		print_unit(delta);
		usleep(1); /* let other things happen */
	}

	printf("max jitter: ");
	print_unit(max - min);
	printf("average runtime: ");
	print_unit(avg/NUMRUNS);

	return 0;
}

Re: -O option causing test jitter?

[Steven Rostedt]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 621 bytes --]



On Thu, 17 Apr 2008, john stultz wrote:
>
> Anyway, I wanted to hit the list with this so folks could look at it and
> let me know if such severe jitter was expected from just compile
> options?
>

I think this may simply be a simple case of cache misses.

Attached is two files: sched_jitter-test.c and do_work.S. I found that by
switching the positions of do_work1 and do_work2, which ever one is first
performs better. do_work1 is me copying the output of objdump of -O1 of
do_work, and do_work2 is copying the output from objdump of -O2.

For true realtime predictability, x86 architecture truly sucks :-p

-- Steve

[-- Attachment #2: Type: TEXT/X-CSRC, Size: 3483 bytes --]

/*    Filename: sched_jitter.c
 *      Author: John Stultz <johnstul@us.ibm.com>
 * Description: This test measures scheduling jitter w/ realtime
 * processes.  It spawns a realtime thread that repeatedly times how long
 * it takes to do a fixed amount of work. It then prints out the maximum
 * jitter seen (longest execution time - the shortest execution time).
 * It also spawns off a realtime thread of higher priority that simply
 * wakes up and goes back to sleep. This tries to measure how much
 * overhead the scheduler adds in switching quickly to another task and
 * back.
 *
 * This program is free software; you can redistribute it and/or modify
 * it under the terms of the GNU General Public License as published by
 * the Free Software Foundation; either version 2 of the License, or
 * (at your option) any later version.
 *
 * This program is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 * GNU General Public License for more details.
 *
 * You should have received a copy of the GNU General Public License
 * along with this program; if not, write to the Free Software
 * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
 *
 * Copyright (C) IBM Corporation, 2006, 2007
 *
 * 2006-May-05:	Initial version by John Stultz <johnstul@us.ibm.com>
 * 2007-July-18: Support to gather stats by Ankita Garg <ankita@in.ibm.com>
 */

#include <stdio.h>
#include <time.h>
#include <pthread.h>
#include <sched.h>
#include <unistd.h>
#include <sys/mman.h>
#include <sys/prctl.h>

#define PR_PREEMPT_TRACING	23

#define NUMRUNS 10
#define NUMLOOPS 10000000
//#define NUMLOOPS 100
#define NSEC_PER_SEC 1000000000
#define WORKLEN 64

char  array[WORKLEN];


unsigned long long ts_sub(struct timespec a , struct timespec b)
{
	unsigned long long first, second;
	
	first = (unsigned long long)a.tv_sec * NSEC_PER_SEC + a.tv_nsec;
	second = (unsigned long long)b.tv_sec * NSEC_PER_SEC + b.tv_nsec;
	return first - second;	
}

void print_unit(unsigned long long val)
{
	if (val > 1000000)
		printf("%f ms\n", (float)(val)/1000000);
	else if (val > 1000)
		printf("%f us\n", (float)(val)/1000);
	else
		printf("%f ns\n", (float)val); 

}

void runme(void (*work)(int))
{
	struct timespec start, stop;
	int i;
	unsigned long long delta;
	unsigned long long min=-1, max=0;
	unsigned long long avg=0;

        for (i=0; i < NUMRUNS; i++) {

		work(1); /* warm cache */

		/* do test */
//		prctl(PR_PREEMPT_TRACING, 1);
		clock_gettime(CLOCK_MONOTONIC, &start);
		work(NUMLOOPS);
		clock_gettime(CLOCK_MONOTONIC, &stop);
//		prctl(PR_PREEMPT_TRACING, 0);

		/* calc delta, min and max */
		delta = ts_sub(stop, start);
		if (delta < min)
			min = delta;
		if (delta> max)
			max = delta;
		avg += delta;
		printf("delta: ");
		print_unit(delta);
		usleep(1); /* let other things happen */
	}

	printf("max jitter: ");
	print_unit(max - min);
	printf("average runtime: ");
	print_unit(avg/NUMRUNS);
}

extern void do_work1(int);
extern void do_work2(int);

int main(int argc, char *argv[])
{
	struct sched_param param;

	param.sched_priority = sched_get_priority_max(SCHED_FIFO);
	sched_setscheduler(0, SCHED_FIFO, &param);
	mlockall(MCL_CURRENT|MCL_FUTURE);

	runme(do_work1);
	runme(do_work2);
	return 0;
}

[-- Attachment #3: Type: TEXT/PLAIN, Size: 879 bytes --]


.align 128
.globl do_work1
do_work1:
	mov    $0x0,%ecx
	test   %edi,%edi
	jg     1f
	retq 
2:	movzbl array+1(%rdx),%eax
	add    %al,array(%rdx)
	add    $0x1,%rdx
	cmp    $0x3f,%rdx
	jne    2b
	mov    $0x0,%dl
3:	movzbl array(%rdx),%eax
	sub    array+1(%rdx),%al
	mov    %al,array(%rdx)
	add    $0x1,%rdx
	cmp    $0x3f,%rdx
	jne    3b
	add    $0x1,%ecx
	cmp    %edi,%ecx
	je     4f
1:	mov    $0x0,%edx
	jmp    2b
4:	retq 



.align 128
.globl do_work2
do_work2:
	xor    %ecx,%ecx
	test   %edi,%edi
	jle    1f
4:	xor    %edx,%edx
2:	movzbl array+1(%rdx),%eax
	add    %al,array(%rdx)
	add    $0x1,%rdx
	cmp    $0x3f,%rdx
	jne    2b
	xor    %dl,%dl
3:	movzbl array(%rdx),%eax
	sub    array+1(%rdx),%al
	mov    %al,array(%rdx)
	add    $0x1,%rdx
	cmp    $0x3f,%rdx
	jne    3b
	add    $0x1,%ecx
	cmp    %edi,%ecx
	jne    4b
1:	retq 

Re: -O option causing test jitter?

[Nivedita Singhvi]

Steven Rostedt wrote:
> 
> On Thu, 17 Apr 2008, john stultz wrote:
>> Anyway, I wanted to hit the list with this so folks could look at it and
>> let me know if such severe jitter was expected from just compile
>> options?
>>
> 
> I think this may simply be a simple case of cache misses.
> 
> Attached is two files: sched_jitter-test.c and do_work.S. I found that by
> switching the positions of do_work1 and do_work2, which ever one is first
> performs better. do_work1 is me copying the output of objdump of -O1 of
> do_work, and do_work2 is copying the output from objdump of -O2.

So jitter going down might simply be a case of the
faster cases actually slowing down, right - and
making things uniformly slow?

Do we know if the whole kaboodle is getting faster?

thanks,
Nivedita