Re: [RFC PATCH] tsc: synchronize TSCs on buggy Intel Xeon E5 CPUs with offset error

[Gratian Crisan <gratian.crisan@ni.com>]

Josh Hunt writes:

> On Tue, Nov 10, 2015 at 1:47 PM, Gratian Crisan <gratian.crisan@ni.com> wrote:
>>
>> The observed behavior does seem to match BT81 errata i.e. the TSC does
>> not get reset on warm reboots and it is otherwise stable.
>>
> If you have a simple testcase to reproduce the problem I'd be
> interested in seeing it.

We have first hit this bug on a 4.1 PREEMPT_RT kernel where it actually
causes a boot hang on warm reboots. I haven't quite got to the bottom of
why the TSC having a large offset vs. CPU0 would cause the hang yet. I
have some stack traces around somewhere I can dig up.

I also wrote a small C utility[1], with a bit of code borrowed from the
kernel, for reading the TSC on all CPUs. It starts a high priority
thread per CPU, tries to synchronize them and prints out the TSC values
and their offset with regards to CPU0.
It can be called from a SysV init shell script[2] at the beginning of
the boot process and right before a reboot to save the values in a file.

I've pasted the results after 3 reboots [3]. You can see the CPU0's TSC
getting reset on reboot and the other cores happily ticking on throughout
the reboot.

-Gratian

[1] read-tsc.c
--8<---------------cut here---------------start------------->8---
#define _GNU_SOURCE
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>
#include <string.h>
#include <pthread.h>
#include <sched.h>
#include <errno.h>
#include <assert.h>

#define DECLARE_ARGS(val, low, high)	unsigned low, high
#define EAX_EDX_VAL(val, low, high)	((low) | ((uint64_t)(high) << 32))
#define EAX_EDX_ARGS(val, low, high)	"a" (low), "d" (high)
#define EAX_EDX_RET(val, low, high)	"=a" (low), "=d" (high)

static int thread_sync;
static unsigned long long *tsc_data = NULL;

#define ACCESS_ONCE(x) (*(volatile typeof(x) *)&(x))

static inline void rep_nop(void)
{
	asm volatile("rep; nop" ::: "memory");
}

static inline void cpu_relax(void)
{
	rep_nop();
}

static inline unsigned long long rdtsc_ordered(void)
{
	DECLARE_ARGS(val, low, high);

	asm volatile("lfence" : : : "memory");
	asm volatile("rdtsc" : EAX_EDX_RET(val, low, high));

	return EAX_EDX_VAL(val, low, high);
}

static void* threadfn(void *param)
{
	long cpu = (long)param;
	cpu_set_t mask;
	struct sched_param schedp;

	CPU_ZERO(&mask);
	CPU_SET(cpu, &mask);
	if (sched_setaffinity(0, sizeof(mask), &mask) == -1) {
		perror("error: Failed to set the CPU affinity");
		return NULL;
	}

	/*
	 * Set the thread priority just below the migration thread's. The idea
	 * is to minimize the chances of being preempted while running the test.
	 */
	memset(&schedp, 0, sizeof(schedp));
	schedp.sched_priority = sched_get_priority_max(SCHED_FIFO) - 1;
	if (sched_setscheduler(0, SCHED_FIFO, &schedp) == -1) {
		perror("error: Failed to set the thread priority");
		return NULL;
	}

	__sync_sub_and_fetch(&thread_sync, 1);
	while (ACCESS_ONCE(thread_sync))
		cpu_relax();

	tsc_data[cpu] = rdtsc_ordered();

	return NULL;
}

int main(int argc, char* argv[])
{
	long i;
	unsigned long n_cpus;
	pthread_t *th = NULL;
	int ret = EXIT_SUCCESS;

	n_cpus = sysconf(_SC_NPROCESSORS_ONLN);
	thread_sync = n_cpus;
	__sync_synchronize();

	tsc_data = (unsigned long long*)malloc(n_cpus *
					       sizeof(unsigned long long));
	if (!tsc_data) {
		fprintf(stderr, "error: Failed to allocate memory for TSC data\n");
		ret = EXIT_FAILURE;
		goto out;
	}

	th = (pthread_t *)malloc(n_cpus * sizeof(pthread_t));
	if (!th) {
		fprintf(stderr, "error: Failed to allocate memory for thread data\n");
		ret = EXIT_FAILURE;
		goto out;
	}

	for (i = 0; i < n_cpus; i++)
		pthread_create(&th[i], NULL, threadfn, (void*)i);		

	for (i = 0; i < n_cpus; i++)
		pthread_join(th[i], NULL);

	if (argc > 1)
		printf("%s: ", argv[1]);
	for (i = 0; i < n_cpus; i++)
		printf("%llu[%lld] ", tsc_data[i], tsc_data[i] - tsc_data[0]);
	printf("\n");
	
  out:
	free(tsc_data);
	free(th);
		
	return ret;
}
--8<---------------cut here---------------end--------------->8---


[2] /etc/init.d/save-tsc
--8<---------------cut here---------------start------------->8---
#!/bin/sh

read-tsc "$1" >> /tsc.dat
exit 0
--8<---------------cut here---------------end--------------->8---


[3] tsc.dat
--8<---------------cut here---------------start------------->8---
stop: 222292260504[0] 146566095145777[146343802885273] 146566095145866[146343802885362] 146566095145817[146343802885313] 146566095145895[146343802885391] 146566095145840[146343802885336] 146566095145751[146343802885247] 146566095145707[146343802885203] 
start: 42437383741[0] 146626054987730[146583617603989] 146626054987813[146583617604072] 146626054987873[146583617604132] 146626054987444[146583617603703] 146626054987557[146583617603816] 146626054987703[146583617603962] 146626054987922[146583617604181] 
stop: 175075718467[0] 146758693322318[146583617603851] 146758693322251[146583617603784] 146758693322294[146583617603827] 146758693322276[146583617603809] 146758693322197[146583617603730] 146758693322228[146583617603761] 146758693322116[146583617603649] 
start: 42318111746[0] 146818573335855[146776255224109] 146818573336118[146776255224372] 146818573335988[146776255224242] 146818573335796[146776255224050] 146818573335930[146776255224184] 146818573335738[146776255223992] 146818573335619[146776255223873] 
stop: 117186647162[0] 146893441871380[146776255224218] 146893441871412[146776255224250] 146893441871361[146776255224199] 146893441871287[146776255224125] 146893441871335[146776255224173] 146893441871439[146776255224277] 146893441871269[146776255224107] 
start: 42577639385[0] 146953539519284[146910961879899] 146953539519333[146910961879948] 146953539519268[146910961879883] 146953539536718[146910961897333] 146953539519223[146910961879838] 146953539519068[146910961879683] 146953539519185[146910961879800] 
--8<---------------cut here---------------end--------------->8---