RFC: New tf.print

[tomerk]

Review period open until 2018-09-10

New tf.print

Status	Proposed
Author(s)	Tomer Kaftan (Google)
Sponsor	Asim Shankar (Google)
Updated	2018-08-24

A proposal for a new tf.print operator, as part of TF 2.0 development.

Summary

This doc proposes a new tf.print TensorFlow printing approach that is very
similar to the standard python print API whether or not executing eagerly. It
also provides long-requested functionality for both eager and session-based
execution, such as a more meaningful Tensor summarization, support for printing
nested data structures that contain tensors, and controllable logging levels.

[googlebot]

CLAs look good, thanks!

[facaiy]

Is there any way to print the whole elements of a tensor, say, summarize=None or -1 ?

[tomerk]

We can go ahead and add that functionality.

[karmel]

This doesn't seem much better than tf.Print is right now from a graph perspective. Don't the problems listed out in the overview continue to exist? Except now I don't just have an Identity, I have to control deps.

[tomerk]

From a session-based graph building perspective those problems do continue to exist. My understanding is this is a lower priority to solve if we're moving to an eager & graph function-first world.

We could add support for tf.print as a context manager in session-based graph building mode that automatically adds the control dependency, so users could say:

with tf.print(...):
    ...
    out = ...
session.run(out)

Instead of having to explicitly add it with tf.control_dependencies.

Alternatively, it might be better to suggest that users add the return value of tf.print to their session.run code rather than add control_dependencies, if that's a better user experience. That would be harder w/ control flow and functions in graph mode though.

We could even try implicitly adding tf.prints to a graph collection that automatically gets executed at session.run. I'm more hesitant to do that, because it would require a lot of care with control flow & functions, and to work nicely with graph pruning.

[sharvil]

FWIW, I agree with @karmel and feel that the new proposal is a worse experience for session-based graph users. If solving this problem is a low priority for the team, please reconsider deprecating tf.Print until a better solution is available.

[karmel]

nit: it's potentially slightly confusing to use tensor * 2 as the tensor being printed and here, since it becomes less clear which doubled tensor is being printed below.

[tomerk]

Ah that's true, I can update this example.

[karmel]

This seems like a fairly big caveat. Isn't one of the primary use-cases running in a notebook or similar, when you're debugging some graph/op?

[tomerk]

Yeah, I think so too. There's unfortunately no clean solution because python notebooks don't support this very well. As I mention lower down in the doc:

*  Python notebooks require complex capturing logic to send C++ output to notebook cells, and
    the solutions are often not totally portable across operating systems /
    C++ runtimes.
*  Mixing C++ output and python print output requires regular, careful flushing to prevent things happening in strange orders. This definitely has portability issues.
*   If we want to do something about this, a possible approach could be to
    have the PrintV2 kernel execute a python print if we detect a
    jupyter/colab notebook environment and that the current device has a
    python runtime, rather than using the C++ logging/printing methods.
*   Alternatively, we could provide utilities to capture the C++
    stdout/stderr in Jupyter notebook outputs as a part of TensorFlow.
*   With either approach, we would have to be very careful w/ device placement in distributed
    multi-machine/multi-device settings to ensure that the print device is
    the notebook kernel CPU.

There is some internal tooling for colabs that captures stderr and prints it to the cell output which we could look into releasing. But, it's not perfect and it only flushes/prints the log output once the cell finishes executing. This can be painful w/ long-running execution so we'd need to add a regular poll for flushing.

[karmel]

Does this include data structures with mixed types? Ie, [python int, tensor, python object, python list of tensors...]

[tomerk]

Yes, those print fine as well. I can add some text about that to the description.

[karmel]

In the case of colabs + similar, where do tf.log messages end up going?

[tomerk]

The tf.log messages should end up going to stderr, with extra logging context & the log filtering levels applied. If the device is set to the colab kernel, this should end up in the kernel console stderr logs. (But I can check this to confirm).

[karmel]

Any reason the default placeholder shouldn't reflect "new style" string formatting?

[tomerk]

I'm not totally sure which formatting style on that page you're referring to. If you just mean changing the default placeholder to "{}", that's totally fine and easy to do.

If you mean adding support for positional arguments, for modifiers of the number format, or even for the full-fledged python formatted string literals (https://docs.python.org/3/reference/lexical_analysis.html#f-strings) there's more steps involved. I'm hesitant to spend too much effort on string formatting as part of this design, because the focus of this is on the printing functionality. At the same time, we don't want the API of this design to limit adding better functionality to the strings.format operator in the future.

Below I list a bunch of possibilities for how string formatting could be made more fully-fledged (although I'm not sure if any of these are worthwhile right now):

A lot of complexity comes about from having to combine both python string processing and c++ string processing. We need to process python code to do the python object formatting & template substitution, and then have to use c++ code to process the template with python objects inserted, format tensors, and substitute them into the template.

If you are referring to support for {} and positional arguments: We could carefully combine the nest utilities & python formatting to convert the string into a template that either the c++ abseil strings substitute method or printf in can support.

• The abseil template would only be able to support 10 tensors positionally referenced in the template.
• Printf would be able to support NL_ARGMAX positionally specified tensors (which is implementation-dependent, but is at least 9).
• These would probably be slower than the current strsplit/strcat-based implementation of the kernel, but the absl method should be faster than the printf based one.
• Printf might be more susceptible to security flaws.
• We would have to be careful if any python objects inserted into the template include strings that conflict w/ the printf or absl substitute placeholders. It would probably be easier to escape / modify the printed objects correctly for absl substitute than for printf.

If you mean printf named argument support where tensors in the format string are requested as strings (but python objects may be formatted w/ the number formatting): Same as the above support for {} and positional arguments.

If you mean printf style number formatting for tensors: We would no longer be able to call directly into strsplit/substitute/printf methods. We would need to manually check the string to find where tensors need to be inserted and how their elements should be formatted. We would then need to extend the tensor summarization code w/ support for printing elements using different number formats.

If you mean fully-fledged python f-strings: This would be really hard and would involve manually checking the python environment scopes / manually parsing & rewriting the python code to hook references to tensors.

[karmel]

To clarify, all I meant was having {} be the default, since that also plays nicely with ints, floats, and others by default, whereas %s does not. Plus, one assumes that people will gradually expect that to be the way they write string formatters as py3 takes over.

[karmel]

Can this also support python primitives/objects as the print method does? Imagine:

def my_func(tensor, some_param=5)
  raise ValueError(tf.string.format("You passed in {} with param {}, which is not allowed", (tensor, my_param))

Seems easier than having to tf.string.format the tensor, then normal-string-format that with the param.

[tomerk]

See my above comment on supporting {} and positional arguments. This is definitely possible, but there would be some caveats caused by using absl string substitute or the c++ printf.

[karmel]

You mean tf.print here presumably?

[tomerk]

Yes, will update that!

[karmel]

This seems like it will be a confusing gotcha for users. Is there some way to indicate that the value is stale?

[tomerk]

I just ran this by @akshayka, and this actually shouldn't be an issue.
Non-eager tf control flow doesn't support modifying python objects anyway, and the tfe.defun graph functions should automatically detect that the cached value is stale and will re-generate the ops.

I'll remove this caveat from the doc.

[karmel]

Design Review notes

• Most comments were addressed in the existing CLs
• Concerns that in graph mode, tf.print is still painful
  • Could use context -- with tf.print-- but that's not better.
  • Any way to get automatic control deps? defun.
  • This concern mostly goes away in 2.0, so fine to leave as-is for now.
  • → Include defun example, test
• For the registration of the op, no special formatting for now-- just a placeholder attribute. Seems fine for now.
• There is an explicit with device(cpu); is this a problem?
  • joshl: Seems like it will fix more than it breaks.
  • apassos: not safe for non-eager TPU code.
  • There are places this would help-- GPU code block in eager.
  • Then user should specify with cpu
  • Eager should respect soft placement, but that's a separate issue
  • → Remove explicit device placement
• Concerns about memory/performance if you are copying tensor to print onto CPU?
  • Turn off printing for performance; that is expected
  • But memory? Shouldn't be a concern generally. If the tensor fits on the GPU, it will fit on the CPU it is being transferred to.
  • Don't worry for now. If we need to add summary ops later, we can
• Add a deprecation warning to tf.Print

[mitar]

I do not think this is a good design, if we want compatibility with Python logging. Currently, the caller of the tf.print decides what is an output stream. This is I think not good. Ideally, using tf.print you would just send data to be printed/logged. And then from a central location you could configure exactly where and how and which levels should be logged. It should not be a role of the tf.print to decide if something should go to stderr or logging stream. It should maybe just set a level of the message.

In this way, in libraries, we can have clear and standard way to log messages. And then users of libraries they can configure in which way they want to display those message (iPython output, stderr, stdout, redirect to Python logging, saving to database, whatever).

[ewilderj]

@tomerk are there notes from the review meeting to add to this PR comment thread? and are there any updates?

pending adding those, I'm ready to merge this.

[tomerk]

Hi @ewilderj, @karmel added the notes above. Before merging I still need to figure out if it makes sense to do anything re @mitar's comment first, or if that should come later (e.g. having tf.print default to None as the logging level, in which case it would look it up from a global config.)

[ewilderj]

Great, thanks. Sorry I missed the notes. Please feel free to ping me when further action is needed.

[tomerk]

Okay, so:
@mitar Thank you for your suggestion! To do it we would need to set up some sort of global configuration for Tensorflow logging & automated print op device placement (e.g. see the concerns mentioned in the doc re: printing in colabs). We've decided that this is out of scope for this specific design doc. However, we can always look into extending tf.print's default behavior in the future to support this.
@ewilderj you're free to merge this now, thank you!

[mitar]

However, we can always look into extending tf.print's default behavior in the future to support this.

How do you see this being possible, if you we now train everyone to hard-code where to output logs. Then later on we will have a problem or ignoring what they explicitly requested (output to stdout) or not being able to suppress it.

I really believe that providing to a community tooling here is critical because otherwise it will be so much noise that this logging will become useless. Especially in code where TF is used deep inside some other codebase.

Also, why not simply building this on top of Python logging. Then TF does not have to reinvent anything here. Just use Python logging and TF can be just a Python logger.

[tomerk]

Hi @mitar ,
W/ regards to not training users improperly now: I'll run it by some folks again to see about making the output_stream kwarg default to None instead of stderr, and perhaps adding a default_print_output_stream to the context (which itself would default to stderr).

As for your second question, as well as why adding python-based printing & custom logging functionality tf.print would be out of scope for this specific document:
Building tf.print on top of python print itself (using tf.py_func) was my first inclination as well.
Unfortunately we can't naively build tf.print like this because that places an operator in the graph whose device requires a python runtime. This would cause issues when running in distributed settings, on TPU devices, on embedded devices, and when using non-python front-ends.

So, properly adding support for this would require configuration options to determine if there is a python runtime, and what device is the client. The print / string_format operator placement then needs to carefully happen according to these configurations. At the same time, we would still need to support exporting the graph to environments without python runtimes, so we would have to be careful to make sure this doesn't cause device placement issues for the exported graphs.

Additionally, the operator kernel itself would need to know whether to switch between a py_func for printing and the C++ logging operations. We would probably still need to maintain some level of consistency between the functionality of both.

This is somewhat related both to the "Device Locations" section in the document, and the various caveats mentioned w/ respect to Colabs.

[mitar]

I'll run it by some folks again to see about making the output_stream kwarg default to None instead of stderr, and perhaps adding a default_print_output_stream to the context (which itself would default to stderr).

I think this would be better. Or maybe even not having output_stream in the print, but just have it configured through the context?

[ewilderj]

@tomerk I'll wait a re-confirmation, if you're making changes as per the recent comments.

[tomerk]

Hi @ewilderj, a follow up on all this:
tf.print now successfully prints to colab notebooks, as a result of adding a Log listener registration mechanism to the Tensorflow C api that is used by tf.print, and registering a listener in interactive environments that prints to the Python stdout.

For now though we will be leaving output_stream in the tf.print's api because it matches how python's own print method works. If people want to extend this in the future they will be able to extend Tensorflow's source with new log listeners, or to expose interactive python log listener registration in more than just interactive environments, and do whatever they want with python's stdout.

[ewilderj]

Thanks for the update.

So to be clear, will this design proposal be resumed, or should I just archive it?