[util-linux] readprofile ignores the last element in /proc/profile

[util-linux] readprofile ignores the last element in /proc/profile

[mita akinobu]

Hello,

The readprofile command does not print the number of clock ticks about
the last element in profiling buffer.

Since the number of clock ticks which occur on the module functions is
as same as the value of the last element of prof_buffer[]. when many
ticks occur on there, some users who browsing the output of readprofile
may overlook the fact that the bottle-neck may exist in the modules.

I create the patch which enable to print clock ticks of the last
element as "*unknown*".

# readprofile
 77843 poll_idle                                1526.3333
     1 cpu_idle                                   0.0043
 [...]
     4 schedule_timeout                           0.0209
     2 *unknown*
108494 total                                      0.0385

If the clock ticks of '*unknown*' is large, it is highly recommended
to use OProfile, or to retry readprofile after compiling suspicious
modules into the kernel.

Mr.Brouwer, Could you apply this patch against util-linux-2.12a?


--- util-linux-2.12a/sys-utils/readprofile.c.orig	2004-08-24 23:11:16.383760112 +0900
+++ util-linux-2.12a/sys-utils/readprofile.c	2004-08-24 23:15:03.780190600 +0900
@@ -145,6 +145,7 @@ main(int argc, char **argv) {
 	int maplineno=1;
 	int popenMap;   /* flag to tell if popen() has been used */
 	int header_printed;
+	int end_of_text=0;
 
 #define next (current^1)
 
@@ -314,7 +315,7 @@ main(int argc, char **argv) {
 	/*
 	 * Main loop.
 	 */
-	while (fgets(mapline,S_LEN,map)) {
+	while (!end_of_text && fgets(mapline,S_LEN,map)) {
 		unsigned int this=0;
 
 		if (sscanf(mapline,"%llx %s %s",&next_add,mode,next_name)!=3) {
@@ -327,9 +328,8 @@ main(int argc, char **argv) {
 		/* ignore any LEADING (before a '[tT]' symbol is found)
 		   Absolute symbols */
 		if ((*mode == 'A' || *mode == '?') && total == 0) continue;
-		if (*mode != 'T' && *mode != 't' &&
-		    *mode != 'W' && *mode != 'w')
-			break;	/* only text is profiled */
+		if (!strcmp(next_name, "_etext"))
+			end_of_text = 1;
 
 		if (indx >= len / sizeof(*buf)) {
 			fprintf(stderr, _("%s: profile address out of range. "
@@ -367,6 +367,9 @@ main(int argc, char **argv) {
 
 		maplineno++;
 	}
+	/* clock ticks, out of kernel text */
+	printf("%6i %s\n", buf[len/sizeof(*buf)-1], "*unknown*");
+
 	/* trailer */
 	if (optVerbose)
 		printf("%016x %-40s %6i %8.4f\n",

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

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

On Wed, Aug 25, 2004 at 12:22:09AM +0900, mita akinobu wrote:
> The readprofile command does not print the number of clock ticks about
> the last element in profiling buffer.
> Since the number of clock ticks which occur on the module functions is
> as same as the value of the last element of prof_buffer[]. when many
> ticks occur on there, some users who browsing the output of readprofile
> may overlook the fact that the bottle-neck may exist in the modules.
> I create the patch which enable to print clock ticks of the last
> element as "*unknown*".

Well, since I couldn't stop vomiting for hours after I looked at the
code for readprofile(1), here's a reimplementation, with various
misfeatures removed, included as a MIME attachment.


-- wli

[-- Attachment #2: readprofile.c --]
[-- Type: text/x-csrc, Size: 4984 bytes --]

/*
 * readprofile(1) implementation.
 * (C) 2004 William Irwin, Oracle
 * Licensed under GPL, or any DFSG-free license of the user's choice.
 */
#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>
#include <string.h>
#include <strings.h>
#include <unistd.h>
#include <limits.h>
#include <fcntl.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/utsname.h>

struct sym {
	unsigned long long vaddr;
	char name[64];
	unsigned long hits;
};

struct profile_state {
	int fd, shift;
	uint32_t *buf;
	size_t bufsz;
	struct sym syms[2], *last, *this;
	unsigned long long stext, vaddr;
	unsigned long total;
	char type, sym[64];
};

static int digits(void)
{
	static int ret = 0;
	unsigned long n = ULONG_MAX;

	if (ret)
		return ret;
	for (n = ULONG_MAX; n >= 10; n /= 10)
		++ret;
	ret += !!n;
	return ret;
}

static void shift_syms(struct sym *syms, struct sym **last, struct sym **this)
{
	*last = *this;
	*this = &syms[!(*this - syms)];
}

static int is_text(char c)
{
	return c == 'T' || c == 't' || c == 'W' || c == 'w';
}

static long profile_off(unsigned long long vaddr, struct profile_state *state)
{
	return (((vaddr - state->stext) >> state->shift) + 1)*sizeof(uint32_t);
}

static int state_transition(struct profile_state *state)
{
	int ret = 0;
	long page_mask, start, end;
	unsigned off;

	if (!state->stext) {
		if (!strcmp(state->sym, "_stext"))
			state->stext = state->vaddr;
		goto out;
	} else if ((!state->last || !state->this) && !is_text(state->type)) {
		ret = 1;
		goto out;
	}
	shift_syms(state->syms, &state->last, &state->this);
	state->this->vaddr = state->vaddr;
	state->this->hits = 0;
	if (is_text(state->type)) {
		strcpy(state->this->name, state->sym);
		if (!state->last)
			goto out;
	} else {
		strcpy(state->this->name, "*unknown*");
		ret = 1;
	}
	start = profile_off(state->last->vaddr, state);
	end = profile_off(state->this->vaddr, state)
					+ !!state->shift*sizeof(uint32_t);
	if (lseek(state->fd, start, SEEK_SET) != start) {
		fprintf(stderr, "fseek() failed\n");
		exit(EXIT_FAILURE);
	}
	if (state->bufsz < (size_t)(end - start)) {
		page_mask = getpagesize() - 1;
		state->bufsz = (end - start + page_mask) & ~page_mask;
		free(state->buf);
		if (!(state->buf = malloc(state->bufsz))) {
			fprintf(stderr, "out of memory\n");
			exit(EXIT_FAILURE);
		}
	}
	if (read(state->fd, state->buf, end - start) == end - start) {
		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
			state->last->hits += state->buf[off];
	} else {
		ret = 1;
		strcpy(state->last->name, "*unknown*");
	}
	if (state->last->hits)
		printf("%*lu %s\n", digits(), state->last->hits,
							state->last->name);
	state->total += state->last->hits;
out:
	return ret;
}

static int readprofile(FILE *system_map, int profile_buffer)
{
	char *buf = NULL;
	ssize_t nchar, bufsz;
	uint32_t step;
	struct profile_state state = {
		.fd	= profile_buffer,
		.last	= NULL,
		.this	= NULL,
		.total	= 0,
		.stext	= 0,
	};

	if (read(profile_buffer, &step, sizeof(uint32_t)) != sizeof(uint32_t)) {
		fprintf(stderr, "read() failed\n");
		return EXIT_FAILURE;
	}
	state.shift = ffs(step) - 1;
	if (!(state.buf = malloc(getpagesize()))) {
		fprintf(stderr, "out of memory\n");
		return EXIT_FAILURE;
	}
	state.bufsz = getpagesize();
	while ((nchar = getline(&buf, &bufsz, system_map)) > 0) {
		if (sscanf(buf, "%Lx %c %63s", &state.vaddr, &state.type,
							state.sym) != 3)
			continue;
		if (state_transition(&state))
			break;
	}
	printf("%*lu total\n", digits(), state.total);
	if (state.buf)
		free(state.buf);
	return 0;
}

static FILE *open_system_map(void)
{
	struct utsname buf;
	char s[256];

	if (!access("/boot/System.map", R_OK))
		return fopen("/boot/System.map", "r");
	if (uname(&buf))
		return NULL;
	snprintf(s, sizeof(s), "/boot/System.map-%s", buf.release);
	return fopen(s, "r");
}

int main(int argc, char * const argv[])
{
	FILE *system_map = NULL;
	int c, ret, profile_buffer = -1;
	static const char optstr[] = "m:p:";

	while ((c = getopt(argc, argv, optstr)) != EOF) {
		switch (c) {
			case 'm':
				if (!strcmp(optarg, "-"))
					system_map = fdopen(STDIN_FILENO, "r");
				else if (!access(optarg, R_OK))
					system_map = fopen(optarg, "r");
				else {
					fprintf(stderr, "mapfile %s is "
						"inaccessible\n", optarg);
					exit(EXIT_FAILURE);
				}
				break;
			case 'p':
				if (!strcmp(optarg, "-"))
					profile_buffer = STDIN_FILENO;
				else if (!access(optarg, R_OK))
					profile_buffer = open(optarg, O_RDONLY);
				else {
					fprintf(stderr, "profile %s is "
						"inaccessible\n", optarg);
					exit(EXIT_FAILURE);
				}
				break;
			case '?':
			default:
				fprintf(stderr, "usage: %s [ -m mapfile ] "
					"[ -p profile ]\n", argv[0]);
				exit(EXIT_FAILURE);
		}
	}
	if (!system_map)
		system_map = open_system_map();
	if (profile_buffer < 0)
		profile_buffer = open("/proc/profile", O_RDONLY);
	ret = readprofile(system_map, profile_buffer);
	fclose(system_map);
	close(profile_buffer);
	return ret;
}

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

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

On Sun, Aug 29, 2004 at 09:22:52AM -0700, William Lee Irwin III wrote:
> Well, since I couldn't stop vomiting for hours after I looked at the
> code for readprofile(1), here's a reimplementation, with various
> misfeatures removed, included as a MIME attachment.

I guess I might as well write a diffprof(1) too.


-- wli

[-- Attachment #2: diffprof.c --]
[-- Type: text/x-csrc, Size: 6143 bytes --]

/*
 * diffprof(1) implementation.
 * (C) 2004 William Irwin, Oracle
 * Licensed under GPL, and derived from the following GPL code:
 * linked list implementation (C) Linus Torvalds and various others
 * jhash implementation (C) Bob Jenkins, David S. Miller, and others
 */
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <stdint.h>
#include <limits.h>

#define TABLE_SIZE		1024
#define offsetof(type, member)	((size_t)(unsigned long)(&((type *)0)->member))
#define list_entry(elem, type, member)					\
		((type *)((char *)(elem) - offsetof(type, member)))
#define list_for_each(elem, list, member)				\
	for (elem = list_entry((list)->next, typeof(*(elem)), member);	\
		&(elem)->member != (list);				\
		elem = list_entry((elem)->member.next, typeof(*(elem)), member))
#define list_for_each_safe(elem, save, list, member)			\
for (elem = list_entry((list)->next, typeof(*(elem)), member),		\
	save = list_entry((elem)->member.next, typeof(*(elem)), member);\
		&(elem)->member != (list);				\
	elem = save,							\
	save = list_entry((save)->member.next, typeof(*(elem)), member))

/*
 * A number close to ((sqrt(5) - 1)/2) * 2**32 with low d(n) (few divisors)
 * 0x9e3779b9 == 2654435769 == 3 * 89 * 523 * 19009
 */
#define JHASH_GOLDEN_RATIO      0x9e3779b9
#define __jhash_mix(a, b, c)						\
{									\
	a -= b; a -= c; a ^= (c) >> 13;					\
	b -= c; b -= a; b ^= (a) << 8;					\
	c -= a; c -= b; c ^= (b) >> 13;					\
	a -= b; a -= c; a ^= (c) >> 12;					\
	b -= c; b -= a; b ^= (a) << 16;					\
	c -= a; c -= b; c ^= (b) >> 5;					\
	a -= b; a -= c; a ^= (c) >> 3;					\
	b -= c; b -= a; b ^= (a) << 10;					\
	c -= a; c -= b; c ^= (b) >> 15;					\
}

struct list {
	struct list *next, *prev;
};

struct sym {
	long len, hits[2];
	char *s;
	struct list list;
};

static struct list table[TABLE_SIZE];

static uint32_t jhash(const void *key, uint32_t length, uint32_t initval)
{
	const uint8_t *k = key;
	uint32_t a = JHASH_GOLDEN_RATIO, b = JHASH_GOLDEN_RATIO, c = initval,
								len = length;

	while (len >= 12) {
		a += k[0] + ((uint32_t)k[1] << 8) + ((uint32_t)k[2] << 16)
						+ ((uint32_t)k[3] << 24);
		b += k[4] + ((uint32_t)k[5] << 8) + ((uint32_t)k[6] << 16)
						+ ((uint32_t)k[7] << 24);
		c += k[8] + ((uint32_t)k[9] << 8) + ((uint32_t)k[10] << 16)
						+ ((uint32_t)k[11] << 24);
		__jhash_mix(a,b,c);
		k += 12;
		len -= 12;
	}
	c += length;
	switch (len) {
		case 11:
			c += (uint32_t)k[10] << 24;
		case 10:
			c += (uint32_t)k[9] << 16;
		case 9:
			c += (uint32_t)k[8] << 8;
		case 8:
			b += (uint32_t)k[7] << 24;
		case 7:
			b += (uint32_t)k[6] << 16;
		case 6:
			b += (uint32_t)k[5] << 8;
		case 5:
			b += k[4];
		case 4:
			a += (uint32_t)k[3] << 24;
		case 3:
			a += (uint32_t)k[2] << 16;
		case 2:
			a += (uint32_t)k[1] << 8;
		case 1:
			a += k[0];
	}
	__jhash_mix(a,b,c);
	return c;
}

static void list_init(struct list *list)
{
	list->next = list->prev = list;
}

static void __list_add(struct list *prev, struct list *next, struct list *elem)
{
	next->prev = elem;
	elem->next = next;
	elem->prev = prev;
	prev->next = elem;
}

static void list_add(struct list *list, struct list *elem)
{
	__list_add(list, list->next, elem);
}

static void __list_del(struct list *prev, struct list *next)
{
	next->prev = prev;
	prev->next = next;
}

static void list_del(struct list *list)
{
	__list_del(list->prev, list->next);
}

static void table_init(void)
{
	int i;

	for (i = 0; i < TABLE_SIZE; ++i)
		list_init(&table[i]);
}

struct sym *sym_alloc(const char *buf, int after)
{
	struct sym *sym = malloc(sizeof(struct sym));

	if (sym) {
		memset(sym, 0, sizeof(struct sym));
		sym->s = strdup(buf);
		if (!sym->s)
			goto err_sym;
		if (sscanf(buf, "%ld %s\n", &sym->hits[after], sym->s) != 2)
			goto err_str;
		sym->len = strlen(sym->s);
	}
	return sym;
err_str:
	free(sym->s);
err_sym:
	free(sym);
	return NULL;
}

static void sym_free(struct sym *sym)
{
	free(sym->s);
	free(sym);
}

static void sym_emit(struct sym *sym)
{
	static int digits = 0;
	long difference = sym->hits[1] - sym->hits[0];

	if (!digits) {
		unsigned long n = ULONG_MAX;

		for (n = ULONG_MAX; n >= 10; n /= 10)
			++digits;
		digits += !!n;
	}
	if (difference)
		printf("%*ld %s\n", digits, difference, sym->s);
}

static void sym_hash(struct sym *sym, int after)
{
	struct sym *collide;
	struct list *list;

	list = &table[jhash(sym->s, sym->len, sym->len) % TABLE_SIZE];
	list_for_each(collide, list, list) {
		if (collide->len == sym->len && !strcmp(collide->s, sym->s)) {
			collide->hits[after] = sym->hits[after];
			sym_emit(collide);
			list_del(&collide->list);
			sym_free(collide);
			sym_free(sym);
			return;
		}
	}
	list_add(list, &sym->list);
}

static void sym_cleanup(void)
{
	struct sym *save, *sym;
	int i;

	for (i = 0; i < TABLE_SIZE; ++i) {
		list_for_each_safe(sym, save, &table[i], list) {
			list_del(&sym->list);
			sym_emit(sym);
			sym_free(sym);
		}
	}
}

static int __read_sym(FILE *file, char **buf, size_t *bufsz, int after)
{
	struct sym *sym;
	ssize_t ret = getline(buf, bufsz, file);

	if (ret <= 0)
		return ret;
	if (!(sym = sym_alloc(*buf, after)))
		return -1;
	sym_hash(sym, after);
	return 0;
}

static void read_syms(FILE *before, FILE *after)
{
	char *buf = NULL;
	size_t bufsz;
	int eof_before = 0, eof_after = 0;

	while (!eof_before && !eof_after) {
		if (!eof_before) {
			if (feof(before))
				eof_before = 1;
			else if (__read_sym(before, &buf, &bufsz, 0) < 0)
				break;
		}
		if (!eof_after) {
			if (feof(after))
				eof_after = 1;
			else if (__read_sym(after, &buf, &bufsz, 1) < 0)
				break;
		}
	}
	free(buf);
}

int main(int argc, char * const argv[])
{
	FILE *before, *after;

	if (argc > 3 || argc < 2)
		goto usage;
	if (strcmp(argv[1], "-"))
		before = fopen(argv[1], "r");
	else {
		before = stdin;
		if (!strcmp(argv[2], "-"))
			goto usage;
	}
	if (!strcmp(argv[2], "-") || argc == 2)
		after = stdin;
	else
		after = fopen(argv[2], "r");
	if (!before || !after)
		goto usage;
	table_init();
	read_syms(before, after);
	sym_cleanup();
	return 0;
usage:
	fprintf(stderr, "usage: %s profile [ profile ]\n", argv[0]);
	return EXIT_FAILURE;
}

Re: [util-linux] readprofile ignores the last element in /proc/profile

[Andries Brouwer]

On Sun, Aug 29, 2004 at 11:41:14AM -0700, William Lee Irwin III wrote:
> On Sun, Aug 29, 2004 at 09:22:52AM -0700, William Lee Irwin III wrote:
> > Well, since I couldn't stop vomiting for hours after I looked at the
> > code for readprofile(1), here's a reimplementation, with various
> > misfeatures removed, included as a MIME attachment.
> 
> I guess I might as well write a diffprof(1) too.

Thanks!

<mutter>
Is it really necessary to tell Alessandro Rubini, Stephane Eranian,
Andrew Morton, Werner Almesberger, John Levon, Nikita Danilov
that their work makes you vomit?
Many kernel people have such unpleasant habits.
It fully suffices to say that you considered the original code
too ugly to fix.
</mutter>

<util-linux maintainer>
Your code still requires some polishing. No localized messages, etc.
And next, you removed some features, but do not indicate what
replacement you see.
For example, Andrew added the -M option that sets a frequency.
Are you going to contribute a write_profile too?
Or do you think nobody should wish to set a frequency?
</util-linux maintainer>

Andries

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

On Sun, Aug 29, 2004 at 11:41:14AM -0700, William Lee Irwin III wrote:
>> I guess I might as well write a diffprof(1) too.

On Sun, Aug 29, 2004 at 09:26:17PM +0200, Andries Brouwer wrote:
> Thanks!
> <mutter>
> Is it really necessary to tell Alessandro Rubini, Stephane Eranian,
> Andrew Morton, Werner Almesberger, John Levon, Nikita Danilov
> that their work makes you vomit?
> Many kernel people have such unpleasant habits.
> It fully suffices to say that you considered the original code
> too ugly to fix.
> </mutter>

It probably qualifies as impolite. I suppose a better way of going
about this would be saying that the code has accumulated some cruft,
and then describing the differences in greater detail.

The removal of the multiplier resetting is an oversight; I rarely
use the feature myself, but upon closer examination, the multiplier
accepted by write_profile() is not ASCII. I also question the role of a
profile report extraction utility in alterations of profiling state.

The removal of the reset feature is once again intentional as this
can be done by echo > /proc/profile.

The removal of the individual bin count reporting is intentional, but
not a very nice removal, as it's a useful feature and definitely not a
misfeature. The format of the histogram reporting is, however, not very
useful as sort(1) etc. don't easily interoperate with it. This should
be put back for serious use.

The removal of accepting compressed files is once again intentional,
and replaced with the new feature of accepting '-' as an argument for
the files operated on so that decompression to pipes may replace it.

The removal of the stepsize reporting was intentional, but again not
a nice removal.

The removal of reporting zero hit count symbols was intentional, but
again not nice.

The removal of verbose reporting with text addresses in addition to the
symbol was intentional, but again not nice.

The removal of -V was intentional, as I consider it bloat.

The removal of the normalized load from the reporting was very
intentional, as it's pure gibberish.

The difference I cared the most about was algorithmic. A giant memcpy()
of the profile buffer and making multiple passes over it is ridiculous.
This was recoded as maintaining a buffer large enough to hold the
length of the profile buffer spanning symbol currently being examined.
In this way the memory resources required for it to operate are
drastically reduced from multiple megabytes to just a few pages.


On Sun, Aug 29, 2004 at 09:26:17PM +0200, Andries Brouwer wrote:
> <util-linux maintainer>
> Your code still requires some polishing. No localized messages, etc.

I tend to avoid locale bits due to system resource and library
dependency concerns. I usually try to avoid using (g)libc for similar
reasons also by making syscalls directly, static linking and so on,
but expected that would not go over well.


On Sun, Aug 29, 2004 at 09:26:17PM +0200, Andries Brouwer wrote:
> And next, you removed some features, but do not indicate what
> replacement you see.
> For example, Andrew added the -M option that sets a frequency.
> Are you going to contribute a write_profile too?
> Or do you think nobody should wish to set a frequency?
> </util-linux maintainer>

I wasn't really expecting much to come of it besides prodding people
to clean up bloat. The reduced functionality alone likely precludes it
from consideration for inclusion. Supposing that there is greater
interest, which I don't expect, I can fix these things up and so on.


-- wli

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

On Sun, Aug 29, 2004 at 02:23:50PM -0700, William Lee Irwin III wrote:
> It probably qualifies as impolite. I suppose a better way of going
> about this would be saying that the code has accumulated some cruft,
> and then describing the differences in greater detail.
> The removal of the multiplier resetting is an oversight; I rarely
> use the feature myself, but upon closer examination, the multiplier
> accepted by write_profile() is not ASCII. I also question the role of a
> profile report extraction utility in alterations of profiling state.
> The removal of the reset feature is once again intentional as this
> can be done by echo > /proc/profile.
> The removal of the individual bin count reporting is intentional, but
> not a very nice removal, as it's a useful feature and definitely not a
> misfeature. The format of the histogram reporting is, however, not very
> useful as sort(1) etc. don't easily interoperate with it. This should
> be put back for serious use.

Oh, the removal of the reversed byte order detection was also very
intentional as that appears to frequently go wrong. I'd prefer an
explicit option to support cross-endianness profiling.


-- wli

Re: [util-linux] readprofile ignores the last element in /proc/profile

[Andries Brouwer]

On Sun, Aug 29, 2004 at 02:23:50PM -0700, William Lee Irwin III wrote:

> The difference I cared the most about was algorithmic. A giant memcpy()
> of the profile buffer and making multiple passes over it is ridiculous.
> This was recoded as maintaining a buffer large enough to hold the
> length of the profile buffer spanning symbol currently being examined.
> In this way the memory resources required for it to operate are
> drastically reduced from multiple megabytes to just a few pages.

That is good - although so far I have not heard complaints
about readprofile's memory use. Maybe multiple MB is not
so excessive these days.

But improvement is always good.

On the other hand, I like stability. Maybe readprofile is just some
kind of throwaway utility, not very important, but nevertheless,
some people use it, and they have habits and hate to relearn,
and they have scripts, and hate to adapt these scripts.

So, if the internal code is improved, excellent, but I am not so
happy if the invocation is changed without a very good reason.

Maybe you can make a cross: your improved algorithm inside the
old framework with options and locale?

> The removal of -V was intentional, as I consider it bloat.

Don't you know that whenever there are complaints about software
the very first question is "which version?"?

> I wasn't really expecting much to come of it besides prodding people
> to clean up bloat. The reduced functionality alone likely precludes it
> from consideration for inclusion. Supposing that there is greater
> interest, which I don't expect, I can fix these things up and so on.

Well, you sent me something. I have three choices: take it as
replacement for the current version, ignore it, work on it.
I have no time to work on it, so am only happy with what you send
if it can replace the current version.

Andries

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

On Mon, Aug 30, 2004 at 01:25:43AM +0200, Andries Brouwer wrote:
> That is good - although so far I have not heard complaints
> about readprofile's memory use. Maybe multiple MB is not
> so excessive these days.
> But improvement is always good.
> On the other hand, I like stability. Maybe readprofile is just some
> kind of throwaway utility, not very important, but nevertheless,
> some people use it, and they have habits and hate to relearn,
> and they have scripts, and hate to adapt these scripts.
> So, if the internal code is improved, excellent, but I am not so
> happy if the invocation is changed without a very good reason.
> Maybe you can make a cross: your improved algorithm inside the
> old framework with options and locale?

Easy enough, though I suppose there are also stylistic improvements.


On Sun, Aug 29, 2004 at 02:23:50PM -0700, William Lee Irwin III wrote:
>> The removal of -V was intentional, as I consider it bloat.

On Mon, Aug 30, 2004 at 01:25:43AM +0200, Andries Brouwer wrote:
> Don't you know that whenever there are complaints about software
> the very first question is "which version?"?

Okay, I suppose asking to look at external information with dpkg, rpm,
etc. may not be feasible/desirable under all circumstances.


On Sun, Aug 29, 2004 at 02:23:50PM -0700, William Lee Irwin III wrote:
>> I wasn't really expecting much to come of it besides prodding people
>> to clean up bloat. The reduced functionality alone likely precludes it
>> from consideration for inclusion. Supposing that there is greater
>> interest, which I don't expect, I can fix these things up and so on.

On Mon, Aug 30, 2004 at 01:25:43AM +0200, Andries Brouwer wrote:
> Well, you sent me something. I have three choices: take it as
> replacement for the current version, ignore it, work on it.
> I have no time to work on it, so am only happy with what you send
> if it can replace the current version.

I'll look around to see how much interest there is, or if others
complain about the issues I'm concerned with, or others find them
sufficiently compelling, and send an update for inclusion of the
form that appears to be preferred if so.


-- wli

Re: [util-linux] readprofile ignores the last element in /proc/profile

[Paulo Marques]

William Lee Irwin III wrote:
> On Wed, Aug 25, 2004 at 12:22:09AM +0900, mita akinobu wrote:
> 
>>The readprofile command does not print the number of clock ticks about
>>the last element in profiling buffer.
>>Since the number of clock ticks which occur on the module functions is
>>as same as the value of the last element of prof_buffer[]. when many
>>ticks occur on there, some users who browsing the output of readprofile
>>may overlook the fact that the bottle-neck may exist in the modules.
>>I create the patch which enable to print clock ticks of the last
>>element as "*unknown*".
> 
> 
> Well, since I couldn't stop vomiting for hours after I looked at the
> code for readprofile(1), here's a reimplementation, with various
> misfeatures removed, included as a MIME attachment.

While you're at it, can readprofile work by reading the symbols from 
/proc/kallsyms?

If it can, this could be added to the list of files that it tries to 
open, so that it could work even if System.map wasn't available.

-- 
Paulo Marques - www.grupopie.com

To err is human, but to really foul things up requires a computer.
Farmers' Almanac, 1978

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

William Lee Irwin III wrote:
>> Well, since I couldn't stop vomiting for hours after I looked at the
>> code for readprofile(1), here's a reimplementation, with various
>> misfeatures removed, included as a MIME attachment.

On Mon, Aug 30, 2004 at 07:27:25PM +0100, Paulo Marques wrote:
> While you're at it, can readprofile work by reading the symbols from 
> /proc/kallsyms?
> If it can, this could be added to the list of files that it tries to 
> open, so that it could work even if System.map wasn't available.

Well, if it can accept input from a pipe, there's no real need. Since
it would need to be sorted, it would probably bloat the utility too
much to do it internally by creating redundancy with sort(1).


-- wli

Re: [util-linux] readprofile ignores the last element in /proc/profile

[mita akinobu]

On Monday 30 August 2004 01:22, William Lee Irwin III wrote:
> Well, since I couldn't stop vomiting for hours after I looked at the
> code for readprofile(1), here's a reimplementation, with various
> misfeatures removed, included as a MIME attachment.

The rewritten readprofile still ignores the last element on my machine.

Boot option:
	profile=2

System.map:
	c0100264 t ignore_int
	c0100298 T _stext
	c0100298 T calibrate_delay
	[...]
	c03acbf1 T __spinlock_text_end
	c03ae0af A _etext
	c03ae0b0 A __start___ex_table

This is quick fix.


--- readprofile.c.orig	2004-08-31 23:01:23.000000000 +0900
+++ readprofile.c	2004-09-01 01:39:00.316750264 +0900
@@ -25,6 +25,7 @@ struct profile_state {
 	int fd, shift;
 	uint32_t *buf;
 	size_t bufsz;
+	size_t bufcnt;
 	struct sym syms[2], *last, *this;
 	unsigned long long stext, vaddr;
 	unsigned long total;
@@ -101,8 +102,8 @@ static int state_transition(struct profi
 			exit(EXIT_FAILURE);
 		}
 	}
-	if (read(state->fd, state->buf, end - start) == end - start) {
-		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
+	if ((state->bufcnt = read(state->fd, state->buf, end - start)) >= 0) {
+		for (off = 0; off < (state->bufcnt)/sizeof(uint32_t); ++off)
 			state->last->hits += state->buf[off];
 	} else {
 		ret = 1;

Re: [util-linux] readprofile ignores the last element in /proc/profile

[mita akinobu]

Perhaps the prof_buffer[] should have prepared another entry for
exceeded PC samplings.

--- 2.6-mm/kernel/profile.c.orig	2004-09-01 01:46:16.000000000 +0900
+++ 2.6-mm/kernel/profile.c	2004-09-01 01:58:02.549930824 +0900
@@ -44,7 +44,7 @@ void __init profile_init(void)
 		return;
  
 	/* only text is profiled */
-	prof_len = (_etext - _stext) >> prof_shift;
+	prof_len = ((_etext - _stext) >> prof_shift) + 1;
 	prof_buffer = alloc_bootmem(prof_len*sizeof(atomic_t));
 }
 

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

On Monday 30 August 2004 01:22, William Lee Irwin III wrote:
>> Well, since I couldn't stop vomiting for hours after I looked at the
>> code for readprofile(1), here's a reimplementation, with various
>> misfeatures removed, included as a MIME attachment.

On Wed, Sep 01, 2004 at 01:45:51AM +0900, mita akinobu wrote:
> The rewritten readprofile still ignores the last element on my machine.
> Boot option:
> 	profile=2
> System.map:
> 	c0100264 t ignore_int
> 	c0100298 T _stext
> 	c0100298 T calibrate_delay
> 	[...]
> 	c03acbf1 T __spinlock_text_end
> 	c03ae0af A _etext
> 	c03ae0b0 A __start___ex_table

It can't find anything outside a symbol in System.map, as it's
iterating over symbols in System.map. Special treatment for the final
profile buffer position is likely in order.


On Wed, Sep 01, 2004 at 01:45:51AM +0900, mita akinobu wrote:
> This is quick fix.
> --- readprofile.c.orig	2004-08-31 23:01:23.000000000 +0900
> +++ readprofile.c	2004-09-01 01:39:00.316750264 +0900
> @@ -25,6 +25,7 @@ struct profile_state {
>  	int fd, shift;
>  	uint32_t *buf;
>  	size_t bufsz;
> +	size_t bufcnt;
>  	struct sym syms[2], *last, *this;
>  	unsigned long long stext, vaddr;
>  	unsigned long total;
> @@ -101,8 +102,8 @@ static int state_transition(struct profi
>  			exit(EXIT_FAILURE);
>  		}
>  	}
> -	if (read(state->fd, state->buf, end - start) == end - start) {
> -		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
> +	if ((state->bufcnt = read(state->fd, state->buf, end - start)) >= 0) {
> +		for (off = 0; off < (state->bufcnt)/sizeof(uint32_t); ++off)
>  			state->last->hits += state->buf[off];
>  	} else {
>  		ret = 1;

So the last read is always short, which is irritating; but bufcnt needs
to be ssize_t or the nonnegativity condition can never fail. Otherwise
it will report bogus results or terminate in a disorderly fashion if
the read() fails outright, e.g. running out of memory or interruption
by signals. So I propose the following alternative patch.


-- wli


--- readprofile.c.orig2	2004-08-31 12:11:54.000000000 -0700
+++ readprofile.c	2004-08-31 12:13:44.000000000 -0700
@@ -65,6 +65,7 @@
 	int ret = 0;
 	long page_mask, start, end;
 	unsigned off;
+	ssize_t bufcnt;
 
 	if (!state->stext) {
 		if (!strcmp(state->sym, "_stext"))
@@ -101,8 +102,8 @@
 			exit(EXIT_FAILURE);
 		}
 	}
-	if (read(state->fd, state->buf, end - start) == end - start) {
-		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
+	if ((bufcnt = read(state->fd, state->buf, end - start)) >= 0) {
+		for (off = 0; off < bufcnt/sizeof(uint32_t); ++off)
 			state->last->hits += state->buf[off];
 	} else {
 		ret = 1;

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

On Tue, Aug 31, 2004 at 12:25:59PM -0700, William Lee Irwin III wrote:
> > -	if (read(state->fd, state->buf, end - start) == end - start) {
> > -		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
> > +	if ((state->bufcnt = read(state->fd, state->buf, end - start)) >= 0) {
> > +		for (off = 0; off < (state->bufcnt)/sizeof(uint32_t); ++off)
> >  			state->last->hits += state->buf[off];

Still wrong =( That needs to be strict inequality.


--- readprofile.c.orig2	2004-08-31 12:11:54.000000000 -0700
+++ readprofile.c	2004-08-31 12:44:25.000000000 -0700
@@ -65,6 +65,7 @@
 	int ret = 0;
 	long page_mask, start, end;
 	unsigned off;
+	ssize_t bufcnt;
 
 	if (!state->stext) {
 		if (!strcmp(state->sym, "_stext"))
@@ -101,8 +102,8 @@
 			exit(EXIT_FAILURE);
 		}
 	}
-	if (read(state->fd, state->buf, end - start) == end - start) {
-		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
+	if ((bufcnt = read(state->fd, state->buf, end - start)) > 0) {
+		for (off = 0; off < bufcnt/sizeof(uint32_t); ++off)
 			state->last->hits += state->buf[off];
 	} else {
 		ret = 1;

Re: [util-linux] readprofile ignores the last element in /proc/profile

[mita akinobu]

On Wednesday 01 September 2004 04:45, William Lee Irwin III wrote:
> Still wrong =( That needs to be strict inequality.
>
>
> --- readprofile.c.orig2	2004-08-31 12:11:54.000000000 -0700
> +++ readprofile.c	2004-08-31 12:44:25.000000000 -0700
> @@ -65,6 +65,7 @@
>  	int ret = 0;
>  	long page_mask, start, end;
>  	unsigned off;
> +	ssize_t bufcnt;
>
>  	if (!state->stext) {
>  		if (!strcmp(state->sym, "_stext"))
> @@ -101,8 +102,8 @@
>  			exit(EXIT_FAILURE);
>  		}
>  	}
> -	if (read(state->fd, state->buf, end - start) == end - start) {
> -		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
> +	if ((bufcnt = read(state->fd, state->buf, end - start)) > 0) {
> +		for (off = 0; off < bufcnt/sizeof(uint32_t); ++off)
>  			state->last->hits += state->buf[off];
>  	} else {
>  		ret = 1;

If you're passing profile=0 on boot, it exits very early.
(when readprofile saw the symbol whose address is same with next line's
symbol address)

and,
On ia64, the following System.map was generated:

[...]
a000000100000000 A _stext
a000000100000000 A _text		(*)
a000000100000000 T ia64_ivt
a000000100000000 t vhpt_miss

Since the symbol "_text" (*) has absolute symbol type, it could not pass the
is_text() check, and readprofile exits immediately.

BTW, if profile=>1 is passed, The range between start and end in
state_transition() is overlapped every call. Is it intentional?

# readprofile -b (after applied below patch)

[...]
__wake_up_common:
          c011f1d8              47		(*)
__wake_up:
          c011f1d8              47		(*)
          c011f1dc               2



--- readprofile.c.orig	2004-09-02 00:04:55.904405440 +0900
+++ readprofile.c	2004-09-02 00:37:37.277231448 +0900
@@ -25,6 +25,7 @@ struct profile_state {
 	int fd, shift;
 	uint32_t *buf;
 	size_t bufsz;
+	ssize_t bufcnt;
 	struct sym syms[2], *last, *this;
 	unsigned long long stext, vaddr;
 	unsigned long total;
@@ -60,6 +61,32 @@ static long profile_off(unsigned long lo
 	return (((vaddr - state->stext) >> state->shift) + 1)*sizeof(uint32_t);
 }
 
+int optBin;
+
+static void display_hits(struct profile_state *state)
+{
+	char *name = state->last->name;
+	unsigned long hits = state->last->hits;
+
+	if (!hits)
+		return;
+	if (!optBin)
+		printf("%*lu %s\n", digits(), hits, name);
+	else {
+		unsigned long long vaddr = state->last->vaddr;
+		int shift = state->shift;
+		unsigned int off;
+		
+		printf("%s:\n", name);
+		for (off = 0; off < state->bufcnt/sizeof(uint32_t); ++off)
+			if (state->buf[off]) {
+				printf("\t%*llx", digits(),
+					((vaddr >> shift) + off) << shift);
+				printf("\t%*lu\n", digits(), state->buf[off]);
+			}
+	}
+}
+
 static int state_transition(struct profile_state *state)
 {
 	int ret = 0;
@@ -101,16 +128,14 @@ static int state_transition(struct profi
 			exit(EXIT_FAILURE);
 		}
 	}
-	if (read(state->fd, state->buf, end - start) == end - start) {
-		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
+	if ((state->bufcnt = read(state->fd, state->buf, end - start)) > 0) {
+		for (off = 0; off < state->bufcnt/sizeof(uint32_t); ++off)
 			state->last->hits += state->buf[off];
 	} else {
 		ret = 1;
 		strcpy(state->last->name, "*unknown*");
 	}
-	if (state->last->hits)
-		printf("%*lu %s\n", digits(), state->last->hits,
-							state->last->name);
+	display_hits(state);
 	state->total += state->last->hits;
 out:
 	return ret;
@@ -169,7 +194,7 @@ int main(int argc, char * const argv[])
 {
 	FILE *system_map = NULL;
 	int c, ret, profile_buffer = -1;
-	static const char optstr[] = "m:p:";
+	static const char optstr[] = "m:p:b";
 
 	while ((c = getopt(argc, argv, optstr)) != EOF) {
 		switch (c) {
@@ -195,6 +220,9 @@ int main(int argc, char * const argv[])
 					exit(EXIT_FAILURE);
 				}
 				break;
+			case 'b':
+				optBin = 1;
+				break;
 			case '?':
 			default:
 				fprintf(stderr, "usage: %s [ -m mapfile ] "

Re: [util-linux] readprofile ignores the last element in /proc/profile

[William Lee Irwin III]

On Thu, Sep 02, 2004 at 01:09:32AM +0900, mita akinobu wrote:
> If you're passing profile=0 on boot, it exits very early.
> (when readprofile saw the symbol whose address is same with next line's
> symbol address)
> and,
> On ia64, the following System.map was generated:
> [...]
> a000000100000000 A _stext
> a000000100000000 A _text		(*)
> a000000100000000 T ia64_ivt
> a000000100000000 t vhpt_miss
> Since the symbol "_text" (*) has absolute symbol type, it could not pass the
> is_text() check, and readprofile exits immediately.

That is bizarre and very irritating, as at first glance it appears to
require strcmp() on every entry until _stext is set.


On Thu, Sep 02, 2004 at 01:09:32AM +0900, mita akinobu wrote:
> BTW, if profile=>1 is passed, The range between start and end in
> state_transition() is overlapped every call. Is it intentional?
> # readprofile -b (after applied below patch)
> [...]
> __wake_up_common:
>           c011f1d8              47		(*)
> __wake_up:
>           c011f1d8              47		(*)
>           c011f1dc               2

Overlapping the symbols was intentional, yes. The way profiling works
is that the shift passed by profile= represents a power-of-two-sized
divisor that the virtual addresses are divided by. These bins don't
respect symbol boundaries and in fact multiple functions may share them.
I choose to account a bin to all symbols whose virtual address range
overlaps it.


> --- readprofile.c.orig	2004-09-02 00:04:55.904405440 +0900
> +++ readprofile.c	2004-09-02 00:37:37.277231448 +0900
> @@ -25,6 +25,7 @@ struct profile_state {
>  	int fd, shift;
>  	uint32_t *buf;
>  	size_t bufsz;
> +	ssize_t bufcnt;
>  	struct sym syms[2], *last, *this;
>  	unsigned long long stext, vaddr;
>  	unsigned long total;
> @@ -60,6 +61,32 @@ static long profile_off(unsigned long lo
>  	return (((vaddr - state->stext) >> state->shift) + 1)*sizeof(uint32_t);
>  }
>  
> +int optBin;

No global variables and no studlycaps...


On Thu, Sep 02, 2004 at 01:09:32AM +0900, mita akinobu wrote:
> +static void display_hits(struct profile_state *state)
> +{
> +	char *name = state->last->name;
> +	unsigned long hits = state->last->hits;
> +
> +	if (!hits)
> +		return;
> +	if (!optBin)
> +		printf("%*lu %s\n", digits(), hits, name);
> +	else {
> +		unsigned long long vaddr = state->last->vaddr;
> +		int shift = state->shift;
> +		unsigned int off;
> +		
> +		printf("%s:\n", name);
> +		for (off = 0; off < state->bufcnt/sizeof(uint32_t); ++off)
> +			if (state->buf[off]) {
> +				printf("\t%*llx", digits(),
> +					((vaddr >> shift) + off) << shift);
> +				printf("\t%*lu\n", digits(), state->buf[off]);
> +			}
> +	}
> +}

Okay, now that you have a use for ->bufcnt in struct state, it may make
sense to keep it around.


On Thu, Sep 02, 2004 at 01:09:32AM +0900, mita akinobu wrote:
>  static int state_transition(struct profile_state *state)
>  {
>  	int ret = 0;
> @@ -101,16 +128,14 @@ static int state_transition(struct profi
>  			exit(EXIT_FAILURE);
>  		}
>  	}
> -	if (read(state->fd, state->buf, end - start) == end - start) {
> -		for (off = 0; off < (end - start)/sizeof(uint32_t); ++off)
> +	if ((state->bufcnt = read(state->fd, state->buf, end - start)) > 0) {
> +		for (off = 0; off < state->bufcnt/sizeof(uint32_t); ++off)
>  			state->last->hits += state->buf[off];
>  	} else {
>  		ret = 1;
>  		strcpy(state->last->name, "*unknown*");
>  	}
> -	if (state->last->hits)
> -		printf("%*lu %s\n", digits(), state->last->hits,
> -							state->last->name);
> +	display_hits(state);
>  	state->total += state->last->hits;
>  out:
>  	return ret;

It may make more sense to pass a display callback instead, particularly
if potential future usage in a library wants to render to streams that
are not stdout or cares to render to things that aren't streams. This
looks like it's against an older version... this seems to qualify as
enough interest to at least use source control.


-- wli