Logging optimizer info
Hi!
Sometimes you want to know when OpenSCAD applies an optimization to your scad code. Maybe you're trying to make it faster, or you just want to write a unit test for your fancy new code analysis feature.
For instance, why doesn't this get tail recursion on 2019.05?!
function f(n, r=0) = n == 0 ? sqrt(r) : f(n - 1, r + n*n);
(spoiler: because both "sqrt" and "f" are function calls; use "sqrt(r) + 0" as workaround)
And there's PR #3020 which changes the rules for tail recursion again.
To make matters worse, I'm hacking together another optimization, that makes stuff like below much faster by avoiding list copies where possible:
function f_append(n, r=[]) = n == 0 ? r : f_append(n - 1, [each r, n]);
Bottomline: it would be handy to know when an optimization is applied, and have that info be unit-testable.
Easiest for now is to just log the info, I guess. The output would probably need a prefix, like with ECHO/WARNING/ERROR/TRACE and friends.
Maybe use prefix "ANALYSIS".
Some sample output could be, with line/column:
ANALYSIS: Tail recursion enabled for 'f' at 4:23
ANALYSIS: Tail recursion disabled for 'f' at 4:42 (reason: not a pure call)
ANALYSIS: Last read of 'm' at 8:5 (assigned at 7:23)
Too verbose, or not enough? Maybe it needs to be more structured?
And, how to enable output of this info: maybe easiest is to set some config variable inside the .scad, i.e. "$openscad_log_analysis_info". That allows selectively enabling it.
- What would be a nice name for this var?
- Just assign a boolean value to this config var, or something more fancy (i.e. a bitmask, list, ...)
- Or make it a CLI parameter/GUI setting
- Or always enable it, and sit back to enjoy the (parse-time only) spam.
Any thoughts/opinions?
On 09.08.19 14:01, jschobben wrote:
That allows selectively enabling it.
The feature for that is currently --debug=filename-without-extension
For example:
./openscad --debug=FontCache examples/Basics/text_on_cube.scad
This basically enables the output of the PRINTD and PRINTDB
functions.
I guess that could be extended to allow more specific selections if
needed...
ciao,
Torsten.
On 09.08.19 14:01, jschobben wrote:
Some sample output could be, with line/column:
ANALYSIS: Tail recursion enabled for 'f' at 4:23
ANALYSIS: Tail recursion disabled for 'f' at 4:42 (reason: not a pure call)
ANALYSIS: Last read of 'm' at 8:5 (assigned at 7:23)
Oh, another idea we discussed some time ago was to show the
AST in the GUI as actual tree with some extra annotations per
node. Right now there's only a simple "Design->Display AST"
which shows the text form.
That's probably not easy with the current evaluation logic
directly tied to the AST nodes. What I'm thinking is that
changing this to a visitor based evaluation would help and
should make it possible to use a "TimingVisitor" which
collects additional information.
ciao,
Torsten.
jschobben wrote
Sometimes you want to know when OpenSCAD applies an optimization to your
scad code. Maybe you're trying to make it faster, or you just want to
write a unit test for your fancy new code analysis feature.
For instance, why doesn't this get tail recursion on 2019.05?!
function f(n, r=0) = n == 0 ? sqrt(r) : f(n - 1, r + n*n);
(spoiler: because both "sqrt" and "f" are function calls; use "sqrt(r) +
0" as workaround)
Why does it matter that sqrt is a function call and why does adding "+0" act
as a workaround?
I've often found myself puzzling over whether tail recursion is happening or
not, running code on large inputs to try to force it to overflow the stack
as a test.
Easiest for now is to just log the info, I guess. The output would
probably need a prefix, like with ECHO/WARNING/ERROR/TRACE and friends.
Maybe use prefix "ANALYSIS".
Some sample output could be, with line/column:
ANALYSIS: Tail recursion enabled for 'f' at 4:23
ANALYSIS: Tail recursion disabled for 'f' at 4:42 (reason: not a pure
call)
ANALYSIS: Last read of 'm' at 8:5 (assigned at 7:23)
Are those clock times? I'm not sure what the numbers mean. It doesn't
seem like less
And, how to enable output of this info: maybe easiest is to set some
config variable inside the .scad, i.e. "$openscad_log_analysis_info". That
allows selectively enabling it.
- What would be a nice name for this var?
- Just assign a boolean value to this config var, or something more fancy
(i.e. a bitmask, list, ...) - Or make it a CLI parameter/GUI setting
- Or always enable it, and sit back to enjoy the (parse-time only) spam.
In a later message was suggested using a CLI parameter and having output go
to a file. That seems pretty annoying. I think having the info go to the
log on the screen is more useful. And there needs to be a way to toggle the
analysis on and of without quitting OpenSCAD and restarting. It seems like
having a setting in the GUI (and corresponding CLI option) is probably the
right option. Having a variable seems like it might be nice, but it's not
really consistent with how other debugging features are enabled.
--
Sent from: http://forum.openscad.org/
On 09.08.19 23:34, adrianv wrote:
In a later message was suggested using a CLI parameter and having
output go to a file. That seems pretty annoying.
Nope. There was nothing said about a file and if you try the given
example, you'll see that the output enabled by that --debug option
is going into the console window.
What was maybe not clear enough is that "filename-without-extension"
is the scope of the debug flag and refers to the code file where the
debug output is enabled. So --debug=FontCache enables the debug output
in source code file FontCache.cc (hence the comment of not being
very specific regarding what debug output can be enabled).
Personally (I think) I'd prefer a separate window that could show
the info in a tree view. If that really works as well as I imagine
right now is a matter of actually trying it out.
ciao,
Torsten.
tp3 wrote
On 09.08.19 23:34, adrianv wrote:
In a later message was suggested using a CLI parameter and having
output go to a file. That seems pretty annoying.
Nope. There was nothing said about a file and if you try the given
example, you'll see that the output enabled by that --debug option
is going into the console window.
Oh. I tried the example, but with a file that had no text in it. And I got
no output anywhere, so I guess I was left in a state of confusion. But I
do think it would be annoying to have to restart OpenSCAD from the command
line to change the proposed analysis option setting.
--
Sent from: http://forum.openscad.org/
The feature for that is currently --debug=filename-without-extension
Ah, so that's how that works :)
And output also goes nicely to the console when using "-o", so it's suitable
for testing.
The risk is that this "analysis" feature may be split over multiple source
files, or that multiple debug-logs may be present in the same file. But, it
can indeed be extended to improve selection, I guess.
Oh, another idea we discussed some time ago was to show the
AST in the GUI as actual tree with some extra annotations per
node. Right now there's only a simple "Design->Display AST"
which shows the text form.
That could be one way, I was thinking more along the lines of highlighting
code in the source editor directly. The parser provides exact line/column
numbers (after a small bugfix) for all tokens already. I made a simple shell
script that takes my prototype analysis output, and prints a .scad file with
colorized first/last usage of variables.
Well, maybe we can have both a AST tree and colorized source :). But having
a nice GUI is probably "phase two", let's first get textual output so it can
be unit-tested.
Why does it matter that sqrt is a function call and why does adding "+0"
act
as a workaround?
I guess it's a bit of a bug/quirk in current tail recursion detection rules.
The function's top expression must be a ternary, exactly one of its branches
must be a function call, and that one function call must be calling itself.
"sqrt" is a function call, even though it's not named the same. Adding "+0"
makes that branch be a binary operator, which pleases the tail-recursion
detection.
I've often found myself puzzling over whether tail recursion is happening
or
not, running code on large inputs to try to force it to overflow the stack
as a test.
Exactly, that sort of thing is precisely what these "analysis" logs would
clarify ;)
Are those clock times? I'm not sure what the numbers mean. It doesn't
seem like less
Those numbers refer to the line:column in the .scad source file, i.e. the
locations where "f" is called, and where "m" is assigned/last read.
--
Sent from: http://forum.openscad.org/