printf statement optimized out

[brechtvl]

Another bug found by Michel Anders, if you have these two shaders:

shader test_a(output color C = 0)
{
    C[1] = 1; // does not print when removing this line
    if(C[1] != 0.123456)
        printf("%f\n", C);
}

shader test_b(color C = 0)
{
    Ci = C * diffuse(N);
}

and connect them like this:

./testshade --layer layer_a test_a --layer layer_b test_b --connect layer_a C layer_b C

Then it will not print anything when removing the indicated line, but you would expect it to print in both cases. I guess it's because it fails to do constant folding for that line, that it succeeds in printing.

If you use a float instead of a color it never prints:

shader test_a(output float C = 0)
{
    C = 1;
    if(C != 0.123456)
        printf("%f\n", C);
}

shader test_b(float C = 0.0)
{
    Ci = C * diffuse(N);
}

I might look into a fix later, but don't have time anymore this week for it, so if anyone else feels like fixing go ahead.

[lgritz]

I will investigate.

On Jun 21, 2013, at 8:23 AM, Brecht Van Lommel wrote:

Another bug found by Michel Anders, if you have these two shaders:

shader test_a(output color C = 0)
{
C[1] = 1; // does not print when removing this line
if(C[1] != 0.123456)
printf("%f\n", C);
}
shader test_b(color C = 0)
{
Ci = C * diffuse(N);
}
and connect them like this:

./testshade --layer layer_a test_a --layer layer_b test_b --connect layer_a C layer_b C
Then it will not print anything when removing the indicated line, but you would expect it to print in both cases. I guess it's because it fails to do constant folding for that line, that it succeeds in printing.

If you use a float instead of a color it never prints:

shader test_a(output float C = 0)
{
C = 1;
if(C != 0.123456)
printf("%f\n", C);
}
shader test_b(float C = 0.0)
{
Ci = C * diffuse(N);
}
I might look into a fix later, but don't have time anymore this week for it, so if anyone else feels like fixing go ahead.

—
Reply to this email directly or view it on GitHub.

Larry Gritz
lg@larrygritz.com

[lgritz]

I don't think this is a bug; it's the intended behavior.

When you remove the 'C[1]=1' line, the optimizer sees that output C is never altered from its default value of 0, therefore test_b's C is turned into a constant with that value and the connection between the shaders is severed. Without the connection (and more importantly, without the need for test_a to execute in order to know the value of test_b's C parameter), the printf never executes.

With the 'C[1] = 1' in place, however, it sees that C is altered in test_a, and it's sufficiently confused that it doesn't optimize away the connection, so when C is needed in test_b, it triggers the execution of test_a, which will run the printf. (You could argue that it should figure this case out, too, and turn test_b's C into a constant even with the C[1]=1 line in place, but that's not really your issue -- you want to know why the printf never happens, you're not complaining that there is a circumstance in which it does print, but shouldn't.)

We actually consider printf to be an elidable side effect, it's ok to optimize away a set of statements if the only thing they accomplish is printf. That seems strange at first, but what you need to do is try to imagine the problems with assuming that this is not the case... Layers are already run lazily, not in a guaranteed order (except inasmuch as a layer will run no later than when its outputs are needed by downstream layers). So, what if the only use of test_a's output is eliminated during optimization, in which case if you believe that the printf inside test_a should still be executed, WHEN should it happen? It won't happen at the same time as it did before, since the statement that triggered it to run is no longer present. So when? If it can happen at any time before the enclosing shader's outputs are needed, and they aren't, then 'never' ought to be a perfectly fine time to run it.

[brechtvl]

Thanks, that makes sense, and even more so when thinking about the warning() and error() functions, you wouldn't want the overhead of checking if some condition causes an error if the the layer has been optimized out.

[varkenvarken]

Thanks for the explanation & other efforts. I'll see if can write down something for the community at large on Blenderartists with some examples because although this aggressive constant folding is very useful indeed it can also lead to to hard to find issues and indeed make debugging quite tricky (I was actually debugging a shader that didn't alter its outputs so I wanted to print some intermediate variables :-) Ideally there would be a way to temporarily switch of constant folding but I am not aware if there is such an option. Is there?

regards,

-- Michel.

edit: I wrote an article, might be useful to someone;
http://blenderthings.blogspot.nl/2013/06/osl-debugging-tips.html

[brechtvl]

There is an OSL_OPTIONS environment variable that can be set. This particular optimization can be disabled with:

export OSL_OPTIONS="opt_simplify_param=0"

I've also changed Cycles now so that it doesn't set the optimize parameter (since this was setting the same as the default anyway). That will make it possible to do this to turn of all optimizations like this:

export OSL_OPTIONS="optimize=0"

The available options are listed here, there are a bunch more useful ones for debugging:
https://github.com/imageworks/OpenShadingLanguage/blob/master/src/include/oslexec.h

[lgritz]

I strongly recommend turning off optimizations only for specific debugging runs, because the optimizations are really what enables all the good execution speed. Be careful not to leave them turned off once you are done debugging!

Another thing to watch out for: Shader layers are run lazily -- that is, it starts at the end of the list, and upstream layers are run only if and when their outputs are needed. So even if this (or other) optimizations are turned off and the connections are not severed, small changes in the source code of your shader can have big effects on the relative ordering of any printf statements, if they happen in more than one layer. You can turn this off with the option lazylayers=0, which will execute ALL layers, in order. But again, that's very expensive, so use with caution.

[varkenvarken]

@lgritz: good recommendation, in fact I'd even encourage people not to leave any printf calls in production code (but use warn/error for exceptional cases that need reporting) because printing to a console is incredibly slow, especially on windows (that is a general issue, not OSL specific).

@brechtvl: thanks for allowing a user override of OSL_OPTIONS. Tested it on w7-64 r57660 and it works fine from within a command prompt with

set OSL_OPTIONS=optimize=0 <---- note no quotes in windows!
blender

However the more specific options like opt_simplify_param don't seem to work. Not a big deal and I will try to investigate further but from a shader developers point of view having the general one available is probably sufficient and very helpful indeed.

[lgritz]

There are lots of individual optimizations (and switches), and sometimes more than one could potentially achieve the same end of optimizing away a particular statement. opt_simplify_param definitely works, but it may not be the only thing you need to turn off in order to stop this effect on that particular printf.

optimize=1 is also another good choice, it does some things but not others. Sometimes when you use optimize=0, the resulting shader networks (if they are very complex) end up generating too much code and giving you other errors about exceeding the maximum local data use threshold (that prevents runtime stack overflows as you execute shaders).