Skip to content

AST extraction progress line's final "100%" silently switches denominator (total_files instead of len(uncached_work)) — looks like the file count changed mid-run #1693

Description

@sub4biz

Summary

During graphify extract, the intermediate AST extraction: X/Y uncached files (Z%) progress lines
report against len(uncached_work) — only the files that actually need AST processing this run. The
final line switches denominator to total_files — the full corpus of files the detector classified
as code, including files that never entered uncached_work at all. When any files have no registered
extractor for their extension, this makes the total jump upward right after 98-99%, which reads as
inconsistent output rather than a deliberate change in what's being measured.

Evidence

Real terminal output from a full rebuild (graphify extract . --backend deepseek --model deepseek-v4-flash --token-budget 60000 --max-concurrency 32 on a ~20.6k-code-file monorepo):

AST extraction: 20300/20524 uncached files (98%) [8 workers]
AST extraction: 20400/20524 uncached files (99%) [8 workers]
AST extraction: 20500/20524 uncached files (99%) [8 workers]
AST extraction: 20608/20608 files (100%) [8 workers]

Denominator silently changes from 20524 to 20608 between the last two lines — an 84-file jump with
no explanation printed anywhere.

Ruled out as a caching artifact: we initially suspected leftover cache surviving an incomplete
delete (the runner script does Remove-Item -Recurse -Force graphify-out -ErrorAction SilentlyContinue before a full rebuild, and SilentlyContinue would mask a partial-delete failure on
locked files). Checked directly — the graphify-out directory's own creation timestamp matched the
exact start of this run, and the AST cache subdirectory (cache/ast/v0.9.6/, versioned by
_pkg_version("graphifyy")) only began filling ~40s later as the first workers completed. No pre-existing
cache entries were present at the time uncached_work was computed, so the 84-file gap is not a
cache-hit count.

Root cause

Found by reading extract.py directly. The Phase-1 classification loop (extract.py:16358-16368, 0.9.6: 16100-16110):

for i, path in enumerate(paths):
    if _get_extractor(path) is None:
        per_file[i] = {"nodes": [], "edges": []}
        continue                          # <- skipped BEFORE cache check, never in uncached_work
    bypass_cache = path.suffix in _JS_CACHE_BYPASS_SUFFIXES
    if not bypass_cache:
        cached = load_cached(path, effective_root)
        if cached is not None:
            per_file[i] = cached
            continue                      # <- a real cache hit, also never in uncached_work
    uncached_work.append((i, path))

_get_extractor() (extract.py:16081-16120, 0.9.6: 15840-15865) returns None for any file extension with no entry in the
_DISPATCH table (extract.py:15685+) — and every entry in that table is a tree-sitter-backed
extractor (extract_python's own docstring: "via tree-sitter AST"; the module imports
tree_sitter_python, tree_sitter_verilog, tree_sitter_sql, tree_sitter_julia,
tree_sitter_fortran, etc.). So concretely: these are files whose extension has no registered
tree-sitter grammar in graphify
, not files that failed to parse — they're skipped before any parsing
is attempted. There's no generic fallback extractor for an unrecognized code extension. Meanwhile the
file-type detector upstream already classified these same files as "code" and counted them toward
total_files. Such files get an instant empty placeholder ({"nodes": [], "edges": []}) and are
excluded from uncached_work — identically to how a genuine cache hit is excluded — but without
touching the cache at all.

The progress-printing code then uses two different counts for what is presented as the same metric:

  • Intermediate, parallel path — extract.py:16237-16239 (0.9.6: 15981-15982):
    f"  AST extraction: {done_count}/{len(uncached_work)} uncached files "
    f"({done_count * 100 // len(uncached_work)}%) [{max_workers} workers]"
  • Intermediate, sequential path — extract.py:16279 (0.9.6: 16022, same pattern, different function):
    f"  AST extraction: {work_idx}/{len(uncached_work)} uncached files ({work_idx * 100 // len(uncached_work)}%)"
  • Final, parallel path — extract.py:16258 (0.9.6: 16001):
    f"  AST extraction: {total_files}/{total_files} files (100%) [{max_workers} workers]"
  • Final, sequential path — extract.py:16293 (0.9.6: 16035, same pattern):
    print(f"  AST extraction: {total_files}/{total_files} files (100%)", flush=True)

total_files and uncached_work are two independent parameters passed into these functions
(extract.py:16170,16174 in _extract_parallel, and 16265,16268 in _extract_sequential; 0.9.6:
15913,15917 and 16008,16011) — the code never reconciles or explains the difference between them in the
printed output.

Suggested fix

The cleanest fix is to make the denominator consistent across all four lines, and make the final
line explain the skip count rather than let it appear silently. This isn't just about making the
numbers add up — it's about the user being able to tell, from the output alone, why the total changed
without having to go read the source. Two reasonable ways to get there:

  1. Use total_files throughout, including the intermediate lines, and annotate the final line with
    a breakdown of what was skipped and why:
    AST extraction: 20608/20608 files (100%) — 84 skipped (no extractor), 0 skipped (cached) [8 workers]
    
    Treat cache hits and no-extractor files as already-done from the start of the counter (progress
    starts at (total_files - len(uncached_work))/total_files instead of 0/len(uncached_work)), so
    every line in the stream reports against the same number, and the one place the skip count matters
    (the final summary) spells out the reason instead of leaving it to be inferred from a denominator
    jump.
  2. Keep len(uncached_work) throughout, including the final line, and print the same breakdown as
    a preamble before the loop starts instead of at the end — e.g. "Skipping 84 files with no extractor and N cached; processing {len(uncached_work)} of {total_files} files". This keeps the percentage
    math simple (always out of the same denominator) while still surfacing the total_files number
    with its reason, just earlier in the stream rather than folded into the final line.

Either approach needs the two skip reasons (no-extractor vs. cache-hit) tracked as separate counters
during Phase 1 (extract.py:16358-16368, 0.9.6: 16100-16110) so the message can name them individually rather than only
reporting their sum.

Additional suggestion — surface this at the start, not just the end, and name the extensions.
Phase 1 (extract.py:16358-16368, 0.9.6: 16100-16110) already knows the full skip list before any AST work begins — it's
a plain classification loop over paths, with no dependency on extraction actually running. There's no
need to wait until the final line to mention skipped files at all; a preamble printed right after Phase
1 completes (before Phase 2 starts processing uncached_work) could report both the count and
which extensions had no tree-sitter grammar, e.g.:

Skipping 84 files with no tree-sitter grammar for their extension: .proto (41), .thrift (12), .m4 (9), ... (8 more extensions)

This turns "84 files disappeared somewhere" into something a user can act on directly (e.g. decide
whether one of those extensions is worth a future extractor, or whether the files are irrelevant
vendored/generated content that should just be .graphifyignored). Grouping by extension only needs a
collections.Counter keyed on path.suffix for the files that hit the _get_extractor(path) is None
branch — cheap to add alongside the existing count.

Either way, the fix needs to be applied to both the parallel and sequential code paths
(_extract_parallel/_extract_sequential), since they duplicate the same print pattern independently.

Status check (2026-07-06, updated after upgrading to 0.9.7 the same day)

Checked 0.9.7 release notes (GitHub) — this specific denominator/progress-line issue is not mentioned as
fixed. Re-verified directly against 0.9.7 source (upgraded locally, local patch for #1621 reapplied
separately in llm.py — unaffected by this file): the underlying bug and code pattern are unchanged, but
extract.py shifted substantially in this release (Ruby/JS/TS extraction work per the 0.9.7 changelog) —
every line number in this report has been updated to the current 0.9.7 location, with the original 0.9.6
line kept alongside for reference. The four-line denominator-mismatch pattern itself is byte-for-byte the
same logic, just relocated.

Environment

  • Originally observed on graphifyy 0.9.6; line numbers re-verified current as of 0.9.7 (see status check
    above). Behavior itself not re-run on 0.9.7 (original repro was on 0.9.6).
  • graphify extract . --backend deepseek --model deepseek-v4-flash --token-budget 60000 --max-concurrency 32 (full rebuild, run.ps1 wrapper) on a ~20.6k-code-file polyglot monorepo
  • Observed consistently; reporter notes the same denominator-switch behavior recurred across earlier
    graphify versions on this same corpus, not a one-off

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions