887 lines · 21.8 KB · C
RawDownload
// SPDX-License-Identifier: GPL-2.0/* * trace_hwlat.c - A simple Hardware Latency detector. * * Use this tracer to detect large system latencies induced by the behavior of * certain underlying system hardware or firmware, independent of Linux itself. * The code was developed originally to detect the presence of SMIs on Intel * and AMD systems, although there is no dependency upon x86 herein. * * The classical example usage of this tracer is in detecting the presence of * SMIs or System Management Interrupts on Intel and AMD systems. An SMI is a * somewhat special form of hardware interrupt spawned from earlier CPU debug * modes in which the (BIOS/EFI/etc.) firmware arranges for the South Bridge * LPC (or other device) to generate a special interrupt under certain * circumstances, for example, upon expiration of a special SMI timer device, * due to certain external thermal readings, on certain I/O address accesses, * and other situations. An SMI hits a special CPU pin, triggers a special * SMI mode (complete with special memory map), and the OS is unaware. * * Although certain hardware-inducing latencies are necessary (for example, * a modern system often requires an SMI handler for correct thermal control * and remote management) they can wreak havoc upon any OS-level performance * guarantees toward low-latency, especially when the OS is not even made * aware of the presence of these interrupts. For this reason, we need a * somewhat brute force mechanism to detect these interrupts. In this case, * we do it by hogging all of the CPU(s) for configurable timer intervals, * sampling the built-in CPU timer, looking for discontiguous readings. * * WARNING: This implementation necessarily introduces latencies. Therefore, *          you should NEVER use this tracer while running in a production *          environment requiring any kind of low-latency performance *          guarantee(s). * * Copyright (C) 2008-2009 Jon Masters, Red Hat, Inc. <jcm@redhat.com> * Copyright (C) 2013-2016 Steven Rostedt, Red Hat, Inc. <srostedt@redhat.com> * * Includes useful feedback from Clark Williams <williams@redhat.com> * */#include <linux/kthread.h>#include <linux/tracefs.h>#include <linux/uaccess.h>#include <linux/cpumask.h>#include <linux/delay.h>#include <linux/sched/clock.h>#include "trace.h" static struct trace_array	*hwlat_trace; #define U64STR_SIZE		22			/* 20 digits max */ #define BANNER			"hwlat_detector: "#define DEFAULT_SAMPLE_WINDOW	1000000			/* 1s */#define DEFAULT_SAMPLE_WIDTH	500000			/* 0.5s */#define DEFAULT_LAT_THRESHOLD	10			/* 10us */ static struct dentry *hwlat_sample_width;	/* sample width us */static struct dentry *hwlat_sample_window;	/* sample window us */static struct dentry *hwlat_thread_mode;	/* hwlat thread mode */ enum {	MODE_NONE = 0,	MODE_ROUND_ROBIN,	MODE_PER_CPU,	MODE_MAX};static char *thread_mode_str[] = { "none", "round-robin", "per-cpu" }; /* Save the previous tracing_thresh value */static unsigned long save_tracing_thresh; /* runtime kthread data */struct hwlat_kthread_data {	struct task_struct	*kthread;	/* NMI timestamp counters */	u64			nmi_ts_start;	u64			nmi_total_ts;	int			nmi_count;	int			nmi_cpu;}; static struct hwlat_kthread_data hwlat_single_cpu_data;static DEFINE_PER_CPU(struct hwlat_kthread_data, hwlat_per_cpu_data); /* Tells NMIs to call back to the hwlat tracer to record timestamps */bool trace_hwlat_callback_enabled; /* If the user changed threshold, remember it */static u64 last_tracing_thresh = DEFAULT_LAT_THRESHOLD * NSEC_PER_USEC; /* Individual latency samples are stored here when detected. */struct hwlat_sample {	u64			seqnum;		/* unique sequence */	u64			duration;	/* delta */	u64			outer_duration;	/* delta (outer loop) */	u64			nmi_total_ts;	/* Total time spent in NMIs */	struct timespec64	timestamp;	/* wall time */	int			nmi_count;	/* # NMIs during this sample */	int			count;		/* # of iterations over thresh */}; /* keep the global state somewhere. */static struct hwlat_data { 	struct mutex	lock;		/* protect changes */ 	atomic64_t	count;		/* total since reset */ 	u64	sample_window;		/* total sampling window (on+off) */	u64	sample_width;		/* active sampling portion of window */ 	int	thread_mode;		/* thread mode */ } hwlat_data = {	.sample_window		= DEFAULT_SAMPLE_WINDOW,	.sample_width		= DEFAULT_SAMPLE_WIDTH,	.thread_mode		= MODE_ROUND_ROBIN}; static struct hwlat_kthread_data *get_cpu_data(void){	if (hwlat_data.thread_mode == MODE_PER_CPU)		return this_cpu_ptr(&hwlat_per_cpu_data);	else		return &hwlat_single_cpu_data;} static bool hwlat_busy; static void trace_hwlat_sample(struct hwlat_sample *sample){	struct trace_array *tr = hwlat_trace;	struct trace_buffer *buffer = tr->array_buffer.buffer;	struct ring_buffer_event *event;	struct hwlat_entry *entry; 	event = trace_buffer_lock_reserve(buffer, TRACE_HWLAT, sizeof(*entry),					  tracing_gen_ctx());	if (!event)		return;	entry	= ring_buffer_event_data(event);	entry->seqnum			= sample->seqnum;	entry->duration			= sample->duration;	entry->outer_duration		= sample->outer_duration;	entry->timestamp		= sample->timestamp;	entry->nmi_total_ts		= sample->nmi_total_ts;	entry->nmi_count		= sample->nmi_count;	entry->count			= sample->count; 	trace_buffer_unlock_commit_nostack(buffer, event);} /* Macros to encapsulate the time capturing infrastructure */#define time_type	u64#define time_get()	trace_clock_local()#define time_to_us(x)	div_u64(x, 1000)#define time_sub(a, b)	((a) - (b))#define init_time(a, b)	(a = b)#define time_u64(a)	a void trace_hwlat_callback(bool enter){	struct hwlat_kthread_data *kdata = get_cpu_data(); 	if (!kdata->kthread)		return; 	/*	 * Currently trace_clock_local() calls sched_clock() and the	 * generic version is not NMI safe.	 */	if (!IS_ENABLED(CONFIG_GENERIC_SCHED_CLOCK)) {		if (enter)			kdata->nmi_ts_start = time_get();		else			kdata->nmi_total_ts += time_get() - kdata->nmi_ts_start;	} 	if (enter)		kdata->nmi_count++;} /* * hwlat_err - report a hwlat error. */#define hwlat_err(msg) ({							\	struct trace_array *tr = hwlat_trace;					\										\	trace_array_printk_buf(tr->array_buffer.buffer, _THIS_IP_, msg);	\}) /** * get_sample - sample the CPU TSC and look for likely hardware latencies * * Used to repeatedly capture the CPU TSC (or similar), looking for potential * hardware-induced latency. Called with interrupts disabled. */static int get_sample(void){	struct hwlat_kthread_data *kdata = get_cpu_data();	struct trace_array *tr = hwlat_trace;	struct hwlat_sample s;	time_type start, t1, t2, last_t2;	s64 diff, outer_diff, total, last_total = 0;	u64 sample = 0;	u64 sample_width = READ_ONCE(hwlat_data.sample_width);	u64 thresh = tracing_thresh;	u64 outer_sample = 0;	int ret = -1;	unsigned int count = 0; 	do_div(thresh, NSEC_PER_USEC); /* modifies interval value */ 	kdata->nmi_total_ts = 0;	kdata->nmi_count = 0;	/* Make sure NMIs see this first */	barrier(); 	trace_hwlat_callback_enabled = true; 	init_time(last_t2, 0);	start = time_get(); /* start timestamp */	outer_diff = 0; 	do { 		t1 = time_get();	/* we'll look for a discontinuity */		t2 = time_get(); 		if (time_u64(last_t2)) {			/* Check the delta from outer loop (t2 to next t1) */			outer_diff = time_to_us(time_sub(t1, last_t2));			/* This shouldn't happen */			if (outer_diff < 0) {				hwlat_err(BANNER "time running backwards\n");				goto out;			}			if (outer_diff > outer_sample)				outer_sample = outer_diff;		}		last_t2 = t2; 		total = time_to_us(time_sub(t2, start)); /* sample width */ 		/* Check for possible overflows */		if (total < last_total) {			hwlat_err("Time total overflowed\n");			break;		}		last_total = total; 		/* This checks the inner loop (t1 to t2) */		diff = time_to_us(time_sub(t2, t1));     /* current diff */ 		if (diff > thresh || outer_diff > thresh) {			if (!count)				ktime_get_real_ts64(&s.timestamp);			count++;		} 		/* This shouldn't happen */		if (diff < 0) {			hwlat_err(BANNER "time running backwards\n");			goto out;		} 		if (diff > sample)			sample = diff; /* only want highest value */ 	} while (total <= sample_width); 	barrier(); /* finish the above in the view for NMIs */	trace_hwlat_callback_enabled = false;	barrier(); /* Make sure nmi_total_ts is no longer updated */ 	ret = 0; 	/* If we exceed the threshold value, we have found a hardware latency */	if (sample > thresh || outer_sample > thresh) {		u64 latency; 		ret = 1; 		/* We read in microseconds */		if (kdata->nmi_total_ts)			do_div(kdata->nmi_total_ts, NSEC_PER_USEC); 		s.seqnum = atomic64_inc_return(&hwlat_data.count);		s.duration = sample;		s.outer_duration = outer_sample;		s.nmi_total_ts = kdata->nmi_total_ts;		s.nmi_count = kdata->nmi_count;		s.count = count;		trace_hwlat_sample(&s); 		latency = max(sample, outer_sample); 		/* Keep a running maximum ever recorded hardware latency */		if (latency > tr->max_latency) {			tr->max_latency = latency;			latency_fsnotify(tr);		}	} out:	return ret;} static struct cpumask save_cpumask; static void move_to_next_cpu(void){	struct cpumask *current_mask = &save_cpumask;	struct trace_array *tr = hwlat_trace;	int next_cpu; 	/*	 * If for some reason the user modifies the CPU affinity	 * of this thread, then stop migrating for the duration	 * of the current test.	 */	if (!cpumask_equal(current_mask, current->cpus_ptr))		goto change_mode; 	cpus_read_lock();	cpumask_and(current_mask, cpu_online_mask, tr->tracing_cpumask);	next_cpu = cpumask_next_wrap(raw_smp_processor_id(), current_mask);	cpus_read_unlock(); 	if (next_cpu >= nr_cpu_ids) /* Shouldn't happen! */		goto change_mode; 	cpumask_clear(current_mask);	cpumask_set_cpu(next_cpu, current_mask); 	set_cpus_allowed_ptr(current, current_mask);	return;  change_mode:	hwlat_data.thread_mode = MODE_NONE;	pr_info(BANNER "cpumask changed while in round-robin mode, switching to mode none\n");} /* * kthread_fn - The CPU time sampling/hardware latency detection kernel thread * * Used to periodically sample the CPU TSC via a call to get_sample. We * disable interrupts, which does (intentionally) introduce latency since we * need to ensure nothing else might be running (and thus preempting). * Obviously this should never be used in production environments. * * Executes one loop interaction on each CPU in tracing_cpumask sysfs file. */static int kthread_fn(void *data){	u64 interval; 	while (!kthread_should_stop()) { 		if (hwlat_data.thread_mode == MODE_ROUND_ROBIN)			move_to_next_cpu(); 		local_irq_disable();		get_sample();		local_irq_enable(); 		mutex_lock(&hwlat_data.lock);		interval = hwlat_data.sample_window - hwlat_data.sample_width;		mutex_unlock(&hwlat_data.lock); 		do_div(interval, USEC_PER_MSEC); /* modifies interval value */ 		/* Always sleep for at least 1ms */		if (interval < 1)			interval = 1; 		if (msleep_interruptible(interval))			break;	} 	return 0;} /* * stop_stop_kthread - Inform the hardware latency sampling/detector kthread to stop * * This kicks the running hardware latency sampling/detector kernel thread and * tells it to stop sampling now. Use this on unload and at system shutdown. */static void stop_single_kthread(void){	struct hwlat_kthread_data *kdata = get_cpu_data();	struct task_struct *kthread; 	cpus_read_lock();	kthread = kdata->kthread; 	if (!kthread)		goto out_put_cpus; 	kthread_stop(kthread);	kdata->kthread = NULL; out_put_cpus:	cpus_read_unlock();}  /* * start_single_kthread - Kick off the hardware latency sampling/detector kthread * * This starts the kernel thread that will sit and sample the CPU timestamp * counter (TSC or similar) and look for potential hardware latencies. */static int start_single_kthread(struct trace_array *tr){	struct hwlat_kthread_data *kdata = get_cpu_data();	struct cpumask *current_mask = &save_cpumask;	struct task_struct *kthread;	int next_cpu; 	cpus_read_lock();	if (kdata->kthread)		goto out_put_cpus; 	kthread = kthread_create(kthread_fn, NULL, "hwlatd");	if (IS_ERR(kthread)) {		pr_err(BANNER "could not start sampling thread\n");		cpus_read_unlock();		return -ENOMEM;	} 	/* Just pick the first CPU on first iteration */	cpumask_and(current_mask, cpu_online_mask, tr->tracing_cpumask); 	if (hwlat_data.thread_mode == MODE_ROUND_ROBIN) {		next_cpu = cpumask_first(current_mask);		cpumask_clear(current_mask);		cpumask_set_cpu(next_cpu, current_mask); 	} 	set_cpus_allowed_ptr(kthread, current_mask); 	kdata->kthread = kthread;	wake_up_process(kthread); out_put_cpus:	cpus_read_unlock();	return 0;} /* * stop_cpu_kthread - Stop a hwlat cpu kthread */static void stop_cpu_kthread(unsigned int cpu){	struct task_struct *kthread; 	kthread = per_cpu(hwlat_per_cpu_data, cpu).kthread;	if (kthread)		kthread_stop(kthread);	per_cpu(hwlat_per_cpu_data, cpu).kthread = NULL;} /* * stop_per_cpu_kthreads - Inform the hardware latency sampling/detector kthread to stop * * This kicks the running hardware latency sampling/detector kernel threads and * tells it to stop sampling now. Use this on unload and at system shutdown. */static void stop_per_cpu_kthreads(void){	unsigned int cpu; 	cpus_read_lock();	for_each_online_cpu(cpu)		stop_cpu_kthread(cpu);	cpus_read_unlock();} /* * start_cpu_kthread - Start a hwlat cpu kthread */static int start_cpu_kthread(unsigned int cpu){	struct task_struct *kthread; 	/* Do not start a new hwlatd thread if it is already running */	if (per_cpu(hwlat_per_cpu_data, cpu).kthread)		return 0; 	kthread = kthread_run_on_cpu(kthread_fn, NULL, cpu, "hwlatd/%u");	if (IS_ERR(kthread)) {		pr_err(BANNER "could not start sampling thread\n");		return -ENOMEM;	} 	per_cpu(hwlat_per_cpu_data, cpu).kthread = kthread; 

Lines 1–500 of 887.