Fix tmctl report: materialize request_log rows so they outlive the query context that defer-cancel tore down mid-iteration
This commit is contained in:
parent
c4676d53dc
commit
56c2f5a61c
4 changed files with 101 additions and 16 deletions
|
|
@ -109,22 +109,14 @@ func report(cfgPath string) error {
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return err
|
return err
|
||||||
}
|
}
|
||||||
defer rows.Close()
|
|
||||||
|
|
||||||
fmt.Printf("%-20s %-8s %-12s %-22s %8s %8s %8s %8s %8s %10s %8s %-8s %-5s %-3s\n",
|
fmt.Printf("%-20s %-8s %-12s %-22s %8s %8s %8s %8s %8s %10s %8s %-8s %-5s %-3s\n",
|
||||||
"ts", "stage", "role", "model", "prompt", "cached", "cwrite", "compl", "reason", "cost_usd", "ms", "finish", "tmhit", "ok")
|
"ts", "stage", "role", "model", "prompt", "cached", "cwrite", "compl", "reason", "cost_usd", "ms", "finish", "tmhit", "ok")
|
||||||
for rows.Next() {
|
for _, row := range rows {
|
||||||
var ts, stage, role, model, finish string
|
|
||||||
var prompt, cached, cwrite, compl, reason, latency, tmhit, ok int
|
|
||||||
var cost float64
|
|
||||||
if err := rows.Scan(&ts, &stage, &role, &model, &prompt, &cached, &cwrite, &compl, &reason, &cost, &latency, &finish, &tmhit, &ok); err != nil {
|
|
||||||
return err
|
|
||||||
}
|
|
||||||
fmt.Printf("%-20s %-8s %-12s %-22s %8d %8d %8d %8d %8d %10.6f %8d %-8s %-5d %-3d\n",
|
fmt.Printf("%-20s %-8s %-12s %-22s %8d %8d %8d %8d %8d %10.6f %8d %-8s %-5d %-3d\n",
|
||||||
ts, stage, role, model, prompt, cached, cwrite, compl, reason, cost, latency, finish, tmhit, ok)
|
row.TS, row.Stage, row.Role, row.ModelActual, row.PromptTokens, row.CachedTokens,
|
||||||
}
|
row.CacheCreationTokens, row.CompletionTokens, row.ReasoningTokens, row.CostUSD,
|
||||||
if err := rows.Err(); err != nil {
|
row.LatencyMS, row.FinishReason, row.TMHit, row.OK)
|
||||||
return err
|
|
||||||
}
|
}
|
||||||
|
|
||||||
committed, reserved, err := r.Store.SpentUSD(r.Book.BookID)
|
committed, reserved, err := r.Store.SpentUSD(r.Book.BookID)
|
||||||
|
|
|
||||||
|
|
@ -2,7 +2,6 @@ package store
|
||||||
|
|
||||||
import (
|
import (
|
||||||
"context"
|
"context"
|
||||||
"database/sql"
|
|
||||||
"log/slog"
|
"log/slog"
|
||||||
|
|
||||||
"textmachine/backend/internal/obs"
|
"textmachine/backend/internal/obs"
|
||||||
|
|
@ -70,13 +69,51 @@ func (s *Store) LogRequest(ctx context.Context, log *slog.Logger, rl RequestLog)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
// RequestLogRows returns rows for inspection (tmctl report / приёмка Фазы 0).
|
// RequestLogView is one request_log row for inspection (tmctl report).
|
||||||
func (s *Store) RequestLogRows(bookID string) (*sql.Rows, error) {
|
type RequestLogView struct {
|
||||||
|
TS string
|
||||||
|
Stage string
|
||||||
|
Role string
|
||||||
|
ModelActual string
|
||||||
|
PromptTokens int
|
||||||
|
CachedTokens int
|
||||||
|
CacheCreationTokens int
|
||||||
|
CompletionTokens int
|
||||||
|
ReasoningTokens int
|
||||||
|
CostUSD float64
|
||||||
|
LatencyMS int
|
||||||
|
FinishReason string
|
||||||
|
TMHit int
|
||||||
|
OK int
|
||||||
|
}
|
||||||
|
|
||||||
|
// RequestLogRows returns all request_log rows for a book (tmctl report / приёмка
|
||||||
|
// Фазы 0). Строки МАТЕРИАЛИЗУЮТСЯ под op-таймаутом и возвращаются срезом —
|
||||||
|
// отдавать *sql.Rows нельзя: ленивая итерация у вызывающего переживает
|
||||||
|
// `defer cancel()` этого метода, и контекст отменяется ПОСРЕДИ чтения
|
||||||
|
// («context canceled», обрыв таблицы report — находка реальной приёмки).
|
||||||
|
func (s *Store) RequestLogRows(bookID string) ([]RequestLogView, error) {
|
||||||
ctx, cancel := opContext()
|
ctx, cancel := opContext()
|
||||||
defer cancel()
|
defer cancel()
|
||||||
return s.r.QueryContext(ctx, `
|
rows, err := s.r.QueryContext(ctx, `
|
||||||
SELECT ts, stage, role, model_actual, prompt_tokens, cached_tokens,
|
SELECT ts, stage, role, model_actual, prompt_tokens, cached_tokens,
|
||||||
cache_creation_tokens, completion_tokens, reasoning_tokens,
|
cache_creation_tokens, completion_tokens, reasoning_tokens,
|
||||||
cost_usd, latency_ms, finish_reason, tm_hit, ok
|
cost_usd, latency_ms, finish_reason, tm_hit, ok
|
||||||
FROM request_log WHERE book_id = ? ORDER BY id`, bookID)
|
FROM request_log WHERE book_id = ? ORDER BY id`, bookID)
|
||||||
|
if err != nil {
|
||||||
|
return nil, err
|
||||||
|
}
|
||||||
|
defer rows.Close()
|
||||||
|
var out []RequestLogView
|
||||||
|
for rows.Next() {
|
||||||
|
var v RequestLogView
|
||||||
|
if err := rows.Scan(&v.TS, &v.Stage, &v.Role, &v.ModelActual,
|
||||||
|
&v.PromptTokens, &v.CachedTokens, &v.CacheCreationTokens,
|
||||||
|
&v.CompletionTokens, &v.ReasoningTokens, &v.CostUSD,
|
||||||
|
&v.LatencyMS, &v.FinishReason, &v.TMHit, &v.OK); err != nil {
|
||||||
|
return nil, err
|
||||||
|
}
|
||||||
|
out = append(out, v)
|
||||||
|
}
|
||||||
|
return out, rows.Err()
|
||||||
}
|
}
|
||||||
|
|
|
||||||
|
|
@ -178,6 +178,33 @@ func TestJobKeepsOriginalSnapshot(t *testing.T) {
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// RequestLogRows обязан вернуть ВСЕ строки, читаемые вызывающим ПОСЛЕ возврата
|
||||||
|
// метода: раньше он отдавал *sql.Rows с `defer cancel()`, и контекст отменялся
|
||||||
|
// посреди ленивой итерации в tmctl report («context canceled», обрыв таблицы —
|
||||||
|
// находка реальной приёмки Фазы 0).
|
||||||
|
func TestRequestLogRowsMaterializes(t *testing.T) {
|
||||||
|
s, _ := openTemp(t)
|
||||||
|
for i := 1; i <= 3; i++ {
|
||||||
|
if err := s.InsertRequestLog(RequestLog{BookID: "book", Stage: "draft", PromptTokens: 10 * i, OK: true}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
// Строка другой книги не должна попасть в выборку.
|
||||||
|
if err := s.InsertRequestLog(RequestLog{BookID: "other", Stage: "draft", OK: true}); err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
rows, err := s.RequestLogRows("book")
|
||||||
|
if err != nil {
|
||||||
|
t.Fatal(err)
|
||||||
|
}
|
||||||
|
if len(rows) != 3 {
|
||||||
|
t.Fatalf("want 3 materialized rows, got %d (context canceled mid-iteration?)", len(rows))
|
||||||
|
}
|
||||||
|
if rows[0].PromptTokens != 10 || rows[2].PromptTokens != 30 {
|
||||||
|
t.Fatalf("rows not in id order or wrong data: %+v", rows)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
func TestMigrateIsIdempotent(t *testing.T) {
|
func TestMigrateIsIdempotent(t *testing.T) {
|
||||||
path := filepath.Join(t.TempDir(), "test.db")
|
path := filepath.Join(t.TempDir(), "test.db")
|
||||||
for i := 0; i < 3; i++ {
|
for i := 0; i < 3; i++ {
|
||||||
|
|
|
||||||
|
|
@ -152,6 +152,34 @@ per-chunk skip+flag вместо падения; структурный запр
|
||||||
|
|
||||||
Следующее: Фаза 1 (перевод книги целиком) — чанкер, банк памяти v1, гейты (пороги полигона готовы), режим онгоинга.
|
Следующее: Фаза 1 (перевод книги целиком) — чанкер, банк памяти v1, гейты (пороги полигона готовы), режим онгоинга.
|
||||||
|
|
||||||
|
### Реальная приёмка на живых ключах — PASS (04.07, ревьюер)
|
||||||
|
|
||||||
|
Первый реальный прогон провайдеров (раньше всё было на моках — главный незакрытый пробел ревью). `tmctl translate`
|
||||||
|
на `example/book.yaml` (draft=deepseek-v4-flash → edit=glm-5, один чанк 264 симв., потолок $1.00):
|
||||||
|
- **Деньги сходятся до цента**: draft $0.000219 (453·0.14+556·0.28/1e6 ✓), edit $0.001277 (672·1.0+189·3.2/1e6 ✓);
|
||||||
|
`committed == Σстадий == $0.001496`, `reserved=0`. Порядок величин совпал с прайсингом DeepSeek/z.ai.
|
||||||
|
- **Цена по ответившей**: z.ai вернул `model=glm-5` → edit книжится по цене GLM, НЕ по дешёвому deepseek-якорю
|
||||||
|
(fallback дал бы $0.000147 — в 8.7× меньше); `PriceForResponse` подтверждён на реале.
|
||||||
|
- **Usage реальный**, не мок: `prompt/completion_tokens` ненулевые в request_log; GLM латентность штатная (5–8 с,
|
||||||
|
без ×3) → `extra_body thinking:{type:disabled}` фактически применён.
|
||||||
|
- **Resume**: второй прогон — обе стадии из чекпоинтов за **$0**, ledger неизменен (нет двойной оплаты).
|
||||||
|
- **Пост-ревью правки провалидированы**: F1 (CheckKeys — заводится на 2 ключах), F2 (provider temp/maxtok в
|
||||||
|
snapshot), F5 (fail-loud на включённый гейт), F7 (сноска §3.4) — все на месте; Anthropic вычищен из конфигов,
|
||||||
|
висячих ссылок нет (в `BuildClient` ветка `case "anthropic"` осталась, но `kind: anthropic` в models.yaml нет).
|
||||||
|
|
||||||
|
**Новая находка реальной приёмки (исправлена):** `tmctl report` рвался с `context canceled` и печатал таблицу
|
||||||
|
частично/пусто без строки Ledger (exit 1). Причина — `Store.RequestLogRows` отдавал `*sql.Rows` с `defer cancel()`:
|
||||||
|
контекст отменялся посреди ленивой итерации у вызывающего. Данные и деньги в БД были корректны — баг только на
|
||||||
|
read-пути `report`. Фикс: строки материализуются под таймаутом и возвращаются срезом `[]RequestLogView`;
|
||||||
|
регрессионный тест `TestRequestLogRowsMaterializes`. `go test ./... -race` зелёные.
|
||||||
|
|
||||||
|
**Не покрыто реальным прогоном (честно):** (а) DeepSeek cache-hit парсинг — resume короткозамыкает вызов, так что
|
||||||
|
реального повторного prefix-хита не было; закрыт только unit-тестом `TestDeepSeekCacheFieldsVariant` (форсить
|
||||||
|
реальный хит = лишние траты, не гнал); (б) kill-9 посреди реального провайдерского вызова — инвариант
|
||||||
|
`committed==SUM(checkpoints)` доказан unit-тестом `kill9_test.go` (настоящий SIGKILL на SQLite), на реале не
|
||||||
|
воспроизводил (деньги/один-чанк дисциплина). (в) Anthropic cache_control/usage-сумма — Anthropic из стека убран,
|
||||||
|
проверять больше нечего на этом контуре.
|
||||||
|
|
||||||
## Полигон
|
## Полигон
|
||||||
(секция параллельной сессии — записи добавлять сюда)
|
(секция параллельной сессии — записи добавлять сюда)
|
||||||
|
|
||||||
|
|
@ -175,6 +203,7 @@ per-chunk skip+flag вместо падения; структурный запр
|
||||||
|
|
||||||
- **llama.cpp `--n-cpu-moe` для 30b-a3b — перемерено, «Расхождение» с research/06 подтверждено**: потолок генерации на GTX 1070 **~13.5 tok/s** (не 25–30). Таблица конфигов в [03](experiments/03-local-stand.md): ollama 10 → llama.cpp `--cpu-moe` 11.2 → `--n-cpu-moe 33` 13.5 (VRAM 2.9→7.8GB, prefill 105→208). Узкое место — пропускная способность CPU-RAM (DDR4/Pascal), не рантайм; llama.cpp честно лучше ollama (+35% ген., ×2–3 prefill), но 30b-a3b на этом железе — только фоновые роли (~2.5 мин/главу). Скрипт: `eval/llama_moe_bench.sh`.
|
- **llama.cpp `--n-cpu-moe` для 30b-a3b — перемерено, «Расхождение» с research/06 подтверждено**: потолок генерации на GTX 1070 **~13.5 tok/s** (не 25–30). Таблица конфигов в [03](experiments/03-local-stand.md): ollama 10 → llama.cpp `--cpu-moe` 11.2 → `--n-cpu-moe 33` 13.5 (VRAM 2.9→7.8GB, prefill 105→208). Узкое место — пропускная способность CPU-RAM (DDR4/Pascal), не рантайм; llama.cpp честно лучше ollama (+35% ген., ×2–3 prefill), но 30b-a3b на этом железе — только фоновые роли (~2.5 мин/главу). Скрипт: `eval/llama_moe_bench.sh`.
|
||||||
- **Замер 4 новых dense-моделей** (ваниль qwen3:8b / qwen3.5:9b / +abliterated / ruadapt) — готово, таблица в [03](experiments/03-local-stand.md). Три вывода: (1) **абляция бесплатна** — qwen3.5 vanilla vs abliterated идентичны по скорости и SFW-качеству → 18+-роль можно на abliterated без штрафа; (2) поколение 3.5>3 умеренно (лучше понимание, −25% токенов, −10% скорости); (3) **RuAdapt: токен-выигрыш подтверждён (−40% ru-токенов), но перевод развалился** (羅生門→«дерево с колокольчиками») → редактор ru-стиля, не переводчик (как и предупреждал research/06). Разрыв с API держится у всех. **Побочная находка для бэкенда:** thinking у Qwen3.5+/GLM/Gemini для роли переводчика обязателен к отключению (иначе пустой/обрезанный вывод — ловилось дважды: эксп. 02 и здесь).
|
- **Замер 4 новых dense-моделей** (ваниль qwen3:8b / qwen3.5:9b / +abliterated / ruadapt) — готово, таблица в [03](experiments/03-local-stand.md). Три вывода: (1) **абляция бесплатна** — qwen3.5 vanilla vs abliterated идентичны по скорости и SFW-качеству → 18+-роль можно на abliterated без штрафа; (2) поколение 3.5>3 умеренно (лучше понимание, −25% токенов, −10% скорости); (3) **RuAdapt: токен-выигрыш подтверждён (−40% ru-токенов), но перевод развалился** (羅生門→«дерево с колокольчиками») → редактор ru-стиля, не переводчик (как и предупреждал research/06). Разрыв с API держится у всех. **Побочная находка для бэкенда:** thinking у Qwen3.5+/GLM/Gemini для роли переводчика обязателен к отключению (иначе пустой/обрезанный вывод — ловилось дважды: эксп. 02 и здесь).
|
||||||
|
- **Think-режим (проверка гипотезы владельца «reasoning поднимет качество в разы»)** — [03](experiments/03-local-stand.md), раздел «Влияние thinking». Итог: (а) прежняя «пустота» — артефакт тесного контекста (рассуждения не влезали с ответом), не зависание; (б) с ctx 16k think **завершается и реально чинит реалии** (羅生門: «Радзёмон»→«Рашо-мон»; 朱雀 с китайского чтения на японское) — гипотеза частично подтвердилась; (в) но локально нежизнеспособен: 8,6 мин и ~11k токенов рассуждений на 1400 знаков (вебновелла ≈ 200 ч). **Новый пункт бэклога → оркестратору/бэкенду: проверить think-ON vs OFF по КАЧЕСТВУ на быстром облачном черновике/редакторе (DeepSeek/GLM)** — потенциальный дешёвый рычаг качества, раз reasoning вытаскивает реалии.
|
||||||
|
|
||||||
### Следующие шаги полигона
|
### Следующие шаги полигона
|
||||||
- [x] Прогон refusal-бенчмарка (SFW/L1/L2-violence часть) — 66/66 ok, пороги в 02; explicit-часть ждёт фрагментов владельца.
|
- [x] Прогон refusal-бенчмарка (SFW/L1/L2-violence часть) — 66/66 ok, пороги в 02; explicit-часть ждёт фрагментов владельца.
|
||||||
|
|
|
||||||
Loading…
Add table
Reference in a new issue