baseline working model service and perf tooling

worklogs/2026-07-13-initial-run.md

@@ -0,0 +1,149 @@
+# 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.