latency.c [was: Re: 2.6.9-rc1-mm1]

["Rafael J. Wysocki" <rjw@sisk.pl>]

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

On Friday 27 of August 2004 23:54, Rick Lindsley wrote:
[- snip -]
> You can also pick up the program "latency.c" at
> 
>     http://eaglet.rain.com/rick/linux/schedstat/v9/latency.c
> 
> With these two things in hand, you should be able to measure the latency
> on 2.6.8.1 of a particular process.
> 
> A patch is not necessary for 2.6.9-rc1-mm1 (schedstats is already in there)
> but you will need to config the kernel to use it.  Then retrieve a slightly
> different latency.c:
>     
>     http://eaglet.rain.com/rick/linux/schedstat/v10/latency.c
> 
> since 2.6.9-rc1-mm1 output format is different (as you noted, it's a
> different scheduler.)  Then you should be able to see if the latency of
> a particular process (updatedb, for instance) changes.

I've fiddled a bit with both the latency.c programs.  I've added some options 
to them etc.  In particular, now you can specify a program to run and monitor 
instead of a pid, which is handy if you need to monitor processes that exit 
quickly.  Everything is documented in the sources (attached).  I thought you 
might find this useful. :-)

Regards,
RJW

-- 
For a successful technology, reality must take precedence over public 
relations, for nature cannot be fooled.
					-- Richard P. Feynman

[-- Attachment #2: latency-v9.c --]
[-- Type: text/x-csrc, Size: 5613 bytes --]

/*
 * latency -- measure the scheduling latency of a particular process from
 *	the extra information provided in /proc/<pid>stat by version 4 of
 *	the schedstat patch. PLEASE NOTE: This program does NOT check to
 *	make sure that extra information is there; it assumes the last
 *	three fields in that line are the ones it's interested in.  Using
 *	it on a kernel that does not have the schedstat patch compiled in
 *	will cause it to happily produce bizarre results.
 *
 *	Note too that this is known to work only with versions 4 and 5
 *	of the schedstat patch, for similar reasons.
 *
 *	This currently monitors only one pid at a time but could easily
 *	be modified to do more.
 */
/*
 * Modified by Rafael J. Wysocki <rjw@sisk.pl> on September 4, 2004
 * Added options:
 * -o -- allows one to specify a log file to store the results in
 * -n -- turns on a numerical-only format (mutually exclusive with -v)
 * -r -- allows one to specify a program to run and monitor for latencies instead of a pid
 *
 * The -r option is handy if you want to monitor a process that exits quickly (eg. gcc or tar etc.).
 * The -o is necessary if -r is specified to separate the output of latency.c with the output of the
 * monitored process
 * The output generated with the -n option may be useful for creating graphs
 */
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>
#include <stdio.h>
#include <getopt.h>
#include <string.h>
#include <strings.h>

#define STRLEN 256

char procbuf[512];
char statname[64];
char progpath[STRLEN];
char logpath[STRLEN];
char *Progname;
FILE *fp, *outp;

void usage()
{
    fprintf(stderr, "Usage: %s [{-v|-n} ][-s sleeptime ][-o logfile ]{-r program|<pid>}\n", Progname);
    exit(-1);
}

/*
 * execute() is used to spawn a new process that will be monitored for latencies
 * The new process' command line is passed in *file
 */

void execute(char *file)
{
    char *ptr, **args;
    int cnt =  1, j;

    /* See how many arguments are to be passed */
    for (ptr = file; *ptr; ptr++)
	if (*ptr == ' ')  cnt++;
    args = (char **)malloc((cnt + 1) * sizeof(char *));
    /* Extract the arguments */
    args[0] =  file;
    ptr =  file;
    for (j = 1; j < cnt; j++) {
	ptr =  index(ptr, ' ');
	*ptr++ = '\0';
	args[j] =  ptr;
    }
    args[j] =  NULL;
    /* Run the program */
    execvp(args[0], args);
}

/*
 * get_stats() -- we presume that we are interested in the last three
 *	fields of the line we are handed, and further, that they contain
 *	only numbers and single spaces.
 */
void get_stats(char *buf, char *id, unsigned int *run_ticks,
	       unsigned int *wait_ticks, unsigned int *nran)
{
    char *ptr;

    ptr = index(buf, ')') + 1;
    *ptr = 0;
    strcpy(id, buf);
    *ptr = ' ';

    ptr = rindex(buf,' ');
    if (!ptr) return;

    *nran = atoi(ptr--);

    while (isdigit(*ptr) && --ptr != buf);
    if (ptr == buf) return;

    *wait_ticks = atoi(ptr--);

    while (isdigit(*ptr) && --ptr != buf);
    if (ptr == buf) return;

    *run_ticks = atoi(ptr);
}

main(int argc, char *argv[])
{
    int c;
    unsigned int sleeptime = 5, pid = 0, verbose = 0, numeric = 0, runprog = 0, log = 0;
    char id[32];
    unsigned int run_ticks, wait_ticks, nran;
    unsigned int orun_ticks=0, owait_ticks=0, oran=0;

    Progname = argv[0];
    id[0] = 0;
    while ((c = getopt(argc, argv, "s:vnr:o:")) != -1) {
	switch (c) {
	    case 's':
		sleeptime = atoi(optarg);
		break;
	    case 'v':
		verbose++;
		break;
	    case 'n':
		numeric++;
		break;
	    case 'r':
		strncpy(progpath, optarg, STRLEN - 1);
		progpath[STRLEN - 1] =  '\0';
		runprog++;
		break;
	    case 'o':
		strncpy(logpath, optarg, STRLEN - 1);
		logpath[STRLEN - 1] =  '\0';
		log++;
		break;
	    default:
		usage();
	}
    }

    if (verbose && numeric)
	usage();

    if (runprog) {
	pid =  fork();
	if (pid < 0) {
	    puts("fork() failed");
	    exit(pid);
	}
	if (!pid)
	    execute(progpath);
    }
    else if (optind < argc) {
	pid = atoi(argv[optind]);
    }

    if (!pid)
	usage();

    outp =  NULL;
    if (log)
	outp =  fopen(logpath, "w");
    if (!outp) {
	outp =  stdout;
	log = 0;
    }
    /*
     * now just spin collecting the stats
     */
    sprintf(statname,"/proc/%d/stat", pid);
    while (fp = fopen(statname, "r")) {
	    if (runprog)
		waitpid(pid, NULL, WNOHANG);

	    if (!fgets(procbuf, sizeof(procbuf), fp))
		    break;

	    get_stats(procbuf, id, &run_ticks, &wait_ticks, &nran);

	    if (verbose)
		fprintf(outp, "%s %d(%d) %d(%d) %d(%d) %4.2f %4.2f\n",
		    id, run_ticks, run_ticks - orun_ticks,
		    wait_ticks, wait_ticks - owait_ticks,
		    nran, nran - oran,
		    nran - oran ?
			(double)(run_ticks-orun_ticks)/(nran - oran) : 0,
		    nran - oran ?
			(double)(wait_ticks-owait_ticks)/(nran - oran) : 0);
	    else if (numeric)
		fprintf(outp, "%s %4.2f %4.2f\n",
		    id, nran - oran ?
			(double)(run_ticks-orun_ticks)/(nran - oran) : 0,
		    nran - oran ?
			(double)(wait_ticks-owait_ticks)/(nran - oran) : 0);
	    else
		fprintf(outp, "%s avgrun=%4.2fms avgwait=%4.2fms\n",
		    id, nran - oran ?
			(double)(run_ticks-orun_ticks)/(nran - oran) : 0,
		    nran - oran ?
			(double)(wait_ticks-owait_ticks)/(nran - oran) : 0);
	    fclose(fp);
	    oran = nran;
	    orun_ticks = run_ticks;
	    owait_ticks = wait_ticks;
	    sleep(sleeptime);

	    if (runprog)
		waitpid(pid, NULL, WNOHANG);

	    fp = fopen(statname,"r");
	    if (!fp)
		    break;
    }
    if (log)
	fclose(outp);
    if (id[0])
	printf("Process %s has exited.\n", id);
    else
	printf("Process %d does not exist.\n", pid);
    exit(0);
}

[-- Attachment #3: latency-v10.c --]
[-- Type: text/x-csrc, Size: 6230 bytes --]

/*
 * latency -- measure the scheduling latency of a particular process from
 *	the extra information provided in /proc/<pid>stat by version 4 of
 *	the schedstat patch. PLEASE NOTE: This program does NOT check to
 *	make sure that extra information is there; it assumes the last
 *	three fields in that line are the ones it's interested in.  Using
 *	it on a kernel that does not have the schedstat patch compiled in
 *	will cause it to happily produce bizarre results.
 *
 *	Note too that this is known to work only with versions 4 and 5
 *	of the schedstat patch, for similar reasons.
 *
 *	This currently monitors only one pid at a time but could easily
 *	be modified to do more.
 */
/*
 * Modified by Rafael J. Wysocki <rjw@sisk.pl> on September 4, 2004
 * Added options:
 * -o -- allows one to specify a log file to store the results in
 * -n -- turns on a numerical-only format (mutually exclusive with -v)
 * -r -- allows one to specify a program to run and monitor for latencies instead of a pid
 *
 * The -r option is handy if you want to monitor a process that exits quickly (eg. gcc or tar etc.).
 * The -o is necessary if -r is specified to separate the output of latency.c with the output of the
 * monitored process
 * The output generated with the -n option may be useful for creating graphs
 */
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>
#include <stdio.h>
#include <getopt.h>
#include <string.h>
#include <strings.h>

#define STRLEN 256

extern char *index(), *rindex();
char procbuf[512];
char statname[64];
char progpath[STRLEN];
char logpath[STRLEN];
char *Progname;
FILE *fp, *outp;

void usage()
{
    fprintf(stderr, "Usage: %s [{-v|-n} ][-s sleeptime ][-o logfile ]{-r program|<pid>}\n", Progname);
    exit(-1);
}

/*
 * execute() is used to spawn a new process that will be monitored for latencies
 * The new process' command line is passed in *file
 */

void execute(char *file)
{
    char *ptr, **args;
    int cnt =  1, j;

    /* See how many arguments are to be passed */
    for (ptr = file; *ptr; ptr++)
	if (*ptr == ' ')  cnt++;
    args = (char **)malloc((cnt + 1) * sizeof(char *));
    /* Extract the arguments */
    args[0] =  file;
    ptr =  file;
    for (j = 1; j < cnt; j++) {
	ptr =  index(ptr, ' ');
	*ptr++ = '\0';
	args[j] =  ptr;
    }
    args[j] =  NULL;
    /* Run the program */
    execvp(args[0], args);
}

/*
 * get_stats() -- we presume that we are interested in the first three
 *	fields of the line we are handed, and further, that they contain
 *	only numbers and single spaces.
 */
void get_stats(char *buf, unsigned int *run_ticks, unsigned int *wait_ticks,
    unsigned int *nran)
{
    char *ptr;

    /* sanity */
    if (!buf || !run_ticks || !wait_ticks || !nran)
	return;

    /* leading blanks */
    ptr = buf;
    while (*ptr && isblank(*ptr))
	ptr++;

    /* first number -- run_ticks */
    *run_ticks = atoi(ptr);
    while (*ptr && isdigit(*ptr))
	ptr++;
    while (*ptr && isblank(*ptr))
	ptr++;

    /* second number -- wait_ticks */
    *wait_ticks = atoi(ptr);
    while (*ptr && isdigit(*ptr))
	ptr++;
    while (*ptr && isblank(*ptr))
	ptr++;

    /* last number -- nran */
    *nran = atoi(ptr);
}

/*
 * get_id() -- extract the id field from that /proc/<pid>/stat file
 */
void get_id(char *buf, char *id)

{
    char *ptr;

    /* sanity */
    if (!buf || !id)
	return;

    ptr = index(buf, ')') + 1;
    *ptr = 0;
    strcpy(id, buf);
    *ptr = ' ';

    return;
}

main(int argc, char *argv[])
{
    int c;
    unsigned int sleeptime = 5, pid = 0, verbose = 0, numeric = 0, runprog = 0, log = 0;
    char id[32];
    unsigned int run_ticks, wait_ticks, nran;
    unsigned int orun_ticks=0, owait_ticks=0, oran=0;

    Progname = argv[0];
    id[0] = 0;
    while ((c = getopt(argc,argv,"s:vnr:o:")) != -1) {
	switch (c) {
	    case 's':
		sleeptime = atoi(optarg);
		break;
	    case 'v':
		verbose++;
		break;
	    case 'n':
		numeric++;
		break;
	    case 'r':
		strncpy(progpath, optarg, STRLEN - 1);
		progpath[STRLEN - 1] =  '\0';
		runprog++;
		break;
	    case 'o':
		strncpy(logpath, optarg, STRLEN - 1);
		logpath[STRLEN - 1] =  '\0';
		log++;
		break;
	    default:
		usage();
	}
    }

    if (verbose && numeric)
	usage();

    if (runprog) {
	pid =  fork();
	if (pid < 0) {
	    puts("fork() failed");
	    exit(pid);
	}
	if (!pid)
	    execute(progpath);
    }
    else if (optind < argc) {
	pid = atoi(argv[optind]);
    }

    if (!pid)
	usage();

    outp =  NULL;
    if (log)
	outp =  fopen(logpath, "w");
    if (!outp) {
	outp =  stdout;
	log = 0;
    }

    sprintf(statname, "/proc/%d/stat", pid);
    if (fp = fopen(statname, "r")) {
	if (fgets(procbuf, sizeof(procbuf), fp))
	    get_id(procbuf, id);
	fclose(fp);
    }

    /*
     * now just spin collecting the stats
     */
    sprintf(statname, "/proc/%d/schedstat", pid);
    while (fp = fopen(statname, "r")) {
	    if (runprog)
		waitpid(pid, NULL, WNOHANG);

	    if (!fgets(procbuf, sizeof(procbuf), fp))
		    break;

	    get_stats(procbuf, &run_ticks, &wait_ticks, &nran);

	    if (verbose)
		fprintf(outp, "%s %d(%d) %d(%d) %d(%d) %4.2f %4.2f\n",
		    id, run_ticks, run_ticks - orun_ticks,
		    wait_ticks, wait_ticks - owait_ticks,
		    nran, nran - oran,
		    nran - oran ?
			(double)(run_ticks-orun_ticks)/(nran - oran) : 0,
		    nran - oran ?
			(double)(wait_ticks-owait_ticks)/(nran - oran) : 0);
	    else if (numeric)
		fprintf(outp, "%s %4.2f %4.2f\n",
		    id, nran - oran ?
			(double)(run_ticks-orun_ticks)/(nran - oran) : 0,
		    nran - oran ?
			(double)(wait_ticks-owait_ticks)/(nran - oran) : 0);
	    else
		fprintf(outp, "%s avgrun=%4.2fms avgwait=%4.2fms\n",
		    id, nran - oran ?
			(double)(run_ticks-orun_ticks)/(nran - oran) : 0,
		    nran - oran ?
			(double)(wait_ticks-owait_ticks)/(nran - oran) : 0);
	    fclose(fp);
	    oran = nran;
	    orun_ticks = run_ticks;
	    owait_ticks = wait_ticks;
	    sleep(sleeptime);

	    if (runprog)
		waitpid(pid, NULL, WNOHANG);

	    fp = fopen(statname,"r");
	    if (!fp)
		    break;
    }
    if (log)
	fclose(outp);
    if (id[0])
	printf("Process %s has exited.\n", id);
    else
	printf("Process %d does not exist.\n", pid);
    exit(0);
}