# 2026-07-13 Initial Run Worklog

## Working Rules

- Local repository is the source of truth for code changes.
- Remote Phanthy GPU server is used for build, runtime, and validation.
- Every meaningful experiment records: code version, command, environment, result, issue, and next action.
- Changes should be committed with git after a coherent milestone or before risky experiments.

## Remote Target

- Host: `ssh-55c3b0b3.default.gpu.phanthy.com`
- SSH requires TLS ProxyCommand on port `32222`.
- User: `root`

## Status

- Local repository inspected.
- SSH connectivity confirmed with `whoami` and `hostname`.
- Remote environment inspected.

## Remote Environment Findings

- Remote shell user: `root`
- Remote hostname: `cc-55c3b0b3-8c03-4fe2-8ef8-7109a6aff0d6-0`
- Remote appears to already be inside a container.
- `docker` is not installed in the remote runtime container.
- CoreX is installed under `/usr/local/corex -> /usr/local/corex-3.2.3`.
- Iluvatar devices are visible as `/dev/iluvatar0` through `/dev/iluvatar3`.
- PyTorch is available only when `PYTHONPATH` and `LD_LIBRARY_PATH` include CoreX paths.
- PyTorch reports `torch.cuda.is_available() == True` and `torch.cuda.device_count() == 4`.
- Model path found: `/root/public-storage/models/Qwen/Qwen3.6-35B-A3B`.
- Model `config.json` already has `architectures: ["Qwen3_5MoeForCausalLM"]`.
- Because remote has no Docker, first run will patch the current runtime directly instead of building an image.

## First Run Plan

1. Sync only lightweight submission files to `/root/work/enginex-vllm-bi100-qwen36`.
2. Backup target runtime files before applying `qwen3_6_scripts/patch_ops.sh`.
3. Apply patches in the remote CoreX container.
4. Start OpenAI-compatible API server against `/root/public-storage/models/Qwen/Qwen3.6-35B-A3B`.
5. Run minimal smoke tests before deeper compatibility tests.

## 2026-07-14 First Patch Attempt Diagnosis

- User-provided remote log showed repeated `$'\r': command not found` in `patch_ops.sh`.
- Root cause: the shell script, and likely copied `.py` patch helpers, arrived on Linux with Windows CRLF line endings.
- Consequence: `python3 ./patch_model_runner.py\r` and similar patch commands did not execute correctly.
- Later server startup failed with `unrecognized arguments: --reasoning-parser qwen3`.
- Interpretation: OpenAI API runtime files such as `cli_args.py` and `api_server.py` were not patched into `/usr/local/corex/lib/python3/dist-packages/vllm/...`.
- Next action: normalize CRLF to LF on the remote copy, rerun `patch_ops.sh`, verify `--reasoning-parser` exists in the installed vLLM CLI, then restart the API server.

## 2026-07-14 First Server Start After CRLF Fix

- User verified `python3 -m vllm.entrypoints.openai.api_server --help | grep reasoning-parser` now prints `--reasoning-parser`.
- Startup log shows `reasoning_parser='qwen3'`, so OpenAI API argument patch is active.
- `ixsmi` shows no vLLM GPU process and `/health` returns `Connection refused`, so the API server process exited before serving.
- Need inspect the tail of `/root/work/logs/server_first_run.log` after `Downcasting torch.float32 to torch.float16`.
- Additional suspicion to verify: some patches target `/usr/local/corex/lib/python3/dist-packages` while the Qwen3_5 registry patch targets `/usr/local/corex/lib64/python3/dist-packages`; confirm the actual imported registry path and whether both `lib` and `lib64` contain `Qwen3_5MoeForCausalLM`.

## 2026-07-14 Server Still Initializing

- User checked `jobs -l` and `ps`; master process PID 2052 is still running.
- Log has no `Traceback`, `ERROR`, or common fatal exceptions.
- Log reached `Worker ready; awaiting tasks` for three worker processes, so multiprocess executor startup is progressing.
- Both `/usr/local/corex/lib/.../vllm` and `/usr/local/corex/lib64/.../vllm` contain `registry.py` patched with `Qwen3_5MoeForCausalLM`, and `qwen3_5.py` exists in both.
- Earlier `/health` failure was likely checked before API server finished engine initialization and started listening.
- Next action: wait and monitor model loading/GPU memory, then retry `/health`; only diagnose hang if no new log/GPU memory movement for several minutes.

## 2026-07-14 Port Occupied By Stale First Process

- User started a second server while PID 2052 from the first run was still alive.
- Second run exited with `OSError: [Errno 98] Address already in use` at `sock.bind(("", args.port))`.
- `ps` still shows PID 2052 holding the API server command, but `ixsmi` shows no model GPU memory/processes.
- Interpretation: PID 2052 is a stale or stuck master process occupying port 1111, not a healthy loaded model service.
- Next action: stop PID 2052 and any VllmWorkerProcess children, verify port 1111 is free, restart once with a fresh log filename, then wait for explicit `Uvicorn running` / startup-complete logs before testing `/health`.

## 2026-07-14 New Instance Startup Fix

- New host: `ssh-8d2ae743.default.gpu.phanthy.com`.
- Initial failure: `api_server.py: error: unrecognized arguments: --reasoning-parser qwen3`.
- Cause 1: new instance runtime had not yet applied `qwen3_6_scripts/patch_ops.sh`.
- Applied `patch_ops.sh`; `cli_args.py` in both `/usr/local/corex/lib/...` and `/usr/local/corex/lib64/...` then contained `--reasoning-parser`.
- Cause 2: service was started from repository root `/root/data-disk-1/enginex-vllm-bi100-qwen36`, whose local `./vllm` package shadowed the patched CoreX runtime vLLM.
- Fix: start service from `/root` and set CoreX `PYTHONPATH`/`LD_LIBRARY_PATH`, using `python3 -B` to avoid stale bytecode.
- Working log: `/root/work/logs/server_from_root_B.log`.
- Health check reached `GET /health HTTP/1.1" 200 OK`.
- Minimal `/v1/chat/completions` request reached `POST /v1/chat/completions HTTP/1.1" 200 OK`.
- `ixsmi` shows model loaded at roughly 29GB per BI-V100 card.

## 2026-07-14 Baseline Smoke And Mini Benchmark

- Remote benchmark script copied to `/root/work/remote_smoke_bench.py`.
- Result file: `/root/work/logs/baseline_smoke_20260713_195201.json`.
- `/health` status: `200`.
- Non-stream smoke request: `200`, 16 completion tokens in `2.41s`, about `6.63 tok/s`.
- Streaming 3-run summary:
  - TTFT average: `1.03s`.
  - TTFT P90 from 3 samples: about `0.80s` using the simple small-sample estimator.
  - Output TPS after TTFT: about `8.91 tok/s`.
- Prefix-cache probe:
  - First long-prefix request: `cached_tokens=0`, 16 completion tokens in `6.59s`.
  - Second related long-prefix request: `cached_tokens=1056 / 1069 prompt tokens`, 16 completion tokens in `3.61s`.
  - Server metrics also reported GPU prefix cache hit rate around `50.36%`.
- Current status: model is fully runnable and API-compatible enough for smoke tests, but generation throughput is far below the contest target of Output TPS P10 >= 20.
- First performance direction: reduce thinking-token waste, profile decode path, verify XFormers fallback cost, then tune serving parameters after a larger benchmark.

## 2026-07-14 Official-Like Benchmark Dataset Preparation

- Current repository dataset `chat_dataset_v0.json` is only a 4-conversation smoke dataset.
- It has short multi-turn chat/role-play prompts and no realistic `tools`, assistant `tool_calls`, or `tool` role messages.
- It is not representative of the official benchmark, which is an 881-request long-context Agent coding workload.
- Added `worklogs/formal_perf_bench.py` support for OpenAI-style request items with `messages`, `tools`, `tool_choice`, `stream`, and per-request `max_tokens`.
- Added `worklogs/generate_official_like_dataset.py` to synthesize official-like long-context, stream=true, tool-heavy requests.
- Uploaded updated scripts to:
  - `/root/work/formal_perf_bench.py`
  - `/root/work/generate_official_like_dataset.py`
- Server smoke generation succeeded:
  - `/root/work/logs/synthetic_agent_perf_16.jsonl`
  - 16 requests, 13 sessions, approx prompt average `26611.5`, approximate weighted cache ratio `0.638`.
  - File size `4.5M`.

## 2026-07-14 Official-Like Synthetic Benchmark Round 1

- Fixed synthetic request format issues:
  - Assistant tool-call messages now use `content: ""` instead of `content: null`.
  - Synthetic system/context content is merged into a single leading system message because the current runtime rejects multiple system messages with `System message must be at the beginning`.
  - Added `--max-prompt-tokens` to cap generated prompt sizes under the current server `--max-model-len 100000`.
- Generated dataset:
  - `/root/work/logs/synthetic_agent_perf_16_fixed2_cap90k.jsonl`
  - 16 requests, approximate average prompt tokens `25712`, approximate intended cache ratio `0.637`.
- Benchmark:
  - Command output file: `/root/work/logs/perf_synth16_fixed2_cap90k_c1_r4.json`.
  - Concurrency `1`, requests `4`, max output tokens `64`.
- Results:
  - Success rate: `100%` (`4/4`).
  - Prompt tokens total: `166080`.
  - Completion tokens total: `256`.
  - Cached tokens total: `96`.
  - Actual cache hit rate: `0.058%`, far below official-like target; generator does not yet create exact cumulative session-prefix reuse.
  - TTFT P90: `129.07s`.
  - Output TPS P10 per request: `5.23 tok/s`.
  - Aggregate output TPS: `0.607 tok/s`.
  - Aggregate uncached input TPS: `393.52 tok/s`.
  - Weighted token throughput: `1111.78`, far below `8000`.
- Interpretation:
  - Long-context uncached prefill is the immediate bottleneck.
  - Current synthetic generator must be improved to make same-session adjacent requests share exact prefix, otherwise cache behavior is not representative of the official 65.6% cached-token workload.
  - Current runtime also needs template compatibility work for multiple/irregular system messages if official requests include them unmodified.

## 2026-07-14 Cumulative Prefix Synthetic Benchmark Round 2

- Added `--cumulative` mode to `generate_official_like_dataset.py`.
- New mode shares exact system/tool prefix and grows each session history in place, so same-session later requests actually reuse earlier token prefixes.
- Generated dataset:
  - `/root/work/logs/synthetic_cumulative_8_s3_cap40k.jsonl`
  - 8 requests, 3 sessions, approximate prompt average `27452.75`.
  - Prompt cap `40000` to keep test runtime manageable under current `--max-model-len 100000`.
- Benchmark:
  - Result file: `/root/work/logs/perf_cumulative8_s3_cap40k_c1_r4.json`.
  - Concurrency `1`, requests `4`, max output tokens `64`.
- Results:
  - Success rate: `100%` (`4/4`).
  - TTFT P90: `58.49s`.
  - Output TPS P10 per request: `5.94 tok/s`.
  - Aggregate output TPS: `1.55 tok/s`.
  - Aggregate uncached input TPS: `284.96 tok/s`.
  - Aggregate cache TPS: `296.87 tok/s`.
  - Cached tokens: `49152 / 96333`, cache hit rate `51.02%`.
  - Weighted token throughput: `989.82`.
- Target comparison:
  - Cache hit rate and success rate pass.
  - TTFT, Output TPS P10, and weighted throughput are far below target.
- Interpretation:
  - Prefix cache is now being exercised correctly, but cached prefill is still too slow at this configuration.
  - Current serving parameter `--max-num-seqs 1` prevents useful concurrent batching and likely caps weighted throughput.
  - Decode path is also slow: request-level output TPS only `5.9-8.5 tok/s`.
  - Next experiment should restart service with higher `--max-num-seqs`, higher `--max-num-batched-tokens`, and possibly `gpu-memory-utilization 0.95`, then rerun the same cumulative dataset.

## 2026-07-14 Serving Parameter Experiment: seq2 / batched8192

- Restarted service from `/root` with:
  - `--gpu-memory-utilization 0.95`
  - `--max-num-seqs 2`
  - `--max-num-batched-tokens 8192`
  - same model, tensor parallel `4`, prefix cache, chunked prefill, and qwen3 parsers.
- Service started successfully:
  - Log file: `/root/work/logs/server_exp_seq2_b8192.log`
  - Process id observed: `2710`
  - GPU blocks: `21100`, CPU blocks: `6553`

### Concurrency 2 result

- Benchmark:
  - Dataset: `/root/work/logs/synthetic_cumulative_8_s3_cap40k.jsonl`
  - Result file: `/root/work/logs/perf_cumulative8_s3_cap40k_exp_seq2_c2_r4.json`
  - Concurrency `2`, requests `4`, max output tokens `64`.
- Results:
  - Success rate: `100%`.
  - TTFT P90: `58.51s`.
  - Output TPS P10 per request: `0.87 tok/s`.
  - Aggregate output TPS: `1.53 tok/s`.
  - Cache hit rate: `43.22%`.
  - Weighted token throughput: `1076.71`.
- Interpretation:
  - Raising concurrency to `2` harms per-request decode speed and does not improve TTFT on this small long-context test.
  - Cache hit rate also drops below target because overlapping requests disturb the ideal same-session sequential cache path.

### Concurrency 1 result

- Benchmark:
  - Dataset: `/root/work/logs/synthetic_cumulative_8_s3_cap40k.jsonl`
  - Result file: `/root/work/logs/perf_cumulative8_s3_cap40k_exp_seq2_c1_r4.json`
  - Concurrency `1`, requests `4`, max output tokens `64`.
- Results:
  - Success rate: `100%`.
  - TTFT P90: `3.34s`.
  - Output TPS P10 per request: `6.10 tok/s`.
  - Aggregate output TPS: `5.50 tok/s`.
  - Cache hit rate: `99.97%`.
  - Cached tokens: `96304 / 96333`.
  - Weighted token throughput: `1252.05`.
- Interpretation:
  - With warm/exact prefix cache reuse, TTFT and cache-hit targets can pass.
  - Output TPS is still far below the `>=20` target, so the next optimization area is decode throughput.
  - Weighted throughput remains far below `8000`; this requires either much higher input/cache throughput under realistic scheduling or substantially faster decode.

## 2026-07-14 Failed Decode Scheduler Experiment: multi-step

- Investigated available CoreX/vLLM parameters from `/root/work/logs/api_server_help.txt`.
- Tried adding:
  - `--num-scheduler-steps 4`
  - existing `--enable-chunked-prefill`
- Result:
  - Service failed during startup.
  - Log file: `/root/work/logs/server_exp_sched4_seq2_b8192.log`
  - Error: `Multi-Step + Chunked-Prefill not supported for attention backend: xformers`.
  - The runtime suggests `flash-attn`, but current service logs show `Using XFormers backend`.
- Recovery:
  - Restarted the previously working `seq2/b8192` service without `--num-scheduler-steps`.
  - Recovery log file: `/root/work/logs/server_exp_seq2_b8192_recover.log`
  - `/health` returned `200`.
  - Server log recorded a short `/v1/chat/completions` request returning `200 OK`.
- Interpretation:
  - Multi-step scheduling is not available with the current xFormers + chunked-prefill path.
  - Next decode optimization should focus on either enabling a compatible attention backend, checking whether chunked prefill can be disabled for a decode-focused variant, or optimizing parser/reasoning/tool overhead before deeper code changes.

## 2026-07-14 Decode Microbenchmark Round

- Added local and remote script:
  - Local: `worklogs/decode_microbench.py`
  - Remote: `/root/work/decode_microbench.py`
- Synced raw result JSON files to:
  - `worklogs/remote_results/2026-07-14-decode/`
- Wrote Chinese analysis report:
  - `worklogs/decode_analysis_report_2026-07-14.md`
- Key results:
  - Full parser, short prompt, concurrency 1, 256 output tokens: Output TPS P10 `8.74 tok/s`, TTFT P90 `1.85s`.
  - Full parser with 29 tools, concurrency 1, 128 output tokens: Output TPS P10 `8.70 tok/s`, TTFT P90 `4.98s`.
  - Parser-off, short prompt, concurrency 1, 256 output tokens: Output TPS P10 `8.30 tok/s`, TTFT P90 `3.18s`.
  - Parser-off concurrency curve with 128 output tokens:
    - c1: aggregate Output TPS `8.00`, per-request P10 `8.30`.
    - c2: aggregate Output TPS `7.23`, per-request P10 `3.68`.
    - c4: aggregate Output TPS `5.08`, per-request P10 `2.57`, TTFT P90 `51.60s`.
  - c2 with `ixsmi` sampling: average GPU utilization `28.91%`, max GPU utilization `100%`, average power `49.67W`.
- Interpretation:
  - Tool/reasoning parser is not the decode throughput bottleneck.
  - Increasing concurrency does not improve aggregate decode throughput and worsens per-request TPS.
  - Low average GPU utilization suggests scheduling, TP synchronization, MoE kernel, paged attention, or xFormers backend limitations before raw compute saturation.
  - Next focused experiment: disable chunked prefill and retry `--num-scheduler-steps 4` as a decode-only diagnostic variant.

## 2026-07-14 Multi-Step Scheduling Diagnostic

- Goal: verify whether `--num-scheduler-steps 4` can improve decode throughput.
- Appended details to:
  - `worklogs/decode_analysis_report_2026-07-14.md`
- Synced remote failure logs to:
  - `worklogs/remote_results/2026-07-14-scheduler/`
- Experiments:
  - No chunked prefill + `max_model_len=100000` failed because `max_num_batched_tokens=8192` is smaller than `max_model_len=100000`.
  - No chunked prefill + `max_model_len=4096` still failed because `Multi-Step not supported for attention backend: xformers`.
  - Forced `VLLM_ATTENTION_BACKEND=FLASHINFER` failed because `BatchDecodeWithPagedKVCacheWrapper` was `None`, indicating FlashInfer dependencies/wrappers are unavailable or incompatible.
- Conclusion:
  - Multi-step scheduling cannot currently be tested or used on this server because the available attention backend is xFormers.
  - The next practical direction is not more `num_scheduler_steps` tuning, but either making FlashAttention/FlashInfer backend available or profiling the current xFormers + MoE + TP decode path.
- Recovery:
  - Restored full parser service with chunked prefill and prefix cache.
  - Recovery log: `/root/work/logs/server_exp_seq2_b8192_fullparser_restored_after_schedtest.log`.
  - `/health` returned `200`.