GNOME Bugzilla – Bug 165814
very low (19 times) performance of widgets entry&label in comparison to GTK+-1.2
Last modified: 2013-02-04 02:27:49 UTC
In the GTK+-2.0 (tested versions 2.4 and 2.6) the widgets "entry" and "label" have very low performance (until 19 times) in displaying text in comparison to GTK+-1.2. The test loop consists of 4 calls of the procedure gtk_entry_set_text (4 distinct entry widgets) and 4 calls of the procedure gtk_label_set_text (4 distinct label widgets). The widgets are immediately updated by gtk_widget_draw(w,NULL); while (gtk_main_iteration_do(FALSE)); The results of "entry" and "label" performance tests: ------------------------- GTK|RH->RH|RH->SO|BC->SO| ------------------------- 1.2| 1 ms| 2 ms| 4 ms| 2.4| 3 ms| 38 ms| 24 ms| 2.6| 3 ms| 37 ms| 26 ms| ------------------------- (particular results attached below after the test source) Column "GTK" - version of GTK+ column "RH->RH" - results OS: RedHat 9 linux, CPU: Pentium 4 2.8 GHz, DISPLAY set to localhost:0 Column "RH->SO" - results OS: RedHat 9 linux, CPU: Pentium 4 2.8 GHz, DISPLAY set to remotehost:0 Column "BC->SO" - results OS: BlueCat 5 linux, CPU: some x86, DISPLAY set to remotehost:0 As remote host it's used Solaris 8 on Sun-Blade-100 (sparc). The time is measured in integer milliseconds. The antialiasing was disabled. ---------------------------------------------------------------------- The source of test used to compare the GTK+ performance. ---------------------------------------------------------------------- /* example-start testGTK.c */ #include <gtk/gtk.h> //--------------------------------------- #include <stdio.h> #include <stdlib.h> #include <sys/time.h> static GtkWidget *window = NULL; static GtkWidget *entry1 = NULL; static GtkWidget *entry2 = NULL; static GtkWidget *entry3 = NULL; static GtkWidget *entry4 = NULL; static GtkWidget *label1 = NULL; static GtkWidget *label2 = NULL; static GtkWidget *label3 = NULL; static GtkWidget *label4 = NULL; #define TIME_LIMIT 200 int brun = 0; int srun = 0; long loopMax = 200; // stop after loopMax or never (loopMax < 1) long loopCnt = 0; int timeMax = 0; int timeMin = 32000; int timeLimit = TIME_LIMIT; // ms int timeMean = 0; int timeAgreg = 1; // in graph agregate by [ms] int updateMode = 1; int cntTest = 0; long timesTab[TIME_LIMIT+1]; const int STATISTIC_SUMMARY = 1; const int STATISTIC_GRAPH = 2; const int STATISTIC_ALL = 3; char loopSet[12]= "\n"; // print statisctic and graph void printStatistic(int mask) { char graphH[] = ".TIME[ms]. ...LOOPS.. .%. GRAPH --------------------------------------------\n"; char graphE[] = "----------------------------------------------------------------------------\n"; char graphS[] = "=================================================="; /* print statistic and graph */ if ((mask & STATISTIC_SUMMARY) != 0) { printf(graphE); printf("Statistic loops: %li time min.: %i ms mean: %i ms max.: %i ms\n", loopCnt,timeMin,timeMean,timeMax); printf(graphE); } if (((mask & STATISTIC_GRAPH) != 0) && (loopCnt > 2)) { printf(graphH); int i,j; int agreg = timeAgreg; long agregCnt, agregCntP, lastCnt; lastCnt=(timeMax < timeLimit) ? timeMax : timeLimit-1; i = timeMin; for (; i <= lastCnt;i+=agreg) { agregCnt = timesTab[i]; long sc = agregCnt; /* number of values in interval */ agregCntP=(agregCnt*100)/loopCnt; int sp = (int)agregCntP; /* % from all values */ printf("% 10i % 10li % 3i%% ",i,sc,(int)sp); if (agregCntP/2 > 0) printf("%.*s\n",(int)agregCntP/2,graphS); else if (agregCntP > 0) printf("-\n"); else if (agregCnt > 0) printf(".\n"); else printf("\n"); } /* time values out of range: time < 1 or timeLimit <= time */ if (timesTab[timeLimit] > 0) { agregCntP=(timesTab[timeLimit]*100)/loopCnt; printf("out of lim.% 10li % 3i%% %.*s\n", timesTab[timeLimit],(int)agregCntP,(int)agregCntP/2,graphS); } printf(graphE); } } long currentTimeMillis() { struct timeval tp; gettimeofday (&tp, 0); return (long)(tp.tv_sec%1000*1000 + tp.tv_usec/1000); } void redraw(GtkWidget* w, int immediately) { if (immediately & 1) { gtk_widget_draw(w,NULL); while (gtk_main_iteration_do(FALSE)); } else { gtk_widget_queue_draw(w); } } void run_test() { char * as[8] = { "1", "2U", "3Hu", "4AAA", "5Uhuhuuu","6Oho", "7HoHoHo Hoooooo", "8Ahoj !"}; int i,k; long ttime, ts, te, t1, t2; int brunOld = brun; timeMax = 0; timeMin = 32000; timeMean = 0; loopCnt = 0; for (i=0;i<timeLimit;i++) timesTab[i]=0; printf("\n Update mode %i \n",updateMode); if (brun > 1) printf("Loop : Time [ms] \n"); i = 0; while ((brun > 0) && ((loopMax == 0) || (loopCnt < loopMax))) { i++; for( k = 0; k < 33; k++) { ts = currentTimeMillis(); gtk_entry_set_text((GtkEntry*)entry1,as[k & 7]); redraw(entry1,updateMode); gtk_entry_set_text((GtkEntry*)entry2,as[(k + 1) & 7]); redraw(entry2,updateMode); gtk_entry_set_text((GtkEntry*)entry3,as[(k + 2) & 7]); redraw(entry3,updateMode); gtk_entry_set_text((GtkEntry*)entry4,as[(k + 3) & 7]); redraw(entry4,updateMode); gtk_label_set_text((GtkLabel*)label1,as[(k + 4) & 7]); redraw(label1,updateMode); gtk_label_set_text((GtkLabel*)label2,as[(k + 5) & 7]); redraw(label2,updateMode); gtk_label_set_text((GtkLabel*)label3,as[(k + 6) & 7]); redraw(label3,updateMode); gtk_label_set_text((GtkLabel*)label4,as[(k + 7) & 7]); redraw(label4,updateMode); if ((updateMode & 1) ==0) { // gdk_window_process_updates(window->window,TRUE); while (gtk_main_iteration_do(FALSE)); } te = currentTimeMillis(); ttime = te-ts; /* statistics */ if (ttime > timeMax) timeMax = (int)ttime; if (ttime < timeMin) timeMin = (int)ttime; if (ttime < timeLimit) { timesTab[(int)ttime]++; } else { timesTab[timeLimit]++; } loopCnt++; timeMean+=ttime; if (brun > 1) printf("% 5li : % 4li \n",loopCnt,ttime); if ((brun < 1) || ((loopMax != 0) &&(loopCnt >= loopMax))) break; } } brun = 0; timeMean = (loopCnt > 0 ) ? (int)(timeMean/loopCnt) : 0; if ((loopCnt > 0)) printStatistic(STATISTIC_ALL); cntTest++; } void stop_test(GtkButton *button, gpointer user_data) { brun = 0; } void start_test(GtkButton *button, gpointer user_data) { brun = 1; run_test(); } void startp_test(GtkButton *button, gpointer user_data) { brun = 2; run_test(); } void switch_mode(GtkButton *button, gpointer user_data) { updateMode = (updateMode == 0) ? 1 : 0; printf("Update mode set to %i \n", updateMode); if (updateMode & 1) printf(" update fields immediately \n"); else printf(" queue requests to update fields \n"); } //--------------------------------------- void enter_callback( GtkWidget *widget, GtkWidget *entry ) { gchar *entry_text; int entry_num; entry_text = gtk_entry_get_text(GTK_ENTRY(entry)); entry_num = atoi(entry_text); loopMax=entry_num; printf("Loop set to %i\n", entry_num); } int main( int argc, char *argv[] ) { // GtkWidget *window; GtkWidget *vbox, *hbox; GtkWidget *table; GtkWidget *label; GtkWidget *entry; GtkWidget *button; GtkWidget *check; GtkWidget *separator; gtk_init (&argc, &argv); /* create a new window */ window = gtk_window_new(GTK_WINDOW_TOPLEVEL); gtk_window_set_title(GTK_WINDOW (window), "Test setText"); gtk_signal_connect(GTK_OBJECT (window), "delete_event", (GtkSignalFunc) gtk_exit, NULL); vbox = gtk_vbox_new (FALSE, 0); gtk_container_add (GTK_CONTAINER (window), vbox); gtk_widget_show (vbox); // table with labels and entries // |label |entry | table = gtk_table_new (4, 2, TRUE); gtk_table_set_row_spacings (GTK_TABLE (table), 4); gtk_table_set_col_spacings (GTK_TABLE (table), 4); gtk_box_pack_start ((GtkBox*)vbox, table, FALSE, FALSE, 0); gtk_widget_show (table); label1 = gtk_label_new ("Entry 1"); gtk_table_attach_defaults (GTK_TABLE (table), label1, 0, 1, 0, 1); gtk_widget_show (label1); entry1 = gtk_entry_new (); gtk_entry_set_text((GtkEntry*)entry1,"Data 1"); gtk_table_attach_defaults (GTK_TABLE (table), entry1, 1, 2, 0, 1); gtk_widget_show (entry1); label2 = gtk_label_new ("Entry 2"); gtk_table_attach_defaults (GTK_TABLE (table), label2, 0, 1, 1, 2); gtk_widget_show (label2); entry2 = gtk_entry_new (); gtk_entry_set_text((GtkEntry*)entry2,"Data 2"); gtk_table_attach_defaults (GTK_TABLE (table), entry2, 1, 2, 1, 2); gtk_widget_show (entry2); label3 = gtk_label_new ("Entry 3"); gtk_table_attach_defaults (GTK_TABLE (table), label3, 0, 1, 2, 3); gtk_widget_show (label3); entry3 = gtk_entry_new (); gtk_entry_set_text((GtkEntry*)entry3,"Data 3"); gtk_table_attach_defaults (GTK_TABLE (table), entry3, 1, 2, 2, 3); gtk_widget_show (entry3); label4 = gtk_label_new ("Entry 4"); gtk_table_attach_defaults (GTK_TABLE (table), label4, 0, 1, 3, 4); gtk_widget_show (label4); entry4 = gtk_entry_new (); gtk_entry_set_text((GtkEntry*)entry4,"Data 4"); gtk_table_attach_defaults (GTK_TABLE (table), entry4, 1, 2, 3, 4); gtk_widget_show (entry4); separator = gtk_hseparator_new (); gtk_box_pack_start ((GtkBox*)vbox, separator, FALSE, FALSE, 0); gtk_widget_show (separator); // |Loop: |xxxx | hbox = gtk_hbox_new (FALSE, 0); gtk_container_add (GTK_CONTAINER (vbox), hbox); gtk_widget_show (hbox); label = gtk_label_new ("Loop: "); gtk_box_pack_start (GTK_BOX (hbox), label, TRUE, TRUE, 0); gtk_widget_show (label); entry = gtk_entry_new_with_max_length (6); gtk_signal_connect(GTK_OBJECT(entry), "activate", GTK_SIGNAL_FUNC(enter_callback), entry); gtk_entry_set_text (GTK_ENTRY (entry), "200"); gtk_entry_select_region (GTK_ENTRY (entry), 0, GTK_ENTRY(entry)->text_length); gtk_box_pack_start (GTK_BOX (hbox), entry, TRUE, TRUE, 0); gtk_widget_show (entry); separator = gtk_hseparator_new (); gtk_box_pack_start ((GtkBox*)vbox, separator, FALSE, FALSE, 0); gtk_widget_show (separator); // Buttons |Start Test|Start&Print|Stop |Switch Mode} hbox = gtk_hbox_new (FALSE, 0); gtk_container_add (GTK_CONTAINER (vbox), hbox); gtk_widget_show (hbox); hbox = gtk_hbox_new (FALSE, 8); gtk_box_pack_start ((GtkBox*)vbox, hbox, FALSE, FALSE, 0); gtk_widget_show (hbox); button = gtk_button_new_with_label ("Start Test"); gtk_signal_connect (GTK_OBJECT(button), "clicked", GTK_SIGNAL_FUNC (start_test), NULL); gtk_box_pack_start ((GtkBox*)hbox, button, FALSE, FALSE, 0); gtk_widget_show (button); button = gtk_button_new_with_label ("Start&Print"); gtk_signal_connect (GTK_OBJECT(button), "clicked", GTK_SIGNAL_FUNC (startp_test), NULL); gtk_box_pack_start ((GtkBox*)hbox, button, FALSE, FALSE, 0); gtk_widget_show (button); button = gtk_button_new_with_label ("Stop Test"); gtk_signal_connect (GTK_OBJECT(button), "clicked", GTK_SIGNAL_FUNC (stop_test), NULL); gtk_box_pack_start ((GtkBox*)hbox, button, FALSE, FALSE, 0); gtk_widget_show (button); button = gtk_button_new_with_label ("Switch Mode"); gtk_signal_connect (GTK_OBJECT(button), "clicked", GTK_SIGNAL_FUNC (switch_mode), NULL); gtk_box_pack_start ((GtkBox*)hbox, button, FALSE, FALSE, 0); gtk_widget_show (button); separator = gtk_hseparator_new (); gtk_box_pack_start ((GtkBox*)vbox, separator, FALSE, FALSE, 0); gtk_widget_show (separator); // Button |Close| button = gtk_button_new_with_label ("Close"); gtk_signal_connect_object (GTK_OBJECT (button), "clicked", GTK_SIGNAL_FUNC(gtk_exit), GTK_OBJECT (window)); gtk_box_pack_start (GTK_BOX (vbox), button, TRUE, TRUE, 0); GTK_WIDGET_SET_FLAGS (button, GTK_CAN_DEFAULT); gtk_widget_grab_default (button); gtk_widget_show (button); gtk_widget_show(window); gtk_main(); return(0); } /* example-end */ ============================================================================ GTK+-1.2 (glib 1.2.10, gtk 1.2.10) ============================================================================ RedHat 9 -> RedHat 9 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 0 ms mean: 1 ms max.: 9 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 0 103 51% ========================= 1 75 37% ================== 2 0 0% 3 0 0% 4 4 2% = 5 9 4% == 6 2 1% - 7 2 1% - 8 4 2% = 9 1 0% . ---------------------------------------------------------------------------- RedHat 9 -> Solaris 8 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 0 ms mean: 2 ms max.: 22 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 0 102 51% ========================= 1 74 37% ================== 2 0 0% 3 0 0% 4 0 0% 5 0 0% 6 1 0% . 7 0 0% 8 0 0% 9 2 1% - 10 0 0% 11 2 1% - 12 0 0% 13 0 0% 14 7 3% = 15 5 2% = 16 3 1% - 17 0 0% 18 0 0% 19 0 0% 20 1 0% . 21 1 0% . 22 2 1% - ---------------------------------------------------------------------------- ============================================================================ GTK+-2.4 (glib 2.4.6, gtk 2.4.9, atk 1.6.1, pango 1.4.0) ============================================================================ RedHat 9 -> RedHat 9 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 1 ms mean: 3 ms max.: 9 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 1 1 0% . 2 66 33% ================ 3 77 38% =================== 4 6 3% = 5 5 2% = 6 20 10% ===== 7 22 11% ===== 8 2 1% - 9 1 0% . ---------------------------------------------------------------------------- RedHat 9 -> Solaris 8 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 26 ms mean: 38 ms max.: 48 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 26 2 1% - 27 3 1% - 28 0 0% 29 1 0% . 30 0 0% 31 0 0% 32 0 0% 33 0 0% 34 0 0% 35 0 0% 36 0 0% 37 19 9% ==== 38 73 36% ================== 39 78 39% =================== 40 12 6% === 41 6 3% = 42 1 0% . 43 2 1% - 44 1 0% . 45 0 0% 46 0 0% 47 0 0% 48 2 1% - ---------------------------------------------------------------------------- BlueCat 5 -> Solaris 8 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 16 ms mean: 24 ms max.: 34 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 16 1 0% . 17 4 2% = 18 0 0% 19 0 0% 20 0 0% 21 0 0% 22 1 0% . 23 27 13% ====== 24 104 52% ========================== 25 11 5% == 26 6 3% = 27 17 8% ==== 28 6 3% = 29 12 6% === 30 8 4% == 31 1 0% . 32 1 0% . 33 0 0% 34 1 0% . ---------------------------------------------------------------------------- ============================================================================ GTK+-2.6 (glib 2.6.1, gtk 2.6.1, atk 1.6.1, pango 1.8.0) ============================================================================ RedHat 9 -> RedHat 9 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 2 ms mean: 3 ms max.: 7 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 2 39 19% ========= 3 78 39% =================== 4 23 11% ===== 5 22 11% ===== 6 13 6% === 7 25 12% ====== ---------------------------------------------------------------------------- RedHat 9 -> Solaris 8 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 26 ms mean: 37 ms max.: 47 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 26 6 3% = 27 0 0% 28 0 0% 29 0 0% 30 0 0% 31 0 0% 32 0 0% 33 0 0% 34 0 0% 35 0 0% 36 29 14% ======= 37 93 46% ======================= 38 58 29% ============== 39 8 4% == 40 3 1% - 41 1 0% . 42 0 0% 43 0 0% 44 1 0% . 45 0 0% 46 0 0% 47 1 0% . ---------------------------------------------------------------------------- BlueCat 5 -> Solaris 8 Update mode 1 ---------------------------------------------------------------------------- Statistic loops: 200 time min.: 18 ms mean: 26 ms max.: 31 ms ---------------------------------------------------------------------------- .TIME[ms]. ...LOOPS.. .%.0 GRAPH -------------------------------------------- 18 5 2% = 19 0 0% 20 0 0% 21 0 0% 22 1 0% . 23 0 0% 24 7 3% = 25 103 51% ========================= 26 35 17% ======== 27 1 0% . 28 12 6% === 29 15 7% === 30 11 5% == 31 10 5% == ----------------------------------------------------------------------------
The fact that things are slower in 2.x is not surprising, since GTK+-2.x/Pango have *much* i18n and text layout support than 1.2. The discrepancy in the remote timings might be worth looking at. Are we doing extra roundtrips here ? What are those ? xscope would be the right tool to get an idea about this.
Presumably the remote slowness is just the roundtrips for compositing AA text on a server without RENDER.
I tryed the combination "GTK+-2.4 & BC->RH" (on RH the RENDER is present) but the results are about 23 ms. That is only by 1 ms better than "GTK+-2.4 & BC->SO" (without RENDER).
I'd suggest you try getting some profile data to pinpoint exactly where the cycles are being spent. It's impossible to say where the problem is with this little data to work with. could you follow Matthias' suggestion and use xscope to collect data for possible problems with roundtrips?
The tests outputs and the xscope outputs (print-levels 1 & 4) for BlueCat->Solaris, BlueCat->RedHat, RedHat->RedHat, RedHat->Solaris are in http://www.apogee.cz/performance/gtk12x24perf.zip (1.7MB)
#157805 is a similar report, covering only GtkLabel (changing text, as seems to be here too) performance. Adding as a dependency. Not sure if that's the right thing to do.