From mmhazewi@cs.ruu.nl Mon Mar 20 14:55:54 1995 >From mmhazewi@cs.ruu.nl Mon Mar 20 14:55:54 1995 Received: from relay.cs.ruu.nl (root@infix.cs.ruu.nl [131.211.80.7]) by linc.cis.upenn.edu (8.6.10/UPenn 1.4) with SMTP id OAA01791 for ; Mon, 20 Mar 1995 14:55:48 -0500 Posted-Date: Mon, 20 Mar 1995 14:55:48 -0500 Received-Date: Mon, 20 Mar 1995 14:55:48 -0500 Received: from alchemy.cs.ruu.nl by relay.cs.ruu.nl with SMTP id AA00288 (5.67a/IDA-1.5 for ); Mon, 20 Mar 1995 20:55:46 +0100 Received: (from mmhazewi@localhost) by alchemy.cs.ruu.nl (8.6.10/8.6.10/ehk) id UAA17370 for benh@linc.cis.upenn.edu; Mon, 20 Mar 1995 20:55:44 +0100 Date: Mon, 20 Mar 1995 20:55:44 +0100 From: Maarten Hazewinkel Message-Id: <199503201955.UAA17370@alchemy.cs.ruu.nl> To: benh@linc.cis.upenn.edu Subject: Angband (Mac, CW) Status: R Ben, Here are two extracts from a profile I just did. I compiled with the profiler, and let the Borg run a Half Troll Warrior for about 20 minutes in the dungeon. I'd have let it run longer, but I am afraid that even long microsecond counters might start to overflow then. I will include 2 summaries of the profile. One sorted by how often a function was called, and one by how much time it took for itself in total. The column headers are as follows: Count: Number of times the function was called. Only: Amount of time the function to for itself in total. This excludes the time spent in functions that it called. +Childres: Total time in function. This includes the time in called functions. %: The amount of time in the previous column expressed as a percentage of the total time the program ran under profile. Average, Maximum, Minimum: Timings for a single call of the function. Excludes time in called functions. The timings are in milliseconds. The fact that the header states a timebase of microseconds merely indicates the precision of measurement used. The dumps are too wide for an 80-column display. I hope you can look at your mail with something that manages at least 100 columns. If things get mangled badly in the mail, drop me a note and I'll binhex the stuff before mailing you. First here is the profile sorted by Count. I dropped everything below 1000 calls. Sort: by Count Function Name Count Only % +Children % Average Maximum Minimum floor_grid 227952 33.633 0.0 33.633 0.0 0.000 0.324 0.000 grid 135285 21.088 0.0 21.088 0.0 0.000 0.211 0.000 update_view_aux 90142 15401.421 4.9 21408.008 6.9 0.171 1.436 0.000 sf_put 38099 81.112 0.0 81.112 0.0 0.002 30.672 0.000 player_has_los 32895 7.974 0.0 7.974 0.0 0.000 0.912 0.000 known2_p 25277 33.601 0.0 36.833 0.0 0.001 0.367 0.000 player_can_see 24080 2366.242 0.8 2372.950 0.8 0.098 2.432 0.000 Term_what 19917 6.978 0.0 6.978 0.0 0.000 0.248 0.000 cave_seen_add 19684 5.934 0.0 5.934 0.0 0.000 0.303 0.000 prefix 18719 1.857 0.0 1.857 0.0 0.000 0.156 0.000 flavor_p 18681 3.711 0.0 3.711 0.0 0.000 0.221 0.000 inven_aware_p 18681 491.321 0.2 504.218 0.2 0.026 0.675 0.000 random_hack 18457 2.292 0.0 2.292 0.0 0.000 0.180 0.000 map_info 18147 1776.462 0.6 8395.610 2.7 0.098 0.844 0.000 mh_print 18147 1933.762 0.6 2061.278 0.7 0.107 0.584 0.000 mh_print_rel 18147 2403.203 0.8 4452.163 1.4 0.132 1.152 0.000 QueueAttrChar 18147 9.500 0.0 9.500 0.0 0.001 1.043 0.000 Term_draw 18147 118.458 0.0 127.789 0.0 0.007 0.980 0.000 map_info_aux 17926 4752.828 1.5 6599.146 2.1 0.265 1.473 0.000 wr_byte 14595 32.400 0.0 61.621 0.0 0.002 0.398 0.000 cave_view 14447 274.123 0.1 4673.676 1.5 0.019 0.572 0.000 distance 13726 3.064 0.0 3.064 0.0 0.000 0.548 0.000 insert_str 13181 14.408 0.0 14.408 0.0 0.001 0.423 0.000 lite_spot 11597 5678.861 1.8 14823.976 4.8 0.490 1.271 0.000 update_map 11597 429.621 0.1 1426.986 0.5 0.037 0.521 0.000 known2_aux 11401 3.232 0.0 3.232 0.0 0.000 0.244 0.000 CheckEvents 11265 52919.428 17.0 52919.428 17.0 4.698 404.660 1.778 FlushOutputRow 9732 42342.416 13.6 61675.805 19.8 4.351 13.086 0.000 update_view_aux_2 8902 632.577 0.2 3295.468 1.1 0.071 0.605 0.000 streq 8194 3.493 0.0 3.493 0.0 0.000 0.246 0.000 inven_char 6303 235.460 0.1 255.687 0.1 0.037 0.533 0.000 inven_attr 6299 235.831 0.1 252.069 0.1 0.037 0.525 0.000 Term_gotoxy 5975 1.139 0.0 1.139 0.0 0.000 0.232 0.000 Term_wipe 5605 720.610 0.2 5770.826 1.9 0.129 0.573 0.000 Term_wipe_mac 5605 5059.616 1.6 5059.616 1.6 0.903 2.107 0.000 update_view_aux_1 5545 753.476 0.2 2767.684 0.9 0.136 0.732 0.000 cave_lite 5364 104.657 0.0 1421.422 0.5 0.020 0.464 0.000 update_mon 5180 2686.416 0.9 6166.841 2.0 0.519 1.456 0.000 Term_xtra_mac 4957 338.939 0.1 57500.721 18.5 0.068 1.329 0.000 objdes 4685 17855.718 5.7 18559.553 6.0 3.811 6.565 0.278 setcolor 4578 5.429 0.0 5.429 0.0 0.001 0.302 0.000 Term_text 4527 594.902 0.2 18284.687 5.9 0.131 0.672 0.000 Term_text_mac 4527 13024.749 4.2 17697.965 5.7 2.877 69.991 0.821 Term_addstr 4500 506.858 0.2 2368.756 0.8 0.113 0.787 0.000 wr_u32b 4452 1555.274 0.5 1605.478 0.5 0.349 0.794 0.000 Term_activate 4450 647.573 0.2 1102.557 0.4 0.146 0.908 0.000 QueueAttrChars 4274 1863.212 0.6 1863.212 0.6 0.436 3.082 0.000 Term_putstr 4233 1046.468 0.3 3344.654 1.1 0.247 0.741 0.000 suffix 4152 2.146 0.0 2.146 0.0 0.001 0.238 0.000 Term_xtra 4114 401.331 0.1 110589.692 35.5 0.098 0.558 0.000 wr_u16b 2848 62.929 0.0 64.259 0.0 0.022 0.628 0.000 los 2630 1687.197 0.5 1689.211 0.5 0.642 3.467 0.000 Term_xtra_mac_level 2552 6.099 0.0 6.314 0.0 0.002 0.262 0.000 Term_xtra_borg 2517 1076.165 0.3 98398.931 31.6 0.428 9.512 0.000 auto_build_room_floor 2337 537.317 0.2 537.970 0.2 0.230 4.040 0.000 process_monsters 2049 4038.944 1.3 9063.639 2.9 1.971 6.477 0.000 is_a_vowel 1961 0.374 0.0 0.374 0.0 0.000 0.157 0.000 clean_grid 1831 0.445 0.0 0.445 0.0 0.000 0.119 0.000 index_to_label 1629 0.288 0.0 0.288 0.0 0.000 0.086 0.000 inven_attr_by_tval 1623 0.817 0.0 0.817 0.0 0.001 0.190 0.000 Term_xtra_mac_react 1587 0.535 0.0 0.535 0.0 0.000 0.262 0.000 Term_xtra_mac_check 1575 689.838 0.2 26311.033 8.5 0.438 0.961 0.000 inven_tried_p 1374 194.080 0.1 408.381 0.1 0.141 0.525 0.000 wr_s16b 1315 153.598 0.0 186.052 0.1 0.117 0.403 0.000 activate 1314 0.215 0.0 0.215 0.0 0.000 0.140 0.000 auto_build_snake 1222 404.039 0.1 404.510 0.1 0.331 0.987 0.000 wield_slot 1174 0.054 0.0 0.054 0.0 0.000 0.054 0.000 Term_hide_cursor 1151 0.212 0.0 0.212 0.0 0.000 0.109 0.000 Borg_inkey 1078 0.093 0.0 0.093 0.0 0.000 0.076 0.000 And here is the profile sorted by Only. Everything that took less than 1000 milliseconds was dropped. Sort: by Only Function Name Count Only % +Children % Average Maximum Minimum CheckEvents 11265 52919.428 17.0 52919.428 17.0 4.698 404.660 1.778 FlushOutputRow 9732 42342.416 13.6 61675.805 19.8 4.351 13.086 0.000 update_view 189 32009.540 10.3 61757.446 19.8 169.363 351.628 62.405 objdes 4685 17855.718 5.7 18559.553 6.0 3.811 6.565 0.278 update_view_aux 90142 15401.421 4.9 21408.008 6.9 0.171 1.436 0.000 Term_text_mac 4527 13024.749 4.2 17697.965 5.7 2.877 69.991 0.821 auto_prepare_think 213 10914.656 3.5 18884.417 6.1 51.243 172.206 9.767 prt_map 8 8509.322 2.7 14087.934 4.5 1063.665 1095.746 945.723 auto_prepare_start 213 7197.439 2.3 16174.252 5.2 33.791 1459.768 7.579 hook_ralloc 872 6645.138 2.1 6645.138 2.1 7.621 122.324 5.276 auto_flow_explore 3 6052.461 1.9 6895.151 2.2 2017.487 2032.901 1991.859 lite_spot 11597 5678.861 1.8 14823.976 4.8 0.490 1.271 0.000 term_win_wipe 307 5077.875 1.6 5077.875 1.6 16.540 18.093 16.083 Term_wipe_mac 5605 5059.616 1.6 5059.616 1.6 0.903 2.107 0.000 map_info_aux 17926 4752.828 1.5 6599.146 2.1 0.265 1.473 0.000 process_monsters 2049 4038.944 1.3 9063.639 2.9 1.971 6.477 0.000 Term_xtra_mac_event 12 3545.908 1.1 30845.391 9.9 295.492 594.889 44.310 FlushOutput 818 3541.027 1.1 65473.658 21.0 4.329 10.404 0.000 auto_item_analyze 232 3517.190 1.1 3594.933 1.2 15.160 63.686 0.802 choice_inven 245 2998.350 1.0 51035.328 16.4 12.238 17.569 9.363 update_lite 400 2951.482 0.9 6874.331 2.2 7.379 14.522 0.403 wr_lore 549 2739.691 0.9 4034.636 1.3 4.990 5.738 3.299 update_mon 5180 2686.416 0.9 6166.841 2.0 0.519 1.456 0.000 mh_print_rel 18147 2403.203 0.8 4452.163 1.4 0.132 1.152 0.000 player_can_see 24080 2366.242 0.8 2372.950 0.8 0.098 2.432 0.000 mh_print 18147 1933.762 0.6 2061.278 0.7 0.107 0.584 0.000 cave_seen_grab_view 189 1889.014 0.6 1893.300 0.6 9.995 27.163 0.000 QueueAttrChars 4274 1863.212 0.6 1863.212 0.6 0.436 3.082 0.000 map_info 18147 1776.462 0.6 8395.610 2.7 0.098 0.844 0.000 los 2630 1687.197 0.5 1689.211 0.5 0.642 3.467 0.000 auto_build_room 213 1672.186 0.5 8503.315 2.7 7.851 47.834 1.387 update_monsters 191 1598.802 0.5 6930.349 2.2 8.371 11.351 6.192 wr_item 184 1567.673 0.5 2172.332 0.7 8.520 8.970 7.109 wr_u32b 4452 1555.274 0.5 1605.478 0.5 0.349 0.794 0.000 wr_dungeon 1 1304.585 0.4 2321.492 0.7 1304.585 1304.585 1304.585 auto_prepare_inven 213 1280.942 0.4 8560.431 2.8 6.014 7.994 5.097 Term_xtra_borg 2517 1076.165 0.3 98398.931 31.6 0.428 9.512 0.000 Term_putstr 4233 1046.468 0.3 3344.654 1.1 0.247 0.741 0.000 If you need anything more from this profile, just mail me. I could probably mail you the binary profile data (24k) and the viewer application (504k, but I can drop the native code to get to 275k, and then compress it of course). If you have access to CodeWarrior, you just need the binary data. I have also done an earlier profile, much less extensive, but without using the borg, and using manual input. This gave a much higher indication for time and calls to CheckEvents. It got called about 90000 times in 4 minutes, using up almost 70% of the program time. I'm going to see if I can do something about this, and whether it will speed up the game under manual control. I'll collect the changes make to get the program to compile under CW tonight, and mail them to you asap. Maarten Hazewinkel mmhazewi@cs.ruu.nl