[profile] Add generic profiling infrastructure

Signed-off-by: Michael Brown <mcb30@ipxe.org>

src/arch/i386/include/bits/profile.h

@@ -0,0 +1,28 @@
+#ifndef _BITS_PROFILE_H
+#define _BITS_PROFILE_H
+
+/** @file
+ *
+ * Profiling
+ *
+ */
+
+FILE_LICENCE ( GPL2_OR_LATER );
+
+#include <stdint.h>
+
+/**
+ * Get profiling timestamp
+ *
+ * @ret timestamp	Timestamp
+ */
+static inline __attribute__ (( always_inline )) uint64_t
+profile_timestamp ( void ) {
+	uint64_t tsc;
+
+	/* Read timestamp counter */
+	__asm__ __volatile__ ( "rdtsc" : "=A" ( tsc ) );
+	return tsc;
+}
+
+#endif /* _BITS_PROFILE_H */

src/arch/x86_64/include/bits/profile.h

@@ -0,0 +1,29 @@
+#ifndef _BITS_PROFILE_H
+#define _BITS_PROFILE_H
+
+/** @file
+ *
+ * Profiling
+ *
+ */
+
+FILE_LICENCE ( GPL2_OR_LATER );
+
+#include <stdint.h>
+
+/**
+ * Get profiling timestamp
+ *
+ * @ret timestamp	Timestamp
+ */
+static inline __attribute__ (( always_inline )) uint64_t
+profile_timestamp ( void ) {
+	uint32_t eax;
+	uint32_t edx;
+
+	/* Read timestamp counter */
+	__asm__ __volatile__ ( "rdtsc" : "=a" ( eax ), "=d" ( edx ) );
+	return ( ( ( ( uint64_t ) edx ) << 32 ) | eax );
+}
+
+#endif /* _BITS_PROFILE_H */

src/core/profile.c

@@ -0,0 +1,269 @@
+/*
+ * Copyright (C) 2014 Michael Brown <mbrown@fensystems.co.uk>.
+ *
+ * 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 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., 51 Franklin Street, Fifth Floor, Boston, MA
+ * 02110-1301, USA.
+ */
+
+FILE_LICENCE ( GPL2_OR_LATER );
+
+#include <stdint.h>
+#include <stdio.h>
+#include <strings.h>
+#include <assert.h>
+#include <ipxe/isqrt.h>
+#include <ipxe/profile.h>
+
+/** @file
+ *
+ * Profiling
+ *
+ * The profiler computes basic statistics (mean, variance, and
+ * standard deviation) for the samples which it records.  Note that
+ * these statistics need not be completely accurate; it is sufficient
+ * to give a rough approximation.
+ *
+ * The algorithm for updating the mean and variance estimators is from
+ * The Art of Computer Programming (via Wikipedia), with adjustments
+ * to avoid the use of floating-point instructions.
+ */
+
+/**
+ * Format a hex fraction (for debugging)
+ *
+ * @v value		Value
+ * @v shift		Bit shift
+ * @ret string		Formatted hex fraction
+ */
+static const char * profile_hex_fraction ( signed long long value,
+					   unsigned int shift ) {
+	static char buf[23] = "-"; /* -0xXXXXXXXXXXXXXXXX.XX + NUL */
+	unsigned long long int_part;
+	uint8_t frac_part;
+	char *ptr;
+
+	if ( value < 0 ) {
+		value = -value;
+		ptr = &buf[0];
+	} else {
+		ptr = &buf[1];
+	}
+	int_part = ( value >> shift );
+	frac_part = ( value >> ( shift - ( 8 * sizeof ( frac_part ) ) ) );
+	snprintf ( &buf[1], ( sizeof ( buf ) - 1  ), "%#llx.%02x",
+		   int_part, frac_part );
+	return ptr;
+}
+
+/**
+ * Calculate bit shift for mean sample value
+ *
+ * @v profiler		Profiler
+ * @ret shift		Bit shift
+ */
+static inline unsigned int profile_mean_shift ( struct profiler *profiler ) {
+
+	return ( ( ( 8 * sizeof ( profiler->mean ) ) - 1 ) /* MSB */
+		 - 1 /* Leave sign bit unused */
+		 - profiler->mean_msb );
+}
+
+/**
+ * Calculate bit shift for accumulated variance value
+ *
+ * @v profiler		Profiler
+ * @ret shift		Bit shift
+ */
+static inline unsigned int profile_accvar_shift ( struct profiler *profiler ) {
+
+	return ( ( ( 8 * sizeof ( profiler->accvar ) ) - 1 ) /* MSB */
+		 - 1 /* Leave top bit unused */
+		 - profiler->accvar_msb );
+}
+
+/**
+ * Update profiler with a new sample
+ *
+ * @v profiler		Profiler
+ * @v sample		Sample value
+ */
+void profile_update ( struct profiler *profiler, unsigned long sample ) {
+	unsigned int sample_msb;
+	unsigned int mean_shift;
+	unsigned int delta_shift;
+	signed long pre_delta;
+	signed long post_delta;
+	signed long long accvar_delta;
+	unsigned int accvar_delta_shift;
+	unsigned int accvar_delta_msb;
+	unsigned int accvar_shift;
+
+	/* Our scaling logic assumes that sample values never overflow
+	 * a signed long (i.e. that the high bit is always zero).
+	 */
+	assert ( ( ( signed ) sample ) >= 0 );
+
+	/* Update sample count */
+	profiler->count++;
+
+	/* Adjust mean sample value scale if necessary.  Skip if
+	 * sample is zero (in which case flsl(sample)-1 would
+	 * underflow): in the case of a zero sample we have no need to
+	 * adjust the scale anyway.
+	 */
+	if ( sample ) {
+		sample_msb = ( flsl ( sample ) - 1 );
+		if ( profiler->mean_msb < sample_msb ) {
+			profiler->mean >>= ( sample_msb - profiler->mean_msb );
+			profiler->mean_msb = sample_msb;
+		}
+	}
+
+	/* Scale sample to internal units */
+	mean_shift = profile_mean_shift ( profiler );
+	sample <<= mean_shift;
+
+	/* Update mean */
+	pre_delta = ( sample - profiler->mean );
+	profiler->mean += ( pre_delta / ( ( signed ) profiler->count ) );
+	post_delta = ( sample - profiler->mean );
+	delta_shift = mean_shift;
+	DBGC ( profiler, "PROFILER %p sample %#lx mean %s", profiler,
+	       ( sample >> mean_shift ),
+		profile_hex_fraction ( profiler->mean, mean_shift ) );
+	DBGC ( profiler, " pre %s",
+	       profile_hex_fraction ( pre_delta, delta_shift ) );
+	DBGC ( profiler, " post %s\n",
+	       profile_hex_fraction ( post_delta, delta_shift ) );
+
+	/* Scale both deltas to fit in half of an unsigned long long
+	 * to avoid potential overflow on multiplication.  Note that
+	 * shifting a signed quantity is "implementation-defined"
+	 * behaviour in the C standard, but gcc documents that it will
+	 * always perform sign extension.
+	 */
+	if ( sizeof ( pre_delta ) > ( sizeof ( accvar_delta ) / 2 ) ) {
+		unsigned int shift = ( 8 * ( sizeof ( pre_delta ) -
+					     ( sizeof ( accvar_delta ) / 2 ) ));
+		pre_delta >>= shift;
+		post_delta >>= shift;
+		delta_shift -= shift;
+	}
+
+	/* Update variance, if applicable.  Skip if either delta is
+	 * zero (in which case flsl(delta)-1 would underflow): in the
+	 * case of a zero delta there is no change to the accumulated
+	 * variance anyway.
+	 */
+	if ( pre_delta && post_delta ) {
+
+		/* Calculate variance delta */
+		accvar_delta = ( ( ( signed long long ) pre_delta ) *
+				 ( ( signed long long ) post_delta ) );
+		accvar_delta_shift = ( 2 * delta_shift );
+		assert ( accvar_delta > 0 );
+
+		/* Calculate variance delta MSB, using flsl() on each
+		 * delta individually to provide an upper bound rather
+		 * than requiring the existence of flsll().
+		 */
+		accvar_delta_msb = ( flsll ( accvar_delta ) - 1 );
+		if ( accvar_delta_msb > accvar_delta_shift ) {
+			accvar_delta_msb -= accvar_delta_shift;
+		} else {
+			accvar_delta_msb = 0;
+		}
+
+		/* Adjust scales as necessary */
+		if ( profiler->accvar_msb < accvar_delta_msb ) {
+			/* Rescale accumulated variance */
+			profiler->accvar >>= ( accvar_delta_msb -
+					       profiler->accvar_msb );
+			profiler->accvar_msb = accvar_delta_msb;
+		} else {
+			/* Rescale variance delta */
+			accvar_delta >>= ( profiler->accvar_msb -
+					   accvar_delta_msb );
+			accvar_delta_shift -= ( profiler->accvar_msb -
+						accvar_delta_msb );
+		}
+
+		/* Scale delta to internal units */
+		accvar_shift = profile_accvar_shift ( profiler );
+		accvar_delta <<= ( accvar_shift - accvar_delta_shift );
+
+		/* Accumulate variance */
+		profiler->accvar += accvar_delta;
+
+		/* Adjust scale if necessary */
+		if ( profiler->accvar &
+		     ( 1ULL << ( ( 8 * sizeof ( profiler->accvar ) ) - 1 ) ) ) {
+			profiler->accvar >>= 1;
+			profiler->accvar_msb++;
+			accvar_delta >>= 1;
+			accvar_shift--;
+		}
+
+		DBGC ( profiler, "PROFILER %p accvar %s", profiler,
+		       profile_hex_fraction ( profiler->accvar, accvar_shift ));
+		DBGC ( profiler, " delta %s\n",
+		       profile_hex_fraction ( accvar_delta, accvar_shift ) );
+	}
+}
+
+/**
+ * Get mean sample value
+ *
+ * @v profiler		Profiler
+ * @ret mean		Mean sample value
+ */
+unsigned long profile_mean ( struct profiler *profiler ) {
+	unsigned int mean_shift = profile_mean_shift ( profiler );
+
+	/* Round to nearest and scale down to original units */
+	return ( ( profiler->mean + ( 1UL << ( mean_shift - 1 ) ) )
+		 >> mean_shift );
+}
+
+/**
+ * Get sample variance
+ *
+ * @v profiler		Profiler
+ * @ret variance	Sample variance
+ */
+unsigned long profile_variance ( struct profiler *profiler ) {
+	unsigned int accvar_shift = profile_accvar_shift ( profiler );
+
+	/* Variance is zero if fewer than two samples exist (avoiding
+	 * division by zero error).
+	 */
+	if ( profiler->count < 2 )
+		return 0;
+
+	/* Calculate variance, round to nearest, and scale to original units */
+	return ( ( ( profiler->accvar / ( profiler->count - 1 ) )
+		   + ( 1ULL << ( accvar_shift - 1 ) ) ) >> accvar_shift );
+}
+
+/**
+ * Get sample standard deviation
+ *
+ * @v profiler		Profiler
+ * @ret stddev		Sample standard deviation
+ */
+unsigned long profile_stddev ( struct profiler *profiler ) {
+
+	return isqrt ( profile_variance ( profiler ) );
+}

src/include/ipxe/profile.h

@@ -10,71 +10,85 @@
 FILE_LICENCE ( GPL2_OR_LATER );
 
 #include <stdint.h>
+#include <bits/profile.h>
+#include <ipxe/tables.h>
+
+#ifdef NDEBUG
+#define PROFILING 0
+#else
+#define PROFILING 1
+#endif
 
 /**
  * A data structure for storing profiling information
  */
-union profiler {
-	/** Timestamp (in CPU-specific "ticks") */
-	uint64_t timestamp;
-	/** Registers returned by rdtsc.
+struct profiler {
+	/** Name */
+	const char *name;
+	/** Start timestamp */
+	uint64_t started;
+	/** Number of samples */
+	unsigned int count;
+	/** Mean sample value (scaled) */
+	unsigned long mean;
+	/** Mean sample value MSB
 	 *
-	 * This part should really be architecture-specific code.
+	 * This is the highest bit set in the raw (unscaled) value
+	 * (i.e. one less than would be returned by flsl(raw_mean)).
 	 */
-	struct {
-		uint32_t eax;
-		uint32_t edx;
-	} rdtsc;
+	unsigned int mean_msb;
+	/** Accumulated variance (scaled) */
+	unsigned long long accvar;
+	/** Accumulated variance MSB
+	 *
+	 * This is the highest bit set in the raw (unscaled) value
+	 * (i.e. one less than would be returned by flsll(raw_accvar)).
+	 */
+	unsigned int accvar_msb;
 };
 
-/**
- * Static per-object profiler, for use with simple_profile()
- */
-static union profiler simple_profiler;
+/** Profiler table */
+#define PROFILERS __table ( struct profiler, "profilers" )
+
+/** Declare a profiler */
+#if PROFILING
+#define __profiler __table_entry ( PROFILERS, 01 )
+#else
+#define __profiler
+#endif
+
+extern void profile_update ( struct profiler *profiler, unsigned long sample );
+extern unsigned long profile_mean ( struct profiler *profiler );
+extern unsigned long profile_variance ( struct profiler *profiler );
+extern unsigned long profile_stddev ( struct profiler *profiler );
 
 /**
- * Perform profiling
+ * Start profiling
  *
- * @v profiler		Profiler data structure
- * @ret delta		Elapsed ticks since last call to profile().
- *
- * Call profile() both before and after the code you wish to measure.
- * The "after" call will return the measurement.  For example:
- *
- * @code
- *
- *     profile ( &profiler );
- *     ... do something here ...
- *     printf ( "It took %ld ticks to execute\n", profile ( &profiler ) );
- *
- * @endcode
+ * @v profiler		Profiler
  */
-static inline __attribute__ (( always_inline )) unsigned long
-profile ( union profiler *profiler ) {
-	uint64_t last_timestamp = profiler->timestamp;
+static inline __attribute__ (( always_inline )) void
+profile_start ( struct profiler *profiler ) {
 
-	__asm__ __volatile__ ( "rdtsc" :
-			       "=a" ( profiler->rdtsc.eax ),
-			       "=d" ( profiler->rdtsc.edx ) );
-	return ( profiler->timestamp - last_timestamp );
+	/* If profiling is active then record start timestamp */
+	if ( PROFILING )
+		profiler->started = profile_timestamp();
 }
 
 /**
- * Perform profiling
+ * Record profiling result
  *
- * @ret delta		Elapsed ticks since last call to profile().
- *
- * When you only need one profiler, you can avoid the hassle of
- * creating your own @c profiler data structure by using
- * simple_profile() instead.
- *
- * simple_profile() is equivalent to profile(&simple_profiler), where
- * @c simple_profiler is a @c profiler data structure that is static
- * to each object which includes @c profile.h.
+ * @v profiler		Profiler
  */
-static inline __attribute__ (( always_inline )) unsigned long
-simple_profile ( void ) {
-	return profile ( &simple_profiler );
+static inline __attribute__ (( always_inline )) void
+profile_stop ( struct profiler *profiler ) {
+	uint64_t ended;
+
+	/* If profiling is active then record end timestamp and update stats */
+	if ( PROFILING ) {
+		ended = profile_timestamp();
+		profile_update ( profiler, ( ended - profiler->started ) );
+	}
 }
 
 #endif /* _IPXE_PROFILE_H */

src/tests/cbc_test.c

@@ -36,6 +36,9 @@ FILE_LICENCE ( GPL2_OR_LATER );
 #include <ipxe/profile.h>
 #include "cbc_test.h"
 
+/** Number of sample iterations for profiling */
+#define PROFILE_COUNT 16
+
 /**
  * Test CBC encryption
  *
@@ -115,8 +118,7 @@ static unsigned long cbc_cost ( struct cipher_algorithm *cipher,
 	uint8_t key[key_len];
 	uint8_t iv[cipher->blocksize];
 	uint8_t ctx[cipher->ctxsize];
-	union profiler profiler;
-	unsigned long long elapsed;
+	struct profiler profiler;
 	unsigned long cost;
 	unsigned int i;
 	int rc;
@@ -135,13 +137,17 @@ static unsigned long cbc_cost ( struct cipher_algorithm *cipher,
 	assert ( rc == 0 );
 	cipher_setiv ( cipher, ctx, iv );
 
-	/* Time operation */
-	profile ( &profiler );
-	op ( cipher, ctx, random, random, sizeof ( random ) );
-	elapsed = profile ( &profiler );
+	/* Profile cipher operation */
+	memset ( &profiler, 0, sizeof ( profiler ) );
+	for ( i = 0 ; i < PROFILE_COUNT ; i++ ) {
+		profile_start ( &profiler );
+		op ( cipher, ctx, random, random, sizeof ( random ) );
+		profile_stop ( &profiler );
+	}
 
 	/* Round to nearest whole number of cycles per byte */
-	cost = ( ( elapsed + ( sizeof ( random ) / 2 ) ) / sizeof ( random ) );
+	cost = ( ( profile_mean ( &profiler ) + ( sizeof ( random ) / 2 ) ) /
+		 sizeof ( random ) );
 
 	return cost;
 }

src/tests/digest_test.c

@@ -25,12 +25,18 @@ FILE_LICENCE ( GPL2_OR_LATER );
  *
  */
 
+/* Forcibly enable assertions */
+#undef NDEBUG
+
 #include <stdlib.h>
 #include <string.h>
 #include <ipxe/crypto.h>
 #include <ipxe/profile.h>
 #include "digest_test.h"
 
+/** Number of sample iterations for profiling */
+#define PROFILE_COUNT 16
+
 /**
  * Test digest algorithm
  *
@@ -81,8 +87,7 @@ unsigned long digest_cost ( struct digest_algorithm *digest ) {
 	static uint8_t random[8192]; /* Too large for stack */
 	uint8_t ctx[digest->ctxsize];
 	uint8_t out[digest->digestsize];
-	union profiler profiler;
-	unsigned long long elapsed;
+	struct profiler profiler;
 	unsigned long cost;
 	unsigned int i;
 
@@ -91,15 +96,19 @@ unsigned long digest_cost ( struct digest_algorithm *digest ) {
 	for ( i = 0 ; i < sizeof ( random ) ; i++ )
 		random[i] = rand();
 
-	/* Time digest calculation */
-	profile ( &profiler );
-	digest_init ( digest, ctx );
-	digest_update ( digest, ctx, random, sizeof ( random ) );
-	digest_final ( digest, ctx, out );
-	elapsed = profile ( &profiler );
+	/* Profile digest calculation */
+	memset ( &profiler, 0, sizeof ( profiler ) );
+	for ( i = 0 ; i < PROFILE_COUNT ; i++ ) {
+		profile_start ( &profiler );
+		digest_init ( digest, ctx );
+		digest_update ( digest, ctx, random, sizeof ( random ) );
+		digest_final ( digest, ctx, out );
+		profile_stop ( &profiler );
+	}
 
 	/* Round to nearest whole number of cycles per byte */
-	cost = ( ( elapsed + ( sizeof ( random ) / 2 ) ) / sizeof ( random ) );
+	cost = ( ( profile_mean ( &profiler ) + ( sizeof ( random ) / 2 ) ) /
+		 sizeof ( random ) );
 
 	return cost;
 }

src/tests/memcpy_test.c

@@ -34,6 +34,9 @@ FILE_LICENCE ( GPL2_OR_LATER );
 #include <ipxe/test.h>
 #include <ipxe/profile.h>
 
+/** Number of sample iterations for profiling */
+#define PROFILE_COUNT 16
+
 /* Provide global functions to allow inspection of generated code */
 
 void memcpy_0 ( void *dest, void *src ) { memcpy ( dest, src, 0 ); }
@@ -120,10 +123,10 @@ __attribute__ (( noinline )) void * memcpy_var ( void *dest, const void *src,
  */
 static void memcpy_test_speed ( unsigned int dest_offset,
 				unsigned int src_offset, size_t len ) {
+	struct profiler profiler;
 	uint8_t *dest;
 	uint8_t *src;
 	unsigned int i;
-	unsigned long elapsed;
 
 	/* Allocate blocks */
 	dest = malloc ( len + dest_offset );
@@ -135,21 +138,26 @@ static void memcpy_test_speed ( unsigned int dest_offset,
 	for ( i = 0 ; i < len ; i++ )
 		src[ src_offset + i ] = random();
 
-	/* Perform memcpy() */
-	simple_profile();
+	/* Check correctness of copied data */
 	memcpy ( ( dest + dest_offset ), ( src + src_offset ), len );
-	elapsed = simple_profile();
-
-	/* Check copied data */
 	ok ( memcmp ( ( dest + dest_offset ), ( src + src_offset ),
 		      len ) == 0 );
 
+	/* Profile memcpy() */
+	memset ( &profiler, 0, sizeof ( profiler ) );
+	for ( i = 0 ; i < PROFILE_COUNT ; i++ ) {
+		profile_start ( &profiler );
+		memcpy ( ( dest + dest_offset ), ( src + src_offset ), len );
+		profile_stop ( &profiler );
+	}
+
 	/* Free blocks */
 	free ( dest );
 	free ( src );
 
-	DBG ( "MEMCPY copied %zd bytes (+%d => +%d) in %ld ticks\n",
-	      len, src_offset, dest_offset, elapsed );
+	DBG ( "MEMCPY copied %zd bytes (+%d => +%d) in %ld +/- %ld ticks\n",
+	      len, src_offset, dest_offset, profile_mean ( &profiler ),
+	      profile_stddev ( &profiler ) );
 }
 
 /**

src/tests/profile_test.c

@@ -0,0 +1,140 @@
+/*
+ * Copyright (C) 2014 Michael Brown <mbrown@fensystems.co.uk>.
+ *
+ * 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 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., 51 Franklin Street, Fifth Floor, Boston, MA
+ * 02110-1301, USA.
+ */
+
+FILE_LICENCE ( GPL2_OR_LATER );
+
+/** @file
+ *
+ * Profiling self-tests
+ *
+ */
+
+/* Forcibly enable assertions */
+#undef NDEBUG
+
+#include <string.h>
+#include <assert.h>
+#include <ipxe/test.h>
+#include <ipxe/profile.h>
+
+/** A profiling test */
+struct profile_test {
+	/** Sample values */
+	const unsigned long *samples;
+	/** Number of samples */
+	unsigned int count;
+	/** Expected mean sample value */
+	unsigned long mean;
+	/** Expected standard deviation */
+	unsigned long stddev;
+};
+
+/** Define inline data */
+#define DATA(...) { __VA_ARGS__ }
+
+/** Define a profiling test */
+#define PROFILE_TEST( name, MEAN, STDDEV, SAMPLES )			\
+	static const unsigned long name ## _samples[] = SAMPLES;	\
+	static struct profile_test name = {				\
+		.samples = name ## _samples,				\
+		.count = ( sizeof ( name ## _samples ) /		\
+			   sizeof ( name ## _samples [0] ) ),		\
+		.mean = MEAN,						\
+		.stddev = STDDEV,					\
+	}
+
+/** Empty data set */
+PROFILE_TEST ( empty, 0, 0, DATA() );
+
+/** Single-element data set (zero) */
+PROFILE_TEST ( zero, 0, 0, DATA ( 0 ) );
+
+/** Single-element data set (non-zero) */
+PROFILE_TEST ( single, 42, 0, DATA ( 42 ) );
+
+/** Multiple identical element data set */
+PROFILE_TEST ( identical, 69, 0, DATA ( 69, 69, 69, 69, 69, 69, 69 ) );
+
+/** Small element data set */
+PROFILE_TEST ( small, 5, 2, DATA ( 3, 5, 9, 4, 3, 2, 5, 7 ) );
+
+/** Random data set */
+PROFILE_TEST ( random, 70198, 394,
+	       DATA ( 69772, 70068, 70769, 69653, 70663, 71078, 70101, 70341,
+		      70215, 69600, 70020, 70456, 70421, 69972, 70267, 69999,
+		      69972 ) );
+
+/** Large-valued random data set */
+PROFILE_TEST ( large, 93533894UL, 25538UL,
+	       DATA ( 93510333UL, 93561169UL, 93492361UL, 93528647UL,
+		      93557566UL, 93503465UL, 93540126UL, 93549020UL,
+		      93502307UL, 93527320UL, 93537152UL, 93540125UL,
+		      93550773UL, 93586731UL, 93521312UL ) );
+
+/**
+ * Report a profiling test result
+ *
+ * @v test		Profiling test
+ * @v file		Test code file
+ * @v line		Test code line
+ */
+static void profile_okx ( struct profile_test *test, const char *file,
+			  unsigned int line ) {
+	struct profiler profiler;
+	unsigned long mean;
+	unsigned long stddev;
+	unsigned int i;
+
+	/* Initialise profiler */
+	memset ( &profiler, 0, sizeof ( profiler ) );
+
+	/* Record sample values */
+	for ( i = 0 ; i < test->count ; i++ )
+		profile_update ( &profiler, test->samples[i] );
+
+	/* Check resulting statistics */
+	mean = profile_mean ( &profiler );
+	stddev = profile_stddev ( &profiler );
+	DBGC ( test, "PROFILE calculated mean %ld stddev %ld\n", mean, stddev );
+	okx ( mean == test->mean, file, line );
+	okx ( stddev == test->stddev, file, line );
+}
+#define profile_ok( test ) profile_okx ( test, __FILE__, __LINE__ )
+
+/**
+ * Perform profiling self-tests
+ *
+ */
+static void profile_test_exec ( void ) {
+
+	/* Perform profiling tests */
+	profile_ok ( &empty );
+	profile_ok ( &zero );
+	profile_ok ( &single );
+	profile_ok ( &identical );
+	profile_ok ( &small );
+	profile_ok ( &random );
+	profile_ok ( &large );
+}
+
+/** Profiling self-test */
+struct self_test profile_test __self_test = {
+	.name = "profile",
+	.exec = profile_test_exec,
+};

src/tests/tcpip_test.c

@@ -36,6 +36,9 @@ FILE_LICENCE ( GPL2_OR_LATER );
 #include <ipxe/profile.h>
 #include <ipxe/tcpip.h>
 
+/** Number of sample iterations for profiling */
+#define PROFILE_COUNT 16
+
 /** A TCP/IP fixed-data test */
 struct tcpip_test {
 	/** Data */
@@ -173,10 +176,10 @@ static void tcpip_okx ( struct tcpip_test *test, const char *file,
 static void tcpip_random_okx ( struct tcpip_random_test *test,
 			       const char *file, unsigned int line ) {
 	uint8_t *data = ( tcpip_data + test->offset );
+	struct profiler profiler;
 	uint16_t expected;
 	uint16_t generic_sum;
 	uint16_t sum;
-	unsigned long elapsed;
 	unsigned int i;
 
 	/* Sanity check */
@@ -194,12 +197,20 @@ static void tcpip_random_okx ( struct tcpip_random_test *test,
 	okx ( generic_sum == expected, file, line );
 
 	/* Verify optimised tcpip_continue_chksum() result */
-	simple_profile();
 	sum = tcpip_continue_chksum ( TCPIP_EMPTY_CSUM, data, test->len );
-	elapsed = simple_profile();
 	okx ( sum == expected, file, line );
-	DBG ( "TCPIP checksummed %zd bytes (+%zd) in %ld ticks\n",
-	      test->len, test->offset, elapsed );
+
+	/* Profile optimised calculation */
+	memset ( &profiler, 0, sizeof ( profiler ) );
+	for ( i = 0 ; i < PROFILE_COUNT ; i++ ) {
+		profile_start ( &profiler );
+		sum = tcpip_continue_chksum ( TCPIP_EMPTY_CSUM, data,
+					      test->len );
+		profile_stop ( &profiler );
+	}
+	DBG ( "TCPIP checksummed %zd bytes (+%zd) in %ld +/- %ld ticks\n",
+	      test->len, test->offset, profile_mean ( &profiler ),
+	      profile_stddev ( &profiler ) );
 }
 #define tcpip_random_ok( test ) tcpip_random_okx ( test, __FILE__, __LINE__ )
 

src/tests/tests.c

@@ -55,3 +55,4 @@ REQUIRE_OBJECT ( deflate_test );
 REQUIRE_OBJECT ( png_test );
 REQUIRE_OBJECT ( dns_test );
 REQUIRE_OBJECT ( uri_test );
+REQUIRE_OBJECT ( profile_test );