Re: Some performance notes

[Soeren Sandmann <sandmann daimi au dk>]

Owen Taylor <otaylor redhat com> writes:

> > Note that this is pretty bad. Eating 100% cpu of 400MHz celeron for GUI
> > is not too good. You should eat 10%... [win95 was usable on 386/40, 4MB]
> 
> Errr, we aren't talking about just sitting there. We are talking
> about opaque resizing. Slower machine == 100% cpu at lower framerate.
> 
> And if you have a slow machine, then you shouldn't be using opaque
> resizing.

On my machine (pentium II, 200MHz, 128 MB RAM, Matrox Millennium 4MB,
1600x1200x16), opaque resizing is usable with Windows 2000, with QT
and with GTK 1.2.  Only with GTK 2.0 is there a noticable delay before
the resize takes effect (but it is still usable).  Turning off double
buffering doesn't help.

I have been instrumenting GTK with the attached files, and it shows
delays of up to a second from the first configure is received until
gtk_container_idle_sizer() calls gdk_flush().  This is with testgtk'
toplevel.

I can't believe it isn't possible to reduce that time.

#ifndef __GPROFILER_H__
#define __GPROFILER_H__

#include <glib.h>
#include <stdio.h>

#ifdef G_ENABLE_PROFILER

typedef struct _GProfilerDataPoint GProfilerDataPoint;

struct _GProfilerDataPoint {
    enum {
	G_PROFILER_DATA_POINT,
	G_PROFILER_DATA_BEGIN,
	G_PROFILER_DATA_END
    } kind;
    guint line_number;
    const gchar *file_name;
    const gchar *text;
    gdouble time_stamp;
};

extern GProfilerDataPoint *g_profiler_data;
extern gsize g_profiler_alloc;
extern gsize g_profiler_used;
extern GTimer *g_profiler_timer;

void g_profiler_dump_data (FILE *f);

#define G_PROFILER_RESET()						\
{									\
    g_timer_reset (g_profiler_timer);					\
}

#define G_PROFILER_CHECK_MEM() G_STMT_START				\
{									\
    if (!g_profiler_data)						\
    {									\
	g_profiler_data = g_new (GProfilerDataPoint, 8192);		\
	g_profiler_alloc = 8192;					\
	g_profiler_timer = g_timer_new ();				\
	g_timer_reset (g_profiler_timer);				\
    }									\
									\
    if (g_profiler_used == g_profiler_alloc)				\
    {									\
	g_profiler_alloc *= 2;						\
	g_profiler_data =						\
	    g_renew (GProfilerDataPoint,				\
		     g_profiler_data,					\
		     g_profiler_alloc);					\
        g_profiler_data[g_profiler_used].kind = G_PROFILER_DATA_POINT;	\
        g_profiler_data[g_profiler_used].line_number = __LINE__;	\
        g_profiler_data[g_profiler_used].file_name = __FILE__;		\
        g_profiler_data[g_profiler_used].text =				\
	    "resizing profiler array";					\
        g_profiler_data[g_profiler_used].time_stamp =			\
	    g_timer_elapsed (g_profiler_timer, NULL);			\
        ++g_profiler_used;						\
    }									\
} G_STMT_END

#define G_PROFILER_POINT(s) G_STMT_START {				\
    G_PROFILER_CHECK_MEM();						\
    g_profiler_data[g_profiler_used].kind = G_PROFILER_DATA_POINT;	\
    g_profiler_data[g_profiler_used].line_number = __LINE__;		\
    g_profiler_data[g_profiler_used].file_name = __FILE__;		\
    g_profiler_data[g_profiler_used].text = s;				\
    g_profiler_data[g_profiler_used].time_stamp =			\
	g_timer_elapsed (g_profiler_timer, NULL);			\
    ++g_profiler_used;							\
} G_STMT_END

#define G_PROFILER_BEGIN(s) G_STMT_START				\
{									\
    G_PROFILER_CHECK_MEM();						\
    g_profiler_data[g_profiler_used].kind = G_PROFILER_DATA_BEGIN;	\
    g_profiler_data[g_profiler_used].line_number = __LINE__;		\
    g_profiler_data[g_profiler_used].file_name = __FILE__;		\
    g_profiler_data[g_profiler_used].text = s;				\
    g_profiler_data[g_profiler_used].time_stamp =			\
	g_timer_elapsed (g_profiler_timer, NULL);			\
    ++g_profiler_used;							\
} G_STMT_END
    
#define G_PROFILER_END() G_STMT_START					\
{									\
    G_PROFILER_CHECK_MEM();						\
    g_profiler_data[g_profiler_used].kind =  G_PROFILER_DATA_END;	\
    g_profiler_data[g_profiler_used].line_number = __LINE__;		\
    g_profiler_data[g_profiler_used].file_name = __FILE__;		\
    g_profiler_data[g_profiler_used].text = NULL;			\
    g_profiler_data[g_profiler_used].time_stamp =			\
	g_timer_elapsed (g_profiler_timer, NULL);			\
    ++g_profiler_used;							\
} G_STMT_END



#else /* !G_ENABLE_PROFILER */

#define G_PROFILER_BEGIN(string)
#define G_PROFILER_END()

#endif /* G_ENABLE_PROFILER */

#endif /* __GPROFILER_H__ */

#define G_ENABLE_PROFILER
#include "gprofiler.h"

GProfilerDataPoint *g_profiler_data	= NULL;
gsize g_profiler_alloc			= 0;
gsize g_profiler_used			= 0;
GTimer *g_profiler_timer		= 0;


void
g_profiler_dump_data (FILE *f)
{
    gint i;
    gint indent = 0;
    GQueue *stack = g_queue_new ();

    fprintf (f, "stamp     cumulative,    file:line        text\n");
    for (i = 0; i < g_profiler_used; i++)
    {
	int j;
	gchar scratch[128];
	gchar scratch2[128];
	GProfilerDataPoint *prev;

	gdouble difference;

	if (i == 0)
	    difference = 0;
	else
	    difference = g_profiler_data[i].time_stamp -
		g_profiler_data[i-1].time_stamp;

	fprintf (f, "%11.5f %11.5f  ",
		 g_profiler_data[i].time_stamp,
		 difference);
		 
	if (g_profiler_data[i].kind == G_PROFILER_DATA_END)
	    indent--;

	for (j = 0; j < indent; j++)
	    fprintf (f, "   ");

	switch (g_profiler_data[i].kind)
	{
	case G_PROFILER_DATA_BEGIN:
	    snprintf (scratch, 128, "%s", g_profiler_data[i].text);
	    indent++;
	    g_queue_push_tail (stack, &g_profiler_data[i]);
	    break;
	case G_PROFILER_DATA_END:
	    prev = g_queue_pop_tail (stack);
	    snprintf (scratch, 128, "done (elapsed %.5f)",
		      g_profiler_data[i].time_stamp -
		      prev->time_stamp);
	    break;
	case G_PROFILER_DATA_POINT:
	    snprintf (scratch, 128, "%s", g_profiler_data[i].text);
	    break;
	default:
	    g_assert_not_reached ();
	}
	fprintf (f, "%-50s  %s:%d\n",
		 scratch,
		 g_profiler_data[i].file_name,
		 g_profiler_data[i].line_number);
    }
}