Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
2009/6/18 James Paige b...@hamsterrepublic.com: On Thu, Jun 18, 2009 at 04:56:35AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Wed, Jun 17, 2009 at 06:18:40AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %time time time/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms 206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James How about adding bounding spheres for slices in addition to bounding boxes. I think that that's what you're using it for? But I'm pretty clueless at the moment as to what the interface for that would be. Hmm... yeah, that would be a decent built-in feature for slices. That is indeed how I am using it. Wow, you certainly have a lot of layers of indirection in get/set force x/y Yes. I'm sure eliminating them will improve performance a decent bit. I had them there because I felt that writing the code was more intuitive for me with them working that way, and that I could optimize later if necessary. (premature optimization, evil, etc...) Also, might I mention that there's no reason to use abs before squaring in 'get c squared' and elsewhere? Oops! heh. I was throwing around abs() a lot to work around our crappy mod bug, and I guess I got superstitious about it. I'll remove. But wait a minute, are you sure that's what you want? abs(-19 mod 10) is 9, not 1, which is what I would usually want: the mathematically correct answer! H... The crappy mod bug I was referring to is that our implementation of mod seems to give different results for negative numbers than what I get from python... although maybe I tested wrong and confused myself? That's right. Python has bucked the trend, and has implemented mathematical modulo instead the hardware mod that every other programming language offers. Good on them. I usually use mod for wrapping. So I was hoping for -1, mod, 4 to result in
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
On Thu, Jun 18, 2009 at 9:29 AM, Ralph Versteegenteeem...@gmail.com wrote: 2009/6/18 James Paige b...@hamsterrepublic.com: On Thu, Jun 18, 2009 at 04:56:35AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Wed, Jun 17, 2009 at 06:18:40AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %time time time/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms 206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James How about adding bounding spheres for slices in addition to bounding boxes. I think that that's what you're using it for? But I'm pretty clueless at the moment as to what the interface for that would be. Hmm... yeah, that would be a decent built-in feature for slices. That is indeed how I am using it. Wow, you certainly have a lot of layers of indirection in get/set force x/y Yes. I'm sure eliminating them will improve performance a decent bit. I had them there because I felt that writing the code was more intuitive for me with them working that way, and that I could optimize later if necessary. (premature optimization, evil, etc...) Also, might I mention that there's no reason to use abs before squaring in 'get c squared' and elsewhere? Oops! heh. I was throwing around abs() a lot to work around our crappy mod bug, and I guess I got superstitious about it. I'll remove. But wait a minute, are you sure that's what you want? abs(-19 mod 10) is 9, not 1, which is what I would usually want: the mathematically correct answer! H... The crappy mod bug I was referring to is that our implementation of mod seems to give different results for negative numbers than what I get from python... although maybe I tested wrong and confused myself? That's right. Python has bucked the trend, and has implemented mathematical modulo instead the hardware mod that every other programming language offers. Good on them.
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
2009/6/17 James Paige b...@hamsterrepublic.com: On Wed, Jun 17, 2009 at 06:18:40AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %time time time/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms 206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James How about adding bounding spheres for slices in addition to bounding boxes. I think that that's what you're using it for? But I'm pretty clueless at the moment as to what the interface for that would be. Hmm... yeah, that would be a decent built-in feature for slices. That is indeed how I am using it. Wow, you certainly have a lot of layers of indirection in get/set force x/y Yes. I'm sure eliminating them will improve performance a decent bit. I had them there because I felt that writing the code was more intuitive for me with them working that way, and that I could optimize later if necessary. (premature optimization, evil, etc...) Also, might I mention that there's no reason to use abs before squaring in 'get c squared' and elsewhere? Oops! heh. I was throwing around abs() a lot to work around our crappy mod bug, and I guess I got superstitious about it. I'll remove. But wait a minute, are you sure that's what you want? abs(-19 mod 10) is 9, not 1, which is what I would usually want: the mathematically correct answer! Looking closer at those numbers that I posted, I'm suspicious of the time spent in updatesprite: it doesn't do much besides call lots of other scripts, but other scripts with a similar number of script calls, like checkcorner, spent no where near as much time. All the collision handling gets called inside updatesprite, so I am not really surprised. But these times don't include time spent in child scripts, so the collision checking time isn't a part of it. And besides, I don't think I had that many bubbles on that run, just enough to make it start lagging (~10). I don't really know how time is spent in the interpreter all that well, understanding the behaviour of an interpreter with a
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
On Thu, Jun 18, 2009 at 04:56:35AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Wed, Jun 17, 2009 at 06:18:40AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %time time time/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms 206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James How about adding bounding spheres for slices in addition to bounding boxes. I think that that's what you're using it for? But I'm pretty clueless at the moment as to what the interface for that would be. Hmm... yeah, that would be a decent built-in feature for slices. That is indeed how I am using it. Wow, you certainly have a lot of layers of indirection in get/set force x/y Yes. I'm sure eliminating them will improve performance a decent bit. I had them there because I felt that writing the code was more intuitive for me with them working that way, and that I could optimize later if necessary. (premature optimization, evil, etc...) Also, might I mention that there's no reason to use abs before squaring in 'get c squared' and elsewhere? Oops! heh. I was throwing around abs() a lot to work around our crappy mod bug, and I guess I got superstitious about it. I'll remove. But wait a minute, are you sure that's what you want? abs(-19 mod 10) is 9, not 1, which is what I would usually want: the mathematically correct answer! H... The crappy mod bug I was referring to is that our implementation of mod seems to give different results for negative numbers than what I get from python... although maybe I tested wrong and confused myself? I usually use mod for wrapping. So I was hoping for -1, mod, 4 to result in 3. That is pretty much the only way I have ever used mod, so it never occured to me that it might be mathematically wrong :) Looking closer at those numbers that I posted, I'm suspicious of the time spent in updatesprite:
[Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas ___ Ohrrpgce mailing list ohrrpgce@lists.motherhamster.org http://lists.motherhamster.org/listinfo.cgi/ohrrpgce-motherhamster.org
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %timetimetime/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit ___ Ohrrpgce mailing list ohrrpgce@lists.motherhamster.org http://lists.motherhamster.org/listinfo.cgi/ohrrpgce-motherhamster.org
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %timetimetime/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James ___ Ohrrpgce mailing list ohrrpgce@lists.motherhamster.org http://lists.motherhamster.org/listinfo.cgi/ohrrpgce-motherhamster.org
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Oh! Another problem. If you specify an rpg file from the command line, the profiling information never gets printed. It only works if you pick the rpg file from the filebrowser. I am guessing that freescripts get called on cleanup, and that gets skipped when exiting directly? hmmm... --- James ___ Ohrrpgce mailing list ohrrpgce@lists.motherhamster.org http://lists.motherhamster.org/listinfo.cgi/ohrrpgce-motherhamster.org
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Oh! Another problem. If you specify an rpg file from the command line, the profiling information never gets printed. It only works if you pick the rpg file from the filebrowser. I am guessing that freescripts get called on cleanup, and that gets skipped when exiting directly? hmmm... --- James Oh, I noticed that the info isn't printed when you pgup+pgdown+esc, but thought that was probably the only case. Guess that could do with fixing afterall. ___ Ohrrpgce mailing list ohrrpgce@lists.motherhamster.org http://lists.motherhamster.org/listinfo.cgi/ohrrpgce-motherhamster.org
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %time time time/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms 206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James How about adding bounding spheres for slices in addition to bounding boxes. I think that that's what you're using it for? But I'm pretty clueless at the moment as to what the interface for that would be. Wow, you certainly have a lot of layers of indirection in get/set force x/y Also, might I mention that there's no reason to use abs before squaring in 'get c squared' and elsewhere? Looking closer at those numbers that I posted, I'm suspicious of the time spent in updatesprite: it doesn't do much besides call lots of other scripts, but other scripts with a similar number of script calls, like checkcorner, spent no where near as much time. So, what happened to adding a builtin abs() anyway? Scanning my emails, it seems it ended, rather predictably, with me claiming I was working on some HSpeak fixes, and then never finishing them. I still have that stuff in my working copy, along with many other things :( Sounds like a project for tomorrow. Perfect, since I was going to work on HSpeak anyway. I was just wondering about squareroot. Ideally, we would have a squareroot that returned a floating point number, but since division is already integer only, maybe we could add sqrt now, and down the road have it return a floating point number if the argument is floating point? ___ Ohrrpgce mailing list ohrrpgce@lists.motherhamster.org http://lists.motherhamster.org/listinfo.cgi/ohrrpgce-motherhamster.org
Re: [Ohrrpgce] SVN: teeemcee/2751 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Ou
On Wed, Jun 17, 2009 at 06:18:40AM +1200, Ralph Versteegen wrote: 2009/6/17 James Paige b...@hamsterrepublic.com: On Tue, Jun 16, 2009 at 10:12:40PM +1200, Ralph Versteegen wrote: 2009/6/16 subvers...@hamsterrepublic.com: teeemcee 2009-06-16 03:09:22 -0700 (Tue, 16 Jun 2009) 458 Script profiling, enabled by passing -d SCRIPTPROFILE at compiletime. Output to g_debug.txt when quitting. Better and runtime toggleable profiling is something for the new interpreter. Profiling is done per-script only, and is not entirely accurate - context switches to other programs (or threads) aren't excluded. Comparison with my benchmarking scripts shows that the times sometimes disagree by 5% or more. I just couldn't leave load/freescripts alone. --- U wip/compat.bi U wip/const.bi U wip/game.bas U wip/gglobals.bi U wip/moresubs.bas U wip/udts.bi U wip/yetmore.bas U wip/yetmore2.bas I forgot to mention that the times include all time spent by script commands called by that script, including screen fades and menus like loadmenu. Here's the front of the output of a game of DON'T EAT SOAP, for interest: OHRRPGCE wip 20090615.2749 gfx_fb/music_sdl FB0.21.0 -g script_profiling Win32 Playing game eatsoap.rpgdir (Don't Eat Soap!) 06-16-2009 21:54:17 script profiling information: #switches is the number of times that the interpreter switched to that script (switching time is relatively neglible and included to help determine calls to other scripts, which are more expensive) Total time recorded in interpreter: 70.449sec (timer overhead = 1.32us) %time time time/call #calls #switches script name 25.66 18080ms 1164us 15537 295099 updatesprite 07.74 5455ms 11us 505553 1011106 getforce 06.49 4570ms 34us 132906 398718 getcsquared 05.24 3693ms 6us 587250 587250 getforceextraslot 03.46 2435ms 206us 11831 302992 checkbubbletobubblecollisions 03.32 2339ms 19us 124696 374088 careaboutdirection 03.29 2316ms 74us 31174 331937 checkcorner 03.28 2309ms 7us 352917 352917 abs 02.95 2077ms 10us 208224 416448 getforcey 02.78 1956ms 9us 208937 417874 getforcex 02.69 1893ms 14us 132477 278784 bubblebubblecollision 02.65 1870ms 12us 158684 158684 isbubblecolideablebubble 01.84 1297ms 21us 61944 185832 careaboutcorner 01.74 1226ms 13us 97460 97460 getexbit This is really cool! I'm going to try and use this info to optimize my script. Right away it makes me want a built-in function for checking radial distances. in circle range(x1, y1, x2, y2, pixels) which does something like scriptret = (x1 - x2) ^ 2 + (y1 - y2) ^ 2 pixels ^ 2 It also looks like my getforce commands would benefit from some optimization. --- James How about adding bounding spheres for slices in addition to bounding boxes. I think that that's what you're using it for? But I'm pretty clueless at the moment as to what the interface for that would be. Hmm... yeah, that would be a decent built-in feature for slices. That is indeed how I am using it. Wow, you certainly have a lot of layers of indirection in get/set force x/y Yes. I'm sure eliminating them will improve performance a decent bit. I had them there because I felt that writing the code was more intuitive for me with them working that way, and that I could optimize later if necessary. (premature optimization, evil, etc...) Also, might I mention that there's no reason to use abs before squaring in 'get c squared' and elsewhere? Oops! heh. I was throwing around abs() a lot to work around our crappy mod bug, and I guess I got superstitious about it. I'll remove. Looking closer at those numbers that I posted, I'm suspicious of the time spent in updatesprite: it doesn't do much besides call lots of other scripts, but other scripts with a similar number of script calls, like checkcorner, spent no where near as much time. All the collision handling gets called inside updatesprite, so I am not really surprised. So, what happened to adding a builtin abs() anyway? Scanning my emails, it seems it ended, rather predictably, with me claiming I was working on some HSpeak fixes, and then never finishing them. I still have that stuff in my working copy, along with many other things :( Sounds like a project for tomorrow. Perfect, since I was going to work on HSpeak anyway. Yeah, check it in! I will rup out my hamsterspeak implementations of abs() from all my scripts... with gusto! Oh, that reminds me. what about bug 567, Plotscripts names are not mutually
