Re: X much slower in 2.0.24 than in 1.2.13

Linus Torvalds (torvalds@cs.helsinki.fi)
Sat, 2 Nov 1996 19:58:08 +0200 (EET)

On Sat, 2 Nov 1996, Chris Evans wrote:
>
> I can confirm that something 2.0.23->2.0.24 kills x performance...
>
> Not the world's most scientific test, but with
>
> time x11perf -all -time 1 -reps 1
>
> 2.0.23: 2.37 user, 2.14 system
> 2.0.24: 3.73 user, 8.85 system
> ^^^^^^^^^^^
> Someone else commented on unreasonably long time spent in "system" rather
> than "user".

Ok, anybody want to profile their kernel? It's really pretty simple:

- boot the kernel with the "profile=2" kernel command line (you can use
a line like
append = "profile=2"
in your lilo.conf if you use LILO).

- make sure you have the System.map file that corresponds to your kernel
in your root directory (this should be done automatically for you if you
use "make zlilo" to create the kernel)

- do a "echo > /proc/profile" as root before starting x11perf to clear
out any old profiling information

- run x11perf and afterwards parse the profile information with the supplied
program. The output is very easy to decipher..

I'd be interested to hear what the results are, and the anomaly _should_
show up pretty clearly.

Linus

---
/*
 * Original by Ramon Garcia Fernandez <ramon@juguete.quim.ucm.es>
 * Hacked by linus
 */
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
#include <sys/fcntl.h>
#include <linux/autoconf.h>


#define prof_func "do_no_page"


#define BUFSIZE 1024


#ifndef CONFIG_PROFILE_SHIFT
#define CONFIG_PROFILE_SHIFT 2
#endif


struct entry {
	struct entry * next;
	unsigned long time;
	unsigned long address;
	char name[1];
};


struct entry * list = NULL;


void do_symbol(int time, unsigned long address, char * name)
{
	struct entry * entry = malloc(sizeof(struct entry) + strlen(name));
	struct entry ** tmp;


	entry->time = time;
	entry->address = address;
	strcpy(entry->name, name + (*name == '_'));
	tmp = &list;
	while (*tmp) {
		if ((*tmp)->time > entry->time)
			break;
		tmp = &(*tmp)->next;
	}
	entry->next = *tmp;
	*tmp = entry;
}


void show_symbols(unsigned long total)
{
	struct entry * entry = list;


	while (entry) {
		printf("%10u %5d.%02d%% %08x %s\n" ,
			entry->time,
			(entry->time*10000/total) / 100,
			(entry->time*10000/total) % 100,
			entry->address, entry->name);
		entry = entry->next;
	}
}


/* If you do not speak Spanish:
 * valor_simbolo_actual: current_symbol_value
 * valor_simbolo_siguiente: next_symbol_value
 * simbolo_actual: current_symbol
 * next_symbol: next_symbol
 * leidos: read (past participle)
 * total: total
*/


int main(int argc, char ** argv)
{
	int fp;
	char * func = prof_func;
	FILE *kmap;
	int current_symbol_value , next_symbol_value;
	char current_symbol[80] , next_symbol[80];
	int has_read , total = 0, j;


	if (argc == 2)
		func = argv[1];


	fp = open("/proc/profile", O_RDONLY);
	if (fp < 0) {
		perror("/proc/profile");
		exit(1);
	}
	kmap = fopen("/System.map","r");
	if (!kmap) {
		kmap = fopen("/usr/src/linux/System.map","r");
		if (!kmap) {
			perror("System.map");
			exit(1);
		}
	}
	fscanf(kmap , "%x %*s %s\n" , &current_symbol_value , current_symbol );
	fscanf(kmap , "%x %*s %s\n" , &next_symbol_value , next_symbol );
	puts(func);


	for (;;) {
		unsigned int buffer[(next_symbol_value - current_symbol_value) >> CONFIG_PROFILE_SHIFT];
		unsigned int tiempo = 0;


		if (next_symbol_value == current_symbol_value) {
			strcpy(current_symbol, next_symbol);
			fscanf(kmap, "%x %*s %s\n", &next_symbol_value, next_symbol);
			continue;
		}
		lseek (fp , sizeof(unsigned int)+current_symbol_value-0xc0100000 , SEEK_SET);
		has_read = read (fp , buffer , sizeof(buffer) );
		for ( j = 0 ; j < has_read/sizeof(unsigned int) ; j++) {
			if (!strcmp(func, current_symbol))
				printf("%08x %d\n", j*4+current_symbol_value, buffer[j]);
			tiempo += buffer[j];
		}
		if (tiempo != 0) {
			do_symbol(tiempo, current_symbol_value, current_symbol);
			total += tiempo;
		}
		if (has_read < (next_symbol_value -current_symbol_value)
				>> CONFIG_PROFILE_SHIFT * sizeof(unsigned long) || 
			next_symbol_value == current_symbol_value )
			break;
		strcpy ( current_symbol , next_symbol );
		current_symbol_value = next_symbol_value;
		fscanf(kmap , "%x %*s %s\n" , &next_symbol_value , next_symbol );
	}
	do_symbol(total, 0, "total");
	show_symbols(total);
	return(0);
}