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

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.