395
edits
User talk:Philosopher/Nasal introspection: Difference between revisions
Jump to navigation
Jump to search
User talk:Philosopher/Nasal introspection (view source)
Revision as of 01:41, 15 September 2013
, 15 September 2013→September 14: new section
Philosopher (talk | contribs) m (→Race Condition ?: del() - fixed) |
Philosopher (talk | contribs) (→September 14: new section) |
||
| Line 127: | Line 127: | ||
—[[User:Hooray|Hooray]] | —[[User:Hooray|Hooray]] | ||
== September 14 == | |||
I've pushed lots of changes yesterday and some today. I would appreciate thoughts on performance – I basically fixed all errors and most warnings, I get these three on exit: | |||
<syntaxhighlight lang="ada"> | |||
Stack processing error: warning: no call stack/return for function test.listener: | |||
at /Users/philosopher/Documents/FlightGear/fgdata/Nasal/test.nas, line 468 | |||
Stack processing error: warning: no call stack/return for function __gcsave.89: | |||
at /Users/philosopher/Documents/FlightGear/fgdata/Nasal/test.nas, line 468 | |||
Stack processing error: warning: no call stack/return for function __gcsave.90: | |||
at /Users/philosopher/Documents/FlightGear/fgdata/Nasal/test.nas, line 468 | |||
</syntaxhighlight> | |||
This is related to the fact that I turn on profiling halfway through a function call stack ;-). (I set a timer, probably shows up as __gcsave.90, which, before the timer exits, triggers a listener, say __gcsave.89, while calls the actual listener body, test.listener, due to the wrapping in globals.nas.) | |||
I also get frequent timing warnings: | |||
<syntaxhighlight lang="php"> | |||
warning: long time for add_func call: 5.640983581542969ms with a size of 10 for entry func:0x7fef4909aa70 | |||
warning: long time for add_func call: 15.3660774230957ms with a size of 11 for entry func:0x7fef4909aa00 | |||
warning: long time for add_func call: 8.067131042480469ms with a size of 40 for entry func:0x7fef49154ff0 | |||
Queue_up: Waiting time: 14.64819908142089ms | |||
warning: long time for add_func call: 15.04707336425781ms with a size of 44 for entry func:0x7fef49112090 | |||
warning: long time for add_func call: 4.133224487304688ms with a size of 53 for entry func:0x7fef4a8e8250 | |||
warning: long time for add_func call: 4.251003265380859ms with a size of 54 for entry func:0x7fef4a8ad070 | |||
warning: long time for add_func call: 5.972862243652344ms with a size of 63 for entry func:0x7fef49154d88 | |||
warning: long time for add_func call: 5.639076232910156ms with a size of 70 for entry func:0x7fef49111a70 | |||
do_worker_thread/get: Waiting time: 5.290031433105469ms | |||
warning: long time for add_func call: 4.57000732421875ms with a size of 79 for entry func:0x7fef4990c4e0 | |||
warning: long time for add_func call: 4.376173019409179ms with a size of 83 for entry func:0x7fef4b135d10 | |||
warning: long time for add_func call: 4.052877426147461ms with a size of 84 for entry func:0x7fef4b149ff8 | |||
warning: long time for add_func call: 4.475116729736328ms with a size of 87 for entry func:0x7fef4a9e8670 | |||
warning: long time for add_func call: 4.47392463684082ms with a size of 89 for entry func:0x7fef49908ca8 | |||
warning: long time for add_func call: 4.024982452392578ms with a size of 90 for entry func:0x7fef49909338 | |||
Queue_up: Waiting time: 17.55404472351074ms | |||
warning: long time for add_func call: 4.741907119750977ms with a size of 91 for entry func:0x7fef49110d88 | |||
warning: long time for add_func call: 5.394935607910156ms with a size of 94 for entry func:0x7fef4aa0c488 | |||
warning: long time for add_func call: 4.699945449829102ms with a size of 99 for entry func:0x7fef4b1496c8 | |||
Queue_up: Waiting time: 17.0600414276123ms | |||
warning: long time for add_func call: 4.919052124023438ms with a size of 100 for entry func:0x7fef4aa0a690 | |||
warning: long time for add_func call: 10.23697853088379ms with a size of 103 for entry func:0x7fef49155338 | |||
warning: long time for add_func call: 4.286050796508789ms with a size of 105 for entry func:0x7fef49111db8 | |||
warning: long time for add_func call: 5.666971206665039ms with a size of 106 for entry func:0x7fef49111df0 | |||
warning: long time for add_func call: 5.033016204833984ms with a size of 107 for entry func:0x7fef490b9e38 | |||
warning: long time for add_func call: 5.100965499877929ms with a size of 108 for entry func:0x7fef49154c70 | |||
warning: long time for add_func call: 27.99296379089355ms with a size of 112 for entry func:0x7fef491551b0 | |||
Queue_up: Waiting time: 6.907939910888672ms | |||
Queue_up: Waiting time: 13.18097114562988ms | |||
warning: long time for add_func call: 5.21397590637207ms with a size of 116 for entry func:0x7fef49290a60 | |||
</syntaxhighlight> | |||
I would postulate that the locking warnings happen when, in between a lock/unlock event, a GC event occurs – otherwise things don't typically hold locks for more than a handful of lines, and that goes zippity-fast in Nasal. You can experiment with the add_func call level to get a sense of what is normal and what isn't. I should ''probably'' delegate some of the more expensive tasks (~cough~, searching for a global lvalue) to the background thread, but it really doesn't take up time worth optimizing yet. I will see what queue_up timing statistics look like tomorrow, but that still doesn't tell me what takes up so much time. | |||
Hm, looking at the code, maybe calling queue_up recursively for allocations isn't such a good idea...? Removing the 1 on line 323 speeds things up some, but I'm still concerned about this statistic: | |||
<syntaxhighlight lang="php"> | |||
Took 182.8384615384615 times as long w/ extras | |||
Took 167.578231292517 times as long w/ extras | |||
Took 213.0176991150443 times as long w/ extras | |||
Took 246.7391304347826 times as long w/ extras | |||
</syntaxhighlight> | |||
== Debugging Threads == | == Debugging Threads == | ||