Unaccounted time during containers' lifecycle

["Matt Hoosier" <matt hoosier gmail com>]

Hi,

I have some use-cases where I'd like to use a window containing grids
of composite widgets. The amount of time which elapsed between the
moment the widgets are all constructed, and when the window containing
them is first exposed, seems to be disproportionately long compared to
the raw amount of painting work to be done by those widgets
themselves.

That probably sounds a little vague; let me offer a concrete example
[not attached]. If I want to display a 9x4 set of buttons, I can
either (a) use individual GtkButtons inserted into a GtkTable, or (b)
derive a custom widget type which manually overrides its expose
handler to make gtk_paint_box() calls to simulate the appearance of
those 36 buttons.

The first approach using nested widgets takes about 1100 seconds from
beginning of construction to the end of the first expose. I did a
second implementation that just draws everything as one huge widget
(the second approach) and it takes about 300 ms.

My first thought was that size negotiation for all the individual
widgets could be taking most of the additional time. So I implemented
a custom version of GtkTable which never consults its children when
determining its requisition; it just requests the amount of space
which I already know will be needed by the whole grid.

This made almost no difference. I suppose that's because the
GtkLabel's contained within the individual GtkButton's must eventually
calculate the on-screen size of their encapsulated PangoLayout anyway,
so one doesn't really save much by avoiding the
gtk_widget_size_request() calls on them.

So, I wrote a little test program which just builds a GtkWindow
containing a 5x5 GtkTable in which each element is a composite widget
looking like this:

 GtkVBox
   GtkHBox
     GtkButton
     GtkAlignment
   GtkHBox
     GtkLabel
     GtkCheckButton

(Why the more complex structure instead of simple buttons? It's a
little more close the actual application that motivated my inquiry to
begin with.)

I attached some callbacks with timer outputs to each of the following
signals on the top-level window:

* expose
* map
* realize
* size-request
* size-allocate

The program just endlessly builds instances of these windows, waits
until they're exposed, and then destroys them. Here's one trace which
shows a typical set of results (there's little variance from one cycle
to the next, so I'm not including a huge dataset).

[Cycle 7]: construction finished at 0.1030 sec
[Cycle 7]: requisition computed at 0.2150 sec
[Cycle 7]: size allocated at 0.2287 sec
[Cycle 7]: realized at 0.2315 sec
[Cycle 7]: mapped at 0.2605 sec
[Cycle 7]: requisition computed at 0.4137 sec
[Cycle 7]: size allocated at 0.4409 sec
[Cycle 7]: exposed at 0.4436 sec

( If the timings look a little slow, that's because I'm working on an
ARM system. )

So, a couple of questions seem to follow from that:

* Why is the size negotiation done twice before that window appears
on-screen? I'm attaching the program used to generate the timings
below, and I don't see any setter calls made on a widget after the
window is shown, that would cause it to do a queue_resize().

* Am I wrong in my earlier speculation that the size-request phase is
not really very expensive? I wouldn't mind at all being contradicted
about that.

* Does something else other than size requisitions happen between the
time that gtk_window_show() is called on a toplevel container, and the
time that its "size-request" signal fires?

In general, I'm wondering why containers seem so much slower than
writing a messy monster widget that manually draws everything. The
actual time expended painting the whole window looks like about 3
milliseconds, which is insignificant compared to the overall time
required for setup. I've run sysprof on an x86 build of the program
used to generate the timings, and no particular function stands out as
a hotspot.

#include <glib.h>
#include <gtk/gtkvbox.h>
#include <gtk/gtkhbox.h>
#include <gtk/gtkalignment.h>
#include <gtk/gtkbutton.h>
#include <gtk/gtkcheckbutton.h>
#include <gtk/gtklabel.h>
#include <gtk/gtkmain.h>
#include <gtk/gtktable.h>
#include <gtk/gtkwindow.h>
#include <stdio.h>

#define ROWS    5
#define COLUMNS 5

static GTimer* timer = NULL;
static int kill_window_idle_handle = -1;
static int cycle_number = 0;

static void     window_realize_cb       (GtkWidget *, gpointer);
static void     window_size_allocate_cb (GtkWidget *, GtkAllocation*, gpointer);
static void     window_size_request_cb  (GtkWidget *, GtkRequisition*, gpointer);
static void     window_map_cb           (GtkWidget *, gpointer);
static gboolean window_expose_cb        (GtkWindow *, GdkEventExpose * e);

static GtkWidget *
create_table_item (guint index)
{
    GtkWidget * item = NULL;

    item = gtk_vbox_new (FALSE, 0);

    GtkWidget * top = gtk_hbox_new (FALSE, 0);
    GtkWidget * bottom = gtk_hbox_new (FALSE, 0);

    gtk_container_add (GTK_CONTAINER (item), top);
    gtk_container_add (GTK_CONTAINER (item), bottom);

    gtk_container_add (GTK_CONTAINER (top),
                       gtk_button_new ());
    gtk_container_add (GTK_CONTAINER (top),
                       gtk_alignment_new (0.5, 0.5, 0.0, 0.0));
    gtk_container_add (GTK_CONTAINER (bottom),
                       gtk_label_new (""));
    gtk_container_add (GTK_CONTAINER (bottom),
                       gtk_check_button_new ());

    return item;
}

static GtkWidget *
create_window ()
{
    guint i, j;
    GtkWidget * window;
    GtkWidget* table;
    GtkWidget* item;

    if (!timer)
        timer = g_timer_new ();

    window = gtk_window_new (GTK_WINDOW_TOPLEVEL);
    table = gtk_table_new (ROWS, COLUMNS, FALSE);

    for (i = 0; i < ROWS; i++)
    {
        for (j = 0; j < COLUMNS; j++)
        {
            item = create_table_item (i * COLUMNS + j);
            gtk_table_attach_defaults (GTK_TABLE (table),
                                       item,
                                       j,
                                       j + 1,
                                       i,
                                       i + 1);

        }
    }

    gtk_container_add (GTK_CONTAINER (window), table);
    
    g_signal_connect (G_OBJECT (window), "realize",
                      G_CALLBACK (window_realize_cb), NULL);
    g_signal_connect (G_OBJECT (window), "map",
                      G_CALLBACK (window_map_cb), NULL);
    g_signal_connect (G_OBJECT (window), "size-request",
                      G_CALLBACK (window_size_request_cb), NULL);
    g_signal_connect (G_OBJECT (window), "size-allocate",
                      G_CALLBACK (window_size_allocate_cb), NULL);
    g_signal_connect (G_OBJECT (window), "expose-event",
                      G_CALLBACK (window_expose_cb), NULL);
    
    cycle_number++;

    if (timer)
    {
        printf ("[Cycle %d]: construction finished at %3.4f sec\n",
                cycle_number,
                (float) g_timer_elapsed (timer, NULL));
    }

    return window;
}

static gboolean
kill_window (GtkWindow * win)
{
    GtkWidget * new_window;
    new_window = create_window ();
    gtk_widget_show_all (new_window);

    gtk_widget_destroy (GTK_WIDGET (win));

    kill_window_idle_handle = -1;
    return FALSE;
}

static void
window_realize_cb (GtkWidget *w, gpointer unused)
{
    if (timer)
    {
        printf ("[Cycle %d]: realized at %3.4f sec\n",
                cycle_number,
                (float) g_timer_elapsed (timer, NULL));
    }
}

static void
window_map_cb (GtkWidget *w, gpointer unused)
{
    if (timer)
    {
        printf ("[Cycle %d]: mapped at %3.4f sec\n",
                cycle_number,
                (float) g_timer_elapsed (timer, NULL));
    }
}

static void
window_size_allocate_cb (GtkWidget *w, GtkAllocation* unused1, gpointer unused2)
{
    if (timer)
    {
        printf ("[Cycle %d]: size allocated at %3.4f sec\n",
                cycle_number,
                (float) g_timer_elapsed (timer, NULL));
    }
}

static void
window_size_request_cb (GtkWidget *w, GtkRequisition* unused1, gpointer unused2)
{
    if (timer)
    {
        printf ("[Cycle %d]: requisition computed at %3.4f sec\n",
                cycle_number,
                (float) g_timer_elapsed (timer, NULL));
    }
}

static gboolean
window_expose_cb (GtkWindow *win, GdkEventExpose * e)
{
    if (kill_window_idle_handle == -1)
    {
      kill_window_idle_handle = g_idle_add ((GSourceFunc) (kill_window), (gpointer) win);
    }

    if (timer)
    {
        printf ("[Cycle %d]: exposed at %3.4f sec\n",
                cycle_number,
                (float) g_timer_elapsed (timer, NULL));
        g_timer_destroy (timer);
        timer = NULL;
    }

    return FALSE;
}

int
main (int argc, char * argv[])
{
    GtkWidget* window;
    double time_initialization;
    double time_construction;


    gtk_init(&argc, &argv);

    timer = g_timer_new ();
    window = create_window ();

    gtk_widget_show_all (window);
    gtk_main ();

    return 0;
}