Re: fontlock-speed

On 08 Feb 2002 at 14:56:48 +0900, "Stephen J. Turnbull" <stephen(a)xemacs.org&gt; wrote: The two binaries used in the following tests were compiled with the same compiler and the same compiler options (the RedHat 7.1 version of gcc, which calls itself "2.96 20000731"; curses on RedHat for doing this!). They are using the same Lisp packages. I configured them with nearly identical options (the difference being --gung-ho for 21.1.14). The tests were done with "-q" to eliminate effects from my customizations. Gprof seems to think that none of those 3 functions is being called at all in 21.1.14, although they are in 21.4.6. Here are the top 20 time-consuming functions from a run of 21.1.14 in which I simply started PVS and then exited: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls us/call us/call name 16.54 0.22 0.22 1136031 0.19 0.22 mark_object 7.52 0.32 0.10 1623314 0.06 0.06 readchar 5.26 0.39 0.07 14610 4.79 7.75 Fbyte_code 4.51 0.45 0.06 80664 0.74 3.39 read1 3.01 0.49 0.04 300305 0.13 0.13 mark_cons 3.01 0.53 0.04 156433 0.26 0.33 find_symbol_value_1 2.26 0.56 0.03 64778 0.46 0.47 read_list_conser 2.26 0.59 0.03 41737 0.72 2.04 read_atom_0 2.26 0.62 0.03 39839 0.75 0.95 oblookup 2.26 0.65 0.03 16173 1.85 2.84 sequence_reader 1.50 0.67 0.02 1139360 0.02 0.02 get_PURESIZE 1.50 0.69 0.02 535294 0.04 0.04 Fcdr 1.50 0.71 0.02 177294 0.11 0.20 reader_nextchar 1.50 0.73 0.02 145610 0.14 0.14 Fset 1.50 0.75 0.02 103408 0.19 0.29 Lstream_flush_out 1.50 0.77 0.02 81498 0.25 0.25 mark_symbol 1.50 0.79 0.02 62370 0.32 0.32 symbol_value_buffer_local_info 1.50 0.81 0.02 36262 0.55 0.83 internal_equal 1.50 0.83 0.02 14097 1.42 3.08 funcall_lambda 1.50 0.85 0.02 5489 3.64 3.91 concat Now here is a run of 21.1.14 in which I started PVS, loaded and font-locked prelude.pvs, and then exited: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 26.62 1.23 1.23 73445 0.02 0.02 re_match_2_internal 6.71 1.54 0.31 400462 0.00 0.00 extent_list_locate 6.06 1.82 0.28 15324 0.02 0.03 Fbyte_code 4.55 2.03 0.21 1900525 0.00 0.00 mark_object 3.46 2.19 0.16 174054 0.00 0.00 map_extents_bytind 3.03 2.33 0.14 99071 0.00 0.00 funcall_recording_as 2.38 2.44 0.11 35414 0.00 0.00 Fstring_equal 1.73 2.52 0.08 42611 0.00 0.00 read_atom_0 1.52 2.59 0.07 1643689 0.00 0.00 readchar 1.52 2.66 0.07 242820 0.00 0.00 advance_plist_pointers 1.52 2.73 0.07 19756 0.00 0.07 sys_re_search_2 1.30 2.79 0.06 994806 0.00 0.00 buffer_or_string_extent_info 1.30 2.85 0.06 558049 0.00 0.00 mark_cons 1.30 2.91 0.06 179703 0.00 0.00 Fextent_property 1.08 2.96 0.05 288412 0.00 0.00 do_symval_forwarding 1.08 3.01 0.05 221980 0.00 0.00 specbind 1.08 3.06 0.05 11 4.55 4.55 sweep_conses 0.87 3.10 0.04 493243 0.00 0.00 Fset 0.87 3.14 0.04 230898 0.00 0.00 find_symbol_value 0.87 3.18 0.04 172407 0.00 0.00 Fcons Next is a run of 21.4.6 in which I just start PVS and then exit: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 11.40 0.13 0.13 1085405 0.00 0.00 mark_object 6.14 0.20 0.07 1645826 0.00 0.00 readchar 5.26 0.26 0.06 15297 0.00 0.01 execute_optimized_program 5.26 0.32 0.06 7 8.57 8.57 compact_string_chars 4.39 0.37 0.05 183586 0.00 0.00 do_symval_forwarding 4.39 0.42 0.05 81429 0.00 0.00 read1 3.51 0.46 0.04 42220 0.00 0.00 read_atom_0 2.63 0.49 0.03 365211 0.00 0.00 mark_cons 2.63 0.52 0.03 76523 0.00 0.00 mark_symbol 2.63 0.55 0.03 7 4.29 4.29 sweep_conses 1.75 0.57 0.02 83613 0.00 0.00 store_symval_forwarding 1.75 0.59 0.02 82376 0.00 0.00 Fcar 1.75 0.61 0.02 58528 0.00 0.00 make_uninit_string 1.75 0.63 0.02 42220 0.00 0.00 read_atom 1.75 0.65 0.02 8683 0.00 0.00 prepare_to_modify_buffer 1.75 0.67 0.02 4134 0.00 0.00 Fmemq 1.75 0.69 0.02 1153 0.02 0.07 set_buffer_internal 1.75 0.71 0.02 7 2.86 2.86 sweep_symbols 0.88 0.72 0.01 178960 0.00 0.00 reader_nextchar 0.88 0.73 0.01 121717 0.00 0.00 find_symbol_value_1 And finally, a run of 21.4.6 in which I load and font-lock prelude.pvs, and then exit: Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 26.39 4.57 4.57 10784976 0.00 0.00 extent_list_locate 21.25 8.25 3.68 122395 0.03 0.03 re_match_2_internal 3.75 8.90 0.65 1011217 0.00 0.00 map_extents_bytind 3.41 9.49 0.59 14611763 0.00 0.00 update_syntax_cache 2.77 9.97 0.48 2579833 0.00 0.00 soe_move 2.66 10.43 0.46 8559888 0.00 0.00 extent_list_at 2.02 10.78 0.35 6358638 0.00 0.00 extent_list_locate_from_pos 1.91 11.11 0.33 1806873 0.00 0.00 extent_in_region_p 1.85 11.43 0.32 744589 0.00 0.00 Fextent_property 1.62 11.71 0.28 20110 0.01 0.02 execute_optimized_program 1.56 11.98 0.27 12375343 0.00 0.00 buffer_or_string_extent_info 1.21 12.19 0.21 2060087 0.00 0.00 mark_object 1.15 12.39 0.20 2227380 0.00 0.00 gap_array_insert_els 1.10 12.58 0.19 4996504 0.00 0.00 gap_array_adjust_markers 1.10 12.77 0.19 2521559 0.00 0.00 get_buffer_pos_char 1.04 12.95 0.18 6094395 0.00 0.00 buffer_or_string_stack_of_extents_force 1.04 13.13 0.18 929921 0.00 0.00 extent_at_bytind 1.04 13.31 0.18 819566 0.00 0.00 extent_find_beginning_of_run 0.98 13.48 0.17 1113690 0.00 0.00 extent_list_insert 0.98 13.65 0.17 1089475 0.00 0.00 advance_plist_pointers The full gprof results are temporarily available here, in the order presented above: <URL:http://www.ittc.ku.edu/~james/xemacs/21.1.14.prof> <URL:http://www.ittc.ku.edu/~james/xemacs/21.1.14.prelude.prof> <URL:http://www.ittc.ku.edu/~james/xemacs/21.4.6.prof> <URL:http://www.ittc.ku.edu/~james/xemacs/21.4.6.prelude.prof> Each file is a bit over 1 MB in size. Let me know if you want me to try anything else. -- Jerry James