Simstim

Houdini

printf debugging a million points: how VEX formats strings and where the output goes

A printf in a Houdini VEX wrangle runs once per point, in parallel. What each format specifier really prints in Houdini 22, where the output goes, and why a string attribute or a guarded print beats flooding the console.

· 9 min read · houdini · vex · tutorial · vex fundamentals

Ten lines of real hython console output from a VEX printf, beside a Karma render of the 10 by 10 grid whose points printed them.

TL;DR VEX, Houdini's C-like language, runs a wrangle once per point, in parallel, so a printf in it behaves like a printf inside a GPU kernel: one line per point, arriving in blocks, in no fixed order. This post covers what printf and sprintf format strings actually do in Houdini 22 (the argument's type matters more than the letter), where the output goes, and why a string attribute you can read in the Geometry Spreadsheet is usually the better debugger.

Houdini in 60 seconds

Houdini stores a 3D model as tables. Points are positions, primitives are faces or curves built from those points, vertices are the corners linking a primitive to its points, and detail is one global row. Each column is an attribute: P (position), v (velocity), or anything you make up. You process geometry in SOPs (surface operators), which are nodes in a graph. The Attribute Wrangle SOP is a text box where you write VEX. Its Run Over setting picks which table the code iterates over. With Points, the snippet is the body of a loop over every point, and Houdini runs it in parallel across cores, much like a compute shader or a NumPy ufunc.

That's the catch for this topic. Inside a wrangle, printf doesn't run once. It runs once per element.

The core idea: C format strings, VEX types

printf and sprintf take a format string that will look familiar to anyone who has written C: %[flags][width][.precision]type. Here is what each conversion in the Houdini 22 docs printed when we ran it:

  • %d and %i print ints. %x and %X print hex with a 0x prefix that C doesn't add (255 prints as 0xff and 0xFF), and %o prints octal with a leading zero (0377).
  • %f, %e and %E print floats, and they also take vectors and matrices, formatting each component: %.3f on {1, 2.5, -3} prints {1.000,2.500,-3.000}.
  • %s prints a string.
  • %g and %p print the "general" form of anything. A vector prints as {1,2.5,-3}, a matrix3 as {1,0,0 0,1,0 0,0,1} (rows separated by spaces), an array as {1, 2, 3} and a dict as indented JSON.
  • %c is listed with %g in the docs, but it printed a character for an int (65 gives A) and nothing at all for a float, a vector or a string.
  • The flags are - (left-justify), 0 (zero pad) and +. A * takes the width or precision from the argument list.

Two things work differently from C, and both matter when you're debugging:

  1. The argument's type decides the formatting more than the letter does. %d on a float printed 3.14159, %s on an int printed 255, and %d on a vector printed the whole vector. Nothing warns you about any of it. A letter VEX doesn't know (%a, %b, %ld) prints as the bare letter, a specifier with no argument left prints as-is, and extra arguments are ignored. None of these is a compile error. One undocumented curiosity: %v isn't a vector format. It printed varying for v@P and uniform for a constant, a glimpse of the compiler's own bookkeeping about which values differ from point to point.
  2. The + flag quotes strings. On a number it forces the sign. On a string it wraps the value in quotes, so %+10s gives "abcdef" and %+s on an empty string gives "". That makes empty strings and trailing spaces visible in a log.

sprintf takes the same arguments but returns the string instead of printing it. Day to day, that's where most of the value is: file paths, node names, labels and padded frame numbers. sprintf("frame.%04d.exr", 42) returns frame.0042.exr.

What trips you up, and what clicks

  1. One line per point, in blocks, in no fixed order. A printf in a point wrangle runs for every point. On a 90,000-point grid, printf("%d\n", @ptnum) printed all 90,000 lines with none garbled, but in blocks of 1,024 consecutive points, and the blocks came out in a different order on each cook. (A 100-point grid printed in order.) It's slow, too: printing every point of a 100,000-point grid took 13.6 seconds against 0.05 seconds without the print, in hython with the output going to a file. In a SideFX forum thread on VEX debugging, one user reports crashing Houdini "many times" by printing to the console. The fix is the same as in a CUDA kernel: guard the print with an index check (if (@ptnum == 0)) or print every Nth element. Printing every 1,000th point cost 0.055 seconds. For a single message, print_once() prints once per cook, not once per point.
  2. "The console" depends on how you launched Houdini. The docs say printf "Prints values to the console which started the VEX program." In hython, Houdini's command-line Python, the lines go to the process's standard output. On Windows, the Houdini application opens its own floating console window for this output (the HOUDINI_DISABLE_CONSOLE environment variable turns that off). On Linux and macOS, the output goes to the terminal you started Houdini from, so start it from a shell if you want to see anything. Tomori's tutorial suggests the -foreground flag; the Houdini 22 help says that flag keeps Houdini from handing the terminal back to the shell. The output never shows up on the node itself: a wrangle that only prints has no messages, warnings or errors.
  3. Attributes are a better debugger. Instead of printing, sprintf a label into a string attribute and open the Geometry Spreadsheet, Houdini's table view of the attributes. It shows every element, it stays there after the cook, and clicking a column header sorts by that column. A Marker visualizer set to Text draws attribute values as labels in the viewport. It's much closer to inspecting a DataFrame than reading a log, and it's the advice a SideFX forum regular gives in the thread above.
  4. Backslashes are processed twice; @ isn't processed at all. In a Houdini 22 wrangle a normal VEX string goes through escape processing twice, once before VEX receives the snippet and once in the compiler. Plain vcc processes escapes only once (len("a\\b") is 3 there and 2 in a wrangle), so it is the wrangle. "\\n" is a newline, and a literal backslash followed by n takes four backslashes, "\\\\n". Tomori's tutorial pointed out the extra backslashes in 2018. Raw strings, r"..." and R"(...)", print exactly what you typed. His tutorial also escapes @ inside strings as \@. That's no longer needed: printf("a @P b\n") prints a @P b and creates no attribute, and \@ still works.
  5. warning() and error() report through the node. Both take printf format strings. Each distinct message from warning() becomes one line of the node's warning: 1,000 points running warning("pt %d", @ptnum) gave a 1,000-line warning, while 1,000 identical messages collapsed to one. The docs' caveat is fair: "It's quite easy to accidentally report thousands of different warnings." error() fails the cook, so the node outputs no geometry and shows your message. print_once() doesn't format at all: print_once("once %d\n", @ptnum) printed once %d, so wrap the message in sprintf if you need values in it.
Two scatter plots of printed point number against output line number for two cooks of the same 90,000-point wrangle; most lines fall on the diagonal, but the early part of each cook arrives as short, shuffled segments.
The order of 90,000 printf lines from two cooks of the same wrangle, as in item 1. Each segment is a run of consecutive points; the runs start on multiples of 1,024 and come out in a different order each time.

Code: debug labels instead of console spam

Make an Attribute Wrangle with Run Over: Points and feed it a Grid. The code reads velocity, so put another wrangle between them with v@v = set(@ptnum * 0.2, 0, 0);, which gives speeds from 0 to 19.8. (A Point Velocity SOP on a grid that doesn't move gives all zeros.) Paste the code, then click the Create spare parameters button to the right of the code editor to get the print_every parameter. It starts at 0, which prints nothing, so set it to 10.

// Attribute Wrangle, Run Over: Points
// Write a readable label on every point; print only a sample.
int every = chi("print_every");      // spare int parm; 0 prints nothing, try 10

// v@v is velocity. If the input has none, this read creates it as {0,0,0}.
float speed = length(v@v);

// sprintf returns a string: zero-padded point number, 3-decimal speed
string label = sprintf("pt %05d |v|=%.3f", @ptnum, speed);
s@debug = label;                     // inspect in the Geometry Spreadsheet

if (every > 0 && @ptnum % every == 0) {
    // %g prints a vector as a braced triple
    printf("%s  P=%g\n", label, v@P);
}

if (speed > 10.0)
    warning("pt %d is moving fast: %g", @ptnum, speed);

On the default 10 × 10 grid, this is the whole console output:

pt 00000 |v|=0.000  P={-5,0,-5}
pt 00010 |v|=2.000  P={-5,0,-3.88889}
pt 00020 |v|=4.000  P={-5,0,-2.77778}
pt 00030 |v|=6.000  P={-5,0,-1.66667}
pt 00040 |v|=8.000  P={-5,0,-0.555555}
pt 00050 |v|=10.000  P={-5,0,0.555556}
pt 00060 |v|=12.000  P={-5,0,1.66667}
pt 00070 |v|=14.000  P={-5,0,2.77778}
pt 00080 |v|=16.000  P={-5,0,3.88889}
pt 00090 |v|=18.000  P={-5,0,5}

The node's warning has 49 lines, from pt 51 is moving fast: 10.2 to pt 99 is moving fast: 19.8, and every point carries its debug label in the spreadsheet. Two VEX details hide in the guard. Integer % by zero doesn't fail in VEX (it returns 0, so @ptnum % 0 == 0 would print every point), and && evaluates both sides, so the every > 0 test is what keeps the print off, not a short circuit.

For comparison, here's the same pattern in NumPy: label everything, print a sample.

import numpy as np
P = np.random.rand(1000, 3); v = np.random.rand(1000, 3) * 20
speed = np.linalg.norm(v, axis=1)
debug = [f"pt {i:05d} |v|={s:.3f}" for i, s in enumerate(speed)]
for i in range(0, len(P), 100):
    print(debug[i], "P=", P[i])

The difference is that in VEX the loop is implicit and parallel, so the if is the only thing between you and one line per point.

Try it yourself

  1. Install Houdini Apprentice, the free, non-commercial edition from SideFX.
  2. Build the Grid → velocity wrangle → debug wrangle chain above, set print_every to 10, then open the Geometry Spreadsheet and click the debug column header to sort by it.
  3. Change %05d to %-8d and %s to %+s, then print a matrix3 with %g to see how its rows are laid out.
  4. No Houdini? Run the NumPy version, then try the same thing with Blender's bpy over mesh.vertices. You'll end up with the same "label everything, print a sample" pattern.

The next post in this series looks at vector swizzling.

Functions used: printf, sprintf, print_once, warning, error, chi, length. Each one links to its entry in the Simstim VEX reference.

Sources

Related

  1. HoudiniStage in, stage out: Houdini's Solaris treats every node as a function over a USD sceneIn Houdini's Solaris, every LOP node takes a composed USD stage and returns one, and its edits land in one in-memory layer at the top. A 31-line usd-core model of that contract, the Python LOP that does it for real, the same network checked in Houdini 22, and why a Layer Break decides what gets saved. · 10 min read
  2. Houdinisplit() is a tokenizer: building cache paths from strings in Houdini VEXVEX strings look like Python's, but split() merges separators and drops empty fields, len() counts bytes, and a wrangle expands $ before the compiler sees it. A per-piece cache path built from the scene file name, and the traps along the way, checked in Houdini 22. · 10 min read
  3. LatestMaterialX is an IR for materials: build a typed shader graph in Python, then lower it to GLSL and OSLA MaterialX material is a typed dataflow graph stored as XML, which a library type-checks and compiles to several shading languages. With only pip install MaterialX, build a checkerboard material in Python, watch the validator reject a float wired into a color, and generate GLSL and OSL from the same file. · 9 min read