Debugging and Profiling filters.python

TL;DR: Print to sys.stderr from inside the function and run pdal pipeline --verbose 4 to see it; wrap the body in cProfile when it is slow; and when the stage produces nothing, check in this order — is the function being called at all, is it returning True, and is the key you wrote into outs spelled exactly as declared.

# Context and Motivation

This guide is part of Programmable Python Filters in PDAL. It exists because the debugging experience inside a filters.python stage is unusually poor: there is no interactive prompt, print appears to go nowhere, an exception surfaces as a C++ error with a truncated traceback, and the most common failure — a dimension that exists and is entirely zero — produces no diagnostic at all.

None of that is unfixable. The stage runs in an ordinary Python interpreter with an ordinary standard library, so every normal tool is available once you know where its output goes. The three techniques below cover essentially every failure people actually hit.

# Prerequisites and Assumptions

# Step-by-Step Implementation

# Step 1 — Get output out of the stage

print goes to stdout, which PDAL may buffer or swallow depending on how it was invoked. sys.stderr is reliable:

import sys

def score(ins, outs):
    print(f"[score] buffer of {len(ins['Z'])} points", file=sys.stderr, flush=True)
    ...

Run with pdal pipeline p.json --verbose 4 and the line appears. If it does not appear at all, the function is not being called — check script and function.

# Step 2 — Count the calls

In streaming mode the function runs once per chunk, and a rule that assumed one call per cloud will behave differently. A module-level counter makes it visible:

_CALLS = 0

def score(ins, outs):
    global _CALLS
    _CALLS += 1
    print(f"[score] call {_CALLS}", file=sys.stderr, flush=True)

# Step 3 — Profile the body when it is slow

import cProfile, pstats, io

def score(ins, outs):
    profiler = cProfile.Profile()
    profiler.enable()
    result = _score_impl(ins, outs)
    profiler.disable()
    buf = io.StringIO()
    pstats.Stats(profiler, stream=buf).sort_stats("cumulative").print_stats(8)
    print(buf.getvalue(), file=sys.stderr)
    return result

The top line is nearly always either a NumPy call doing real work — fine — or a Python-level loop, which is the problem.

# Step 4 — Assert inside the function

An assertion that fires produces a real traceback with your module label, which is far better than a wrong answer:

assert outs["Confidence"].dtype == np.uint8, "dtype drifted from the declaration"
assert len(outs["Confidence"]) == len(ins["Z"]), "output length must match the buffer"

# Complete Working Example

"""A filters.python stage instrumented for diagnosis."""
import io
import os
import sys
import time

import numpy as np

DEBUG = os.environ.get("PDAL_PY_DEBUG") == "1"
_CALLS = 0
_SECONDS = 0.0


def _log(message: str) -> None:
    if DEBUG:
        print(f"[roughness] {message}", file=sys.stderr, flush=True)


def _impl(ins, outs):
    z = ins["Z"]
    # A cheap local roughness proxy: deviation from the buffer median.
    med = np.median(z)
    mad = np.median(np.abs(z - med)) * 1.4826
    scaled = np.zeros_like(z, dtype=np.float32) if mad == 0 else \
        (np.abs(z - med) / mad).astype(np.float32)
    outs["Roughness"] = np.clip(scaled, 0, 1000).astype(np.float32)
    return True


def roughness(ins, outs):
    global _CALLS, _SECONDS
    _CALLS += 1
    started = time.perf_counter()

    n = len(ins["Z"])
    _log(f"call {_CALLS}: {n:,} points")

    result = _impl(ins, outs)

    elapsed = time.perf_counter() - started
    _SECONDS += elapsed
    _log(f"call {_CALLS}: {elapsed * 1000:.1f} ms "
         f"({n / max(elapsed, 1e-9) / 1e6:.1f} M pts/s), total {_SECONDS:.2f} s")

    assert result is True, "impl must return True"
    assert outs["Roughness"].dtype == np.float32, "dtype drifted from the declaration"
    assert len(outs["Roughness"]) == n, "output length must match the input buffer"
    return result

Enable it without editing the pipeline:

PDAL_PY_DEBUG=1 pdal pipeline roughness.json --verbose 4

# Key Parameter Table

# Verification

The instrumentation is off by default. PDAL_PY_DEBUG unset means no output and no profiler. Instrumentation that cannot be left in the repository gets deleted and rewritten every time.

The assertions fire when they should. Deliberately break the dtype — assign float64 — and confirm the assertion raises rather than the pipeline quietly succeeding. An assertion that has never rejected anything proves nothing.

Throughput is where you expect. The logged points-per-second should be in the millions. Anything in the tens of thousands is a Python loop.

# Gotchas and Edge Cases

print to stdout can vanish. Use stderr with flush=True. Buffered output that never flushes is indistinguishable from a function that never ran.

A profiler around a NumPy call tells you very little. cProfile sees one entry taking all the time. Its value is showing you the Python calls, and the giveaway is a call count in the millions.

Module-level state persists across buffers and across tiles in the same process. A counter is fine; a cache keyed by nothing is a memory leak that only appears in a long parallel run.

Exceptions lose their traceback. The module label is what identifies the stage in the error PDAL surfaces, so give every programmable filter a distinct one.

# Frequently Asked Questions

Why does print produce no output from my filter?

Because stdout may be buffered or swallowed depending on how PDAL was invoked. Print to sys.stderr with flush set to True and run the pipeline with --verbose 4. If the marker still does not appear, the function is not being called and the script path or function name is wrong.

My dimension exists but is all zeros — where do I start?

Work through four checks in order: is the function called at all, does it return True, is the key you wrote into outs spelled exactly as declared in add_dimension, and is that name in the writer extra_dims. Each of these produces a run that exits zero, so none of them shows up without an explicit check.

How do I tell whether my function is the bottleneck?

Log the points-per-second the function achieves on each buffer. Vectorised NumPy runs in the millions of points per second; anything in the tens of thousands is a Python loop hiding somewhere in code that looks vectorised.

Is module-level state safe?

For counters and immutable lookups, yes — it persists across buffers and across tiles in the same process, which is usually what you want. A growing cache is a memory leak that only shows up hours into a long parallel run, so keep anything mutable bounded.

# Related

• Programmable Python Filters in PDAL — the parent guide to the stage and its execution model
• Writing a filters.python Stage with NumPy — the function contract these checks assume
• Adding a New Dimension from a Python Filter — the three declarations behind the empty-dimension failure
• Pipeline Validation — catching these failures in CI rather than in production
• Streaming Mode Execution in PDAL — why the call count is not always one