Hi, I just noticed that utilities.html (from ImageMagick manual), takes near three times more time to render with CVS than with 0.7.3. That page is 230KB and has no images. It takes 3 seconds to render with 0.7.3 vs 9 seconds of CVS (on a slow machine). The same is true for the new and old parser. Can somebody please profile it to find the overhead source? (./configure --enable-gprof). TIA Jorge.-
Hi, I just profiled cvs- and 0.7.3 version. I used http://www.w3.org/TR/xslt20/ stored locally on disk (utilities.html rendered too fast here). I could not yet get any reproducible results from profiling, but cvs is obviously slower 5.1 vs. 3.9 seconds. And with cvs the GUI freezes until the whole page is loaded, whereas 0.7.3 displays the GUI while it is rendering the page (you can see the "Kb" counting in the upper right corner). Regards, Johannes Hofmann On Wed, Dec 03, 2003 at 01:09:26PM -0300, Jorge Arellano Cid wrote:
Hi,
I just noticed that utilities.html (from ImageMagick manual), takes near three times more time to render with CVS than with 0.7.3.
That page is 230KB and has no images. It takes 3 seconds to render with 0.7.3 vs 9 seconds of CVS (on a slow machine).
The same is true for the new and old parser.
Can somebody please profile it to find the overhead source? (./configure --enable-gprof).
TIA Jorge.-
_______________________________________________ Dillo-dev mailing list Dillo-dev@lists.auriga.wearlab.de http://lists.auriga.wearlab.de/cgi-bin/mailman/listinfo/dillo-dev
Hi Johannes,
I just profiled cvs- and 0.7.3 version. I used http://www.w3.org/TR/xslt20/ stored locally on disk (utilities.html rendered too fast here). I could not yet get any reproducible results from profiling,
!? Doesn't it show any function usage-ratio/run-time change?
but cvs is obviously slower 5.1 vs. 3.9 seconds. And with cvs the GUI freezes until the whole page is loaded, whereas 0.7.3 displays the GUI while it is rendering the page (you can see the "Kb" counting in the upper right corner).
Yes, probably because rendering is done when idle. Thanks Jorge.-
Hi Jorge, On Thu, Dec 04, 2003 at 10:43:34AM -0300, Jorge Arellano Cid wrote:
I could not yet get any reproducible results from profiling,
!?
Doesn't it show any function usage-ratio/run-time change?
Ok, I redid the profiling on my slower Linux box with utilities.html. Html_cleanup_tag is called more often in cvs version (16742 vs. 10749) and seems quite a bit slower than in 0.7.3. See gprof output below. Hope that helps, Johannes PS: Of course I can send you the whole gprof output, but it is quite large, so I did not want to send the whole thing to the list. ================================= current cvs ============================: Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls us/call us/call name 12.24 0.24 0.24 27862 8.61 8.61 Html_get_attr2 11.73 0.47 0.23 58152 3.96 6.88 Dw_page_real_word_wrap 8.67 0.64 0.17 16742 10.15 12.71 Html_cleanup_tag 5.61 0.75 0.11 61 1803.28 6299.81 Html_write_raw 4.59 0.84 0.09 354712 0.25 0.25 a_Dw_widget_get_type 4.59 0.93 0.09 14073 6.40 13.90 p_Dw_widget_queue_resize 3.06 0.99 0.06 15306 3.92 3.92 Dw_page_add_line 3.06 1.05 0.06 2207 27.19 27.52 Dw_page_get_extremes 2.55 1.10 0.05 15980 3.13 6.77 Html_process_space 2.55 1.15 0.05 5993 8.34 8.34 Html_push_tag 2.04 1.19 0.04 121087 0.33 0.33 a_Dw_page_get_type 1.53 1.22 0.03 77221 0.39 0.40 Dw_page_get_word_extremes 1.53 1.25 0.03 58845 0.51 0.80 Dw_page_mark_change 1.53 1.28 0.03 23886 1.26 1.26 a_Dw_gtk_viewport_get_type 1.53 1.31 0.03 13499 2.22 12.24 Html_process_word 1.53 1.34 0.03 6883 4.36 4.36 a_Dw_style_new 1.53 1.37 0.03 1887 15.90 129.82 Html_tag_open_table_cell 1.53 1.40 0.03 1887 15.90 39.66 a_Dw_table_add_cell 1.53 1.43 0.03 Dw_page_destroy 1.53 1.46 0.03 Dw_table_size_request 1.02 1.48 0.02 58440 0.34 0.34 Html_tag_compare 1.02 1.50 0.02 19938 1.00 1.00 Dw_page_add_word 1.02 1.52 0.02 16527 1.21 9.69 a_Dw_page_add_text 1.02 1.54 0.02 15155 1.32 1.32 a_Dw_page_add_space 1.02 1.56 0.02 13003 1.54 61.50 Html_process_tag 1.02 1.58 0.02 13003 1.54 3.08 Html_tag_index 1.02 1.60 0.02 8499 2.35 2.77 a_Dw_widget_size_request 1.02 1.62 0.02 6883 2.91 2.91 Dw_style_remove 1.02 1.64 0.02 6151 3.25 3.58 Dw_page_forall 1.02 1.66 0.02 3380 5.92 88.16 Dw_page_rewrap 1.02 1.68 0.02 2729 7.33 17.85 Dw_container_destroy 1.02 1.70 0.02 858 23.31 108.94 Html_tag_open_tr 0.51 1.71 0.01 28657 0.35 0.35 a_Dw_container_get_type 0.51 1.72 0.01 16527 0.61 0.61 Dw_page_calc_text_size 0.51 1.73 0.01 16383 0.61 0.61 a_Dw_table_get_type 0.51 1.74 0.01 8016 1.25 1.25 a_Url_str 0.51 1.75 0.01 6159 1.62 1.62 a_Dw_widget_set_ascent 0.51 1.76 0.01 5993 1.67 6.50 Html_eventually_pop_dw 0.51 1.77 0.01 5993 1.67 14.38 Html_tag_cond_cleanup <snip> ----------------------------------------------- 0.00 0.00 69/16742 Html_tag_open_dt [77] 0.00 0.00 426/16742 Html_par_push_tag [88] 0.00 0.00 480/16742 Html_tag_open_dd [68] 0.01 0.00 681/16742 Html_tag_open_table [23] 0.03 0.01 3432/16742 Html_tag_open_tr [19] 0.06 0.01 5661/16742 Html_tag_open_td [7] 0.06 0.02 5993/16742 Html_tag_cond_cleanup [22] [12] 10.9 0.17 0.04 16742 Html_cleanup_tag [12] 0.01 0.03 5993/5993 Html_eventually_pop_dw [37] 0.00 0.00 1314/6883 Dw_style_remove [63] 0.00 0.00 16742/16742 Html_match_tag [227] ----------------------------------------------- ========================== 0.7.3 ===========================: Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls us/call us/call name 13.71 0.27 0.27 58152 4.64 7.26 Dw_page_real_word_wrap 10.66 0.48 0.21 24525 8.56 8.56 Html_get_attr2 6.60 0.61 0.13 333652 0.39 0.39 a_Dw_widget_get_type 4.57 0.70 0.09 116585 0.77 0.77 a_Dw_page_get_type 3.55 0.77 0.07 19938 3.51 3.51 Dw_page_add_word 3.55 0.84 0.07 61 1147.54 6345.30 Html_write_raw 2.54 0.89 0.05 Dw_page_destroy 2.54 0.94 0.05 Dw_page_size_allocate 2.03 0.98 0.04 58440 0.68 0.68 Html_tag_compare 2.03 1.02 0.04 15304 2.61 2.61 Dw_page_add_line 2.03 1.06 0.04 10749 3.72 4.44 Html_cleanup_tag 2.03 1.10 0.04 5993 6.67 6.67 Html_push_tag 2.03 1.14 0.04 Dw_table_size_request 1.52 1.17 0.03 77221 0.39 0.41 Dw_page_get_word_extremes 1.52 1.20 0.03 51991 0.58 1.26 Dw_page_mark_change 1.52 1.23 0.03 16527 1.82 12.58 a_Dw_page_add_text 1.52 1.26 0.03 15980 1.88 6.64 Html_process_space 1.52 1.29 0.03 13499 2.22 15.57 Html_process_word 1.52 1.32 0.03 12896 2.33 12.23 p_Dw_widget_queue_resize 1.52 1.35 0.03 8499 3.53 4.17 a_Dw_widget_size_request 1.52 1.38 0.03 6883 4.36 4.36 a_Dw_style_new 1.52 1.41 0.03 3238 9.26 17.79 Dw_page_calc_widget_size 1.52 1.44 0.03 2207 13.59 14.37 Dw_page_get_extremes 1.52 1.47 0.03 1362 22.03 29.75 Dw_table_sub_calc_col_widt 1.02 1.49 0.02 28654 0.70 0.70 a_Dw_container_get_type 1.02 1.51 0.02 15155 1.32 1.32 a_Dw_page_add_space 1.02 1.53 0.02 6883 2.91 2.91 Dw_style_remove 1.02 1.55 0.02 5135 3.89 12.34 Html_pop_tag 1.02 1.57 0.02 2117 9.45 9.45 a_Url_free 1.02 1.59 0.02 1784 11.21 11.21 Url_object_new 1.02 1.61 0.02 858 23.31 74.05 Html_tag_open_tr 1.02 1.63 0.02 681 29.37 158.58 Html_tag_open_table 1.02 1.65 0.02 Cache_url_hash 0.51 1.66 0.01 22704 0.44 0.44 a_Dw_gtk_viewport_get_type 0.51 1.67 0.01 16565 0.60 0.60 Html_match_tag 0.51 1.68 0.01 16383 0.61 0.61 a_Dw_table_get_type 0.51 1.69 0.01 13003 0.77 48.25 Html_process_tag 0.51 1.70 0.01 13003 0.77 3.85 Html_tag_index 0.51 1.71 0.01 8345 1.20 1.20 a_Url_str 0.51 1.72 0.01 6150 1.63 2.40 Dw_page_forall 0.51 1.73 0.01 6130 1.63 2.07 Dw_widget_update_cursor 0.51 1.74 0.01 6130 1.63 4.11 a_Dw_widget_unrealize 0.51 1.75 0.01 5312 1.88 7.02 Html_eventually_pop_dw 0.51 1.76 0.01 4383 2.28 2.28 a_Bitvec_free 0.51 1.77 0.01 3380 2.96 96.27 Dw_page_rewrap 0.51 1.78 0.01 3067 3.26 4.04 a_Dw_widget_size_allocate 0.51 1.79 0.01 3065 3.26 12.33 a_Dw_widget_realize 0.51 1.80 0.01 3064 3.26 3.96 Dw_container_remove <snip> ----------------------------------------------- 0.00 0.00 69/10749 Html_tag_open_dt [140] 0.00 0.00 426/10749 Html_par_push_tag [110] 0.00 0.00 480/10749 Html_tag_open_dd [78] 0.00 0.00 681/10749 Html_tag_open_table [17] 0.01 0.00 3432/10749 Html_tag_open_tr [27] 0.02 0.00 5661/10749 Html_tag_open_td [9] [35] 2.4 0.04 0.01 10749 Html_cleanup_tag [35] 0.01 0.00 10749/16565 Html_match_tag [93] 0.00 0.00 177/5312 Html_eventually_pop_dw [44]
Related to this, I have a new version (probably the last, announcement to follow) of the kbnav patch which solves some performance issues related to g_list_search_custom(). This function, which caused an enormous overhead, has been eliminated from the patch alltogether in favor of a hashtable-based search. Frank -- WWWWW ________________________ ## o o\ / Frank de Lange \ }# \| / +46-734352015 \ \ `--| _/ <Hacker for Hire> \ `---' \ +31-640037120 / \ frank@unternet.org / `------------------------' [ "Omnis enim res, quae dando non deficit, dum habetur et non datur, nondum habetur, quomodo habenda est." ]
BTW, The new kbnav patch is NOT on the site yet, wait for the announcement before you try to download it... Frank -- WWWWW ________________________ ## o o\ / Frank de Lange \ }# \| / +46-734352015 \ \ `--| _/ <Hacker for Hire> \ `---' \ +31-640037120 / \ frank@unternet.org / `------------------------' [ "Omnis enim res, quae dando non deficit, dum habetur et non datur, nondum habetur, quomodo habenda est." ]
On Fri, 5 Dec 2003, Johannes Hofmann wrote:
Hi Jorge,
On Thu, Dec 04, 2003 at 10:43:34AM -0300, Jorge Arellano Cid wrote:
I could not yet get any reproducible results from profiling,
!?
Doesn't it show any function usage-ratio/run-time change?
Ok, I redid the profiling on my slower Linux box with utilities.html.
Html_cleanup_tag is called more often in cvs version (16742 vs. 10749) and seems quite a bit slower than in 0.7.3.
See gprof output below.
Hope that helps, Johannes
PS: Of course I can send you the whole gprof output, but it is quite large, so I did not want to send the whole thing to the list. [...]
Thanks a lot! Now it's clear where's the problem. I'll review it together with another parsing issue in a few days I hope. Cheers Jorge.-
On Fri, 5 Dec 2003, Johannes Hofmann wrote:
Hi Jorge,
On Thu, Dec 04, 2003 at 10:43:34AM -0300, Jorge Arellano Cid wrote:
I could not yet get any reproducible results from profiling,
!?
Doesn't it show any function usage-ratio/run-time change?
Ok, I redid the profiling on my slower Linux box with utilities.html.
Html_cleanup_tag is called more often in cvs version (16742 vs. 10749) and seems quite a bit slower than in 0.7.3.
See gprof output below. [...]
This is one of those weird situations that computer programming has. If we had been working for a year to make rendering three times faster, and succeeded on the effort, it'd be regarded as a substantial achievement. Actually we had been working for four years to get every bit of speed we can into dillo, and a library upgrade that makes dillo three times slower, is unacceptable. Now, all of a sudden, rendering went three times slower because of some unknown reasons, after applying a simple patch. Profiling revealed that Html_cleanup_tag() was to blame, _but_ that function is identical in both versions! Who's to blame? The compiler, the CPU cache, the pipeline, memory handling, page faults, ... All of them? I made a guess based on our C code, rearranged it and voila!, the former performance is back. Weird world, isn't it? What should have a minor impact on performance (a few CPU cycles overhead) exceeded 0(n) algorithms by a factor of two. :-o It seems that detailed knowledge of the underlying layers plays a significant role in the overall performance of a program. This may seem obvious, but remember that the academy teachs the opposite. Caveat emptor! Patch commited. Cheers Jorge.-
participants (3)
-
Frank de Lange -
Johannes Hofmann -
Jorge Arellano Cid