Skip to content

fixed an error handling in bench_latency.py - #904

Merged
Ying1123 merged 2 commits into
sgl-project:mainfrom
etched-ai:main
Aug 4, 2024
Merged

Ying1123 merged 2 commits into
sgl-project:mainfrom
etched-ai:main

Conversation

@min-xu-et

Copy link
Copy Markdown
Contributor

when running the latency benchmark on a L4 with 24GB of VRAM, the error was not well handled. See before and after below:

before:

[rank0]: Traceback (most recent call last):
[rank0]:   File "<frozen runpy>", line 198, in _run_module_as_main
[rank0]:   File "<frozen runpy>", line 88, in _run_code
[rank0]:   File "/home/min/.cache/sglang/python/sglang/bench_latency.py", line 323, in <module>
[rank0]:     main(server_args, bench_args)
[rank0]:   File "/home/min/.cache/sglang/python/sglang/bench_latency.py", line 288, in main
[rank0]:     work_func(server_args, bench_args, 0)
[rank0]:   File "/home/min/.cache/sglang/python/sglang/bench_latency.py", line 272, in latency_test
[rank0]:     run_once(4)
[rank0]:   File "/home/min/miniconda3/envs/sgl/lib/python3.11/site-packages/torch/utils/_contextlib.py", line 115, in decorate_context
[rank0]:     return func(*args, **kwargs)
[rank0]:            ^^^^^^^^^^^^^^^^^^^^^
[rank0]:   File "/home/min/.cache/sglang/python/sglang/bench_latency.py", line 234, in run_once
[rank0]:     next_token_ids, _, batch = extend(reqs, model_runner)
[rank0]:                                ^^^^^^^^^^^^^^^^^^^^^^^^^^
[rank0]:   File "/home/min/.cache/sglang/python/sglang/bench_latency.py", line 157, in extend
[rank0]:     batch.prepare_for_extend(model_runner.model_config.vocab_size, None)
[rank0]:   File "/home/min/.cache/sglang/python/sglang/srt/managers/schedule_batch.py", line 383, in prepare_for_extend
[rank0]:     self.tree_cache.evict(extend_num_tokens, self.token_to_kv_pool.free)
[rank0]:     ^^^^^^^^^^^^^^^^^^^^^
[rank0]: AttributeError: 'NoneType' object has no attribute 'evict'

after

[gpu=0] Load weight end. type=LlamaForCausalLM, dtype=torch.float16, avail mem=9.30 GB
[gpu=0] Memory pool end. avail mem=4.27 GB
[gpu=0] Capture cuda graph begin. This can take up to several minutes.
max_total_num_tokens=10085
max_batch_size=13
Prefill out of memory. Try to lower your batch size.

@Ying1123 Ying1123 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Currently, it is impossible to see if self.tree_cache is None. The bench_latency file is a hacky way of running model inference using low-level APIs, which skips the step of creating tree_cache.
However, it is also a concern that the --disable-radix option only skips the computation at the lowest level and does not remove everything like tree_cache. It might be better to turn off everything, but in that case, there might not be only one place to change. We are also planning to refactor the tree_cache in a more modular way.

Regardless, the current change is correct and could be part of the complete change. What do you think? @merrymercy

@min-xu-et

Copy link
Copy Markdown
Contributor Author

for benchmarking, maybe it is actually good to be able to run without the cache? That should make the benchmark more deterministic and not affected by caching? IMHO, it is better to have the ability to run things with least dependencies unless tree cache is such a core thing and srt simply can't run without it?

@Ying1123

Ying1123 commented Aug 3, 2024

Copy link
Copy Markdown
Contributor

for benchmarking, maybe it is actually good to be able to run without the cache? That should make the benchmark more deterministic and not affected by caching? IMHO, it is better to have the ability to run things with least dependencies unless tree cache is such a core thing and srt simply can't run without it?

Yes, agree.

@Ying1123 Ying1123 changed the title fixed an error handling fixed an error handling in bench_latency.py Aug 4, 2024
@Ying1123
Ying1123 merged commit 7dd8a7e into sgl-project:main Aug 4, 2024
timethink pushed a commit to timethink/sglang that referenced this pull request Mar 9, 2025
McZyWu pushed a commit to McZyWu/sgl-sglang that referenced this pull request Jul 2, 2026
Modify Multimodal Pressure Test Parameters in the Adaptation Scripts.
efschu pushed a commit to efschu/htsglang that referenced this pull request Aug 26, 2026
…d never joined the transfer that fills it) into the flip train
efschu pushed a commit to efschu/htsglang that referenced this pull request Aug 26, 2026
…, so 411 declines have no verdict

Routing from the write-side agent (sgl-project#872) narrowed Posten 0 correctly: the store
is healthy, 24277 canonical pages live during the R7 window, and the historic
"store is empty" readings probed a path this boot does not use. So the 671
refused walks are a MATCH problem, not a content problem. The question that
follows immediately is the one nobody could answer: a walk that matches nothing
should fall through to an L3 prefetch, and prefetch was attempted on only 264
of 675 sampled walks.

THE OBVIOUS ANSWER IS WRONG, and the code says why. It is tempting to read the
411 as the same MambaComponent refusal declining twice -- one root, two numbers.
It is not:

  * The prefetch anchor IS mamba-gated, but by an aliasing the base contract
    does not describe. base_prefix_cache.py:201-210 separates `last_host_node`
    (the L3 prefetch anchor) from `best_match_node` (the validator-consensus L2
    anchor) -- two fields, two purposes. UnifiedRadixCache sets them equal under
    HiCache (unified_radix_cache.py:1443-1449). Deliberate and commented, but it
    contradicts the field's own documentation, and two fields that are
    documented different and implemented identical are a drift source (sgl-project#747's
    shape). Named, not changed here.
  * Even so, the refusal does NOT decline the prefetch. Total refusal leaves
    best_match_node at the root, and the caller admits the root on purpose:
    `locally_eligible = last_host_node.backuped or last_host_node is
    self.tree_cache.root_node` (scheduler.py:4933-4935). A cold request with no
    match is supposed to prefetch. The first term holds.
  * The second term (>= 256 new tokens) holds for agent prompts of thousands.

That leaves the rate limiter -- AND THERE THE EVIDENCE STOPS, which is the
actual finding. None of the three terms is counted or logged. The 411 declines
are silent. Nobody can attribute them from this boot, and no amount of
re-reading the log will change that.

    eligible = (locally_eligible
                and prefetch_length >= self.prefetch_threshold
                and not self.cache_controller.prefetch_rate_limited())

Three unrelated verdicts wearing one boolean, remedies in three different
files. The sgl-project#914 shape one module over: blame without a defect.

So this is an instrument and NOT a policy change. The three terms are the same
three, evaluated in the same order, with the same outcome; `eligible` is now
`reason is None`, one expression, so the predicate and its explanation cannot
drift apart the way sgl-project#747 records these very lineages drifting. The first
failing term is named rather than all of them -- a request can trip several,
and summing them would double-count exactly as
`refused_tokens_by_component` is documented to.

Not env-gated, unlike the sgl-project#904 match census. That one builds an object and
walks validators a second time, so it pays for itself only when armed. This is
one integer increment on a path that already builds a RadixKey and takes a host
lock -- and a counter you must remember to arm cannot answer "was it ever
tried", which is the whole question. `attempted` is counted alongside the
refusals so the denominator is local (sgl-project#873: a denominator reconstructed from
another log is how a narrowed candidate set reads as a decomposition), and an
unrecorded gate says "no observation" rather than a silent zero (sgl-project#829).

HYPOTHESIS, RECORDED AS ONE. prefetch_capacity_limit is `0.5 *
mem_pool_host.size` (cache_controller.py:729), and that size is not constant
across a phase flip: sgl-project#905 measured the two host tiers at 703472 rows (PP) and
30518 (TP), 23x apart, putting the TP-phase budget near 15259 tokens -- under
four prefetches of the 4096 this window actually completed, against 5
concurrent requests per flip. The order of magnitude fits 411/675, and I am
deliberately not fitting it exactly: the PP phase has ample budget, so the
number cannot come from there alone. If it holds, the same host-tier asymmetry
behind sgl-project#905's double-free is also starving the TP-phase prefetch budget -- one
defect, two effects, to be checked rather than assumed. The counter decides it
on the next boot instead of re-arguing it.

RED-FIRST, four mutants, each red, restored green (14 tests):
  revert to the shipped conjunction (no counter) ......... 4 failed
  eligible computed twice instead of derived from reason . 2 failed
  attempts not counted (denominator lost) ................ 2 failed
  no-observation reported as attempted=0 ................. 1 failed

ONE SELF-INFLICTED DEFECT, found and fixed in the same pass, recorded because
the form is evidently easy to commit. My first version of
test_the_rate_limit_check_is_still_called_at_most_once counted occurrences in
the function's RAW source and went red because a PRE-EXISTING comment at :2674
mentions `prefetch_rate_limited()`. That is the sgl-project#908 substring defect -- prose
used to reach a verdict about code -- in a test of mine, an hour after I
rejected the same form in someone else's patch. Comment lines are now stripped
before counting.

GATE test/registered/unit/mem_cache serial, CVD="": 3 failed, 1950 passed,
1658 skipped. Both axes agree (summary 3, ANSI-stripped extraction 3). Two are
test_acceptance_emitters_758::RefillTiming, baseline-proven pre-existing
earlier in this branch; the third is test_pool_invariant_double_owned_912, a
concurrently-developed test belonging to sgl-project#912 and untouched by this commit.
The sgl-project#904 census suite is green against this change (62 passed together with
the sgl-project#913/sgl-project#914/sgl-project#915 suites), which is the regression that matters: note_refused
gained an optional third argument and its existing callers must not care.
efschu pushed a commit to efschu/htsglang that referenced this pull request Aug 30, 2026
The census (/spinning/gpu-arb/CENSUS_1035_readthrough_chain.md) listed every
gate on the read-through chain with its instrument or BLIND. Three BLIND rows
needed no new mechanism, only exposure, and all three share one shape: a gate
that can ZERO the read path while printing nothing, so a boot where it fired
and a boot where storage was simply cold produce identical logs. That is how
this campaign measured "#cached-token: 0" for weeks without being able to say
which link produced it.

R11 -- unified_radix_cache.py, sgl-project#841 host-only insert declined.
  This is the sgl-project#841 law itself: it marks the whole fetched tail unclaimed and
  returns. It logged at logger.DEBUG, i.e. INVISIBLE on every boot this strand
  runs. Raised to warning, rate-limited, and the line now says the declined
  tail is released rather than published. Cheapest row on the list: a level
  hub, no new logic. The counter it increments already existed.

R13 -- hicache_storage.py, empty KV prefix.
  #1028B fires only when a COMPONENT cap moved the number
  (final_pages != kv_pages). When the KV prefix is itself 0 the claim is
  already zero and NOTHING printed, so "storage genuinely holds nothing for
  this key" and "everything is fine" were the same log. Now named as an honest
  cold miss, explicitly distinguished from a capped claim.

W12 -- staging_write_ring.py, refused admission.
  refused/refused_tokens have been maintained all along, but stats() -- their
  only exposure -- has ZERO callers in the tree, so a write-through page
  refused for want of staging room left no trace anywhere. Nothing can be READ
  back that was never WRITTEN, which makes a silent write-side refusal
  indistinguishable from a read-side miss to whoever debugs the read path
  afterwards. Emitted at the refusal itself rather than waiting for a
  reporting site to be invented.

NOT built, named only (register lines, per the census): R6 symmetric
participation vote returning zero silently; R15/R16 match validators and
dead-node stop (sgl-project#904 exists but is unarmed); W9 -- under write_through
_evict_device_leaf DELETES a childless node outright, taking its mamba anchor
with it, which is a correctness candidate in its own right and not an
instrumenting job.

Check: the failure class here is a NameError on a logger or on an
uninitialised rate-limit attribute, so the check was py_compile on all three
files, a grep asserting each module defines `logger`, and an AST scope check
that every name the three new emitters reference (keys, tokens, matched_length,
total_len, node) is genuinely bound in its enclosing function. All pass.
efschu pushed a commit to efschu/htsglang that referenced this pull request Sep 2, 2026
… per cutover wave

The emission gate was `_dpc_emitted % every == 0` on a process-lifetime
counter with `every` = the shared sgl-project#904 knob (default 64), so the FIRST
[sgl-project#939 double-prefill] line of a boot needed the 64th recording call.
Measured on boot_855_weg1b2 (2026-09-02): two readmit waves, a handful of
calls, ZERO lines -- and the acceptance read that absence as "half B is not
wired" instead of as a rate limit it could not clear.

The section-5 contract is ONE CENSUS PER CUTOVER, so the floor is one LINE
per cutover wave: `_dpc_wave_emitted` forces the first observation after
`reset_double_prefill_census` (the only thing that ends a census) out, and
the periodic sampling plus the always-on breach rule are unchanged on top.

Also documents the launcher knob HICACHE_EXTRA (sgl-project#810 store watermark,
default {"max_size":"200G"}) in docs/dev/WEG1_1068.md section 4; the tree
refuses staging without a watermark (lru_file_evictor.py:151) and boot
weg1b1 died on exactly that.

Evidence (DESK-PROVEN, hermetic, CUDA_VISIBLE_DEVICES=""):
  red on 8bf12cf: 2 failed ("0 not greater than or equal to 2 ... from 2 waves")
  green with the fix: 2 passed
  mutant (drop the wave-flag reset in reset_double_prefill_census): 1 failed
  ruff check: All checks passed!   ruff format --check: 2 files already formatted
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants