Measuring Boot Time

Here is a way to measure boot time on Host. The idea is take timestamp on the host after each UART message.

The original program was built and used under Cygwin. It had a few compiler warnings and a bug that are addressed with the updated program below. The updated program was built and tested under Ubuntu 10.10 with gcc v4.4.5. I'd expect it to still build under Cygwin, but haven't tested it.

copy paste the following as tstamp.c and build tstamp.exe:

// Purpose of this utility is to timestamp each line coming over stdin
// USAGES:
//    tstamp.exe < /dev/ttyS0
//    <commands> | tstamp.exe
// 

#include <stdio.h>
#include <stdlib.h>
#include <assert.h>
#include <time.h>
#include <sys/time.h>
#include <sys/signal.h>

#define MAX_BUF_SIZE	(10*1024)

char buf[MAX_BUF_SIZE];

// Global variables that control process shutdown.
sig_atomic_t graceful_quit = 0;

// Signal handler for SIGINT.
void SIGINT_handler (int signum)
{
	assert (signum == SIGINT);
	graceful_quit = 1;
}

// Signal handler for SIGQUIT.
void SIGQUIT_handler (int signum)
{
	assert (signum == SIGQUIT);
	graceful_quit = 1;
}

main(int argc)
{
	struct timeval tv;
	double time_start,time_now,time_prev;
	int first = 1;
	struct sigaction sa;

	sigemptyset (&sa.sa_mask);
	sa.sa_flags = 0;

	// as of now no arguments are allowed. print usage
	if (argc != 1)
	{
		printf(
			"Timestamps each line coming over stdin\n"
			"\tUSAGES:\n"
			"\t\ttstamp.exe < /dev/ttyS0\n"
			"\t\t<commands> | tstamp.exe\n"
			"\t\tetc..\n"
			"\n"
			"Output is printed in the following format\n"
			"\tcolumn1 is elapsed time since first message\n"
			"\tcolumn2 is elapsed time since previous message\n"
			"\tcolumn3 is the message\n"
		);

		exit(0);
	}

	// Register the handler for SIGINT.
	sa.sa_handler = SIGINT_handler;
	sigaction (SIGINT, &sa, 0);

	// Register the handler for SIGQUIT.
	sa.sa_handler =  SIGQUIT_handler;
	sigaction (SIGQUIT, &sa, 0);

	printf(
		"\tcolumn1 is elapsed time since first message\n"
		"\tcolumn2 is elapsed time since previous message\n"
		"\tcolumn3 is the message\n"
	);

	while (graceful_quit == 0)
	{
		if (fgets(buf, MAX_BUF_SIZE, stdin))
		{
			// get system time
			gettimeofday(&tv, NULL);

			// convert to double
			time_now = tv.tv_sec + (tv.tv_usec*(1.0/1000000.0));

			// if first time, notedown the time_start
			if (first)
			{
				first = 0,  time_start = time_prev = time_now;
			}

			fprintf(stdout
				,"%03.3f %02.3f: %s"
				,(float)(time_now-time_start)
				,(float)(time_now-time_prev)
				,buf
			);

			time_prev = time_now;
		}
	}

	fflush(stdout);
	exit(0);
}

Run tstamp.exe < /dev/ttyS0 and reset DVEVM. Assuming that uart is connected to PC. Here is the sample output:

       column1 is elapsed time since first message
       column2 is elapsed time since previous message
       column3 is the message
0.000 0.000:
0.000 0.000:
0.000 0.000: U-Boot 1.2.0 (Jun 23 2008 - 14:53:30)
0.000 0.000:
0.000 0.000: I2C:   ready
0.000 0.000: DRAM:  256 MB
0.000 0.000: MY AMD Flash: 16 MB
0.060 0.060: n:    serial
0.060 0.000: Out:   serial
0.060 0.000: Err:   serial
0.060 0.000: RM Clock :- 297MHz DDR Clock :- 162MHz
1.071 1.011: Hit any key to stop autoboot:   0
1.261 0.190: # Booting image at 80007fc0 ...
1.261 0.000:    Verifying Checksum ...
1.331 0.070: OK
1.331 0.000: OK
1.331 0.000: ## Loading Ramdisk Image at 80900000 ...
1.331 0.000:    Verifying Checksum ...
1.422 0.091: K
1.422 0.000:
1.422 0.000: Starting kernel ...
1.432 0.010:
2.093 0.661: ncompressing Linux.................................................
......................... oe otn he kernel.
2.463 0.370:bin/ash: can't access tty; job control turned off

Press Control-C to exit tstamp.exe.

• The latest version of Tera Term for Windows has the ability to timestamp incoming serial data when logging via File->Log. However, it just adds the date that the first byte of data on a line was received, it doesn't give an elapsed time like this program will.
• I'm not aware of any Linux terminal emulators that can timestamp incoming messages.
• Please use the following instruction below to set the correct UART Speed & configuration under Fedora 8 before using tstamp.

 stty -F /dev/ttyS0 speed 115200 -parenb -cstopb cread clocal -crtscts

Changes from the previous version:

• Control-C is caught and the output buffers are flushed. This may have been the cause of missing characters in the previous version.
• Changed gets() to fgets() to eliminate buffer overflow issues.