git.giacomolli.uk - onechat/blob - probe.go

   1 package main
   2
   3 import (
   4         "bufio"
   5         "cmp"
   6         "context"
   7         "encoding/json"
   8         "errors"
   9         "fmt"
  10         "io"
  11         "maps"
  12         "os"
  13         "path/filepath"
  14         "slices"
  15         "strconv"
  16         "strings"
  17         "time"
  18 )
  19
  20 const (
  21         // probeName is the agent name of a probe run. The cache key comes from
  22         // it.
  23         probeName = "Probe"
  24
  25         // probeQuotaLimit is how many points the used percent of a quota window
  26         // can grow in a probe run before the run stops.
  27         probeQuotaLimit = 15.0
  28
  29         // probeCallLimit is the most model calls of a probe run.
  30         probeCallLimit = 660
  31
  32         // probeLineBytes is the most bytes of one line of a probe log.
  33         probeLineBytes = 1 << 20
  34 )
  35
  36 // probe runs "onechat probe LOG COUNT [BUILDS]". It appends the first COUNT
  37 // messages of LOG, one JSON object {kind, text} per line, to a new chat in
  38 // probe/ in the data directory, and builds its tree with the real compactor.
  39 // Before each user message it waits for the builds, as a turn does. It stops at
  40 // the first failed call, after probeCallLimit calls, or when the used percent
  41 // of a quota window grows by more than probeQuotaLimit points. At the end it
  42 // reports the calls, the time per call, the calls at once, the cached share,
  43 // the quota, the retries, and the line sizes. BUILDS, from 1 to maxBuilds,
  44 // limits the builds that call the model at once in this run only. The core
  45 // still queues up to maxBuilds builds.
  46 func probe(ctx context.Context, args []string, out io.Writer) error {
  47         if len(args) != 2 && len(args) != 3 {
  48                 return errors.New("usage: onechat probe LOG COUNT [BUILDS]")
  49         }
  50
  51         count, err := strconv.Atoi(args[1])
  52         if err != nil || count <= 0 {
  53                 return fmt.Errorf("COUNT %q is not a positive number", args[1])
  54         }
  55
  56         builds := maxBuilds
  57         if len(args) == 3 {
  58                 builds, err = strconv.Atoi(args[2])
  59                 if err != nil || builds < 1 || builds > maxBuilds {
  60                         return fmt.Errorf("BUILDS %q is not a number from 1 to %d", args[2], maxBuilds)
  61                 }
  62         }
  63
  64         entries, err := readProbeLog(args[0], count)
  65         if err != nil {
  66                 return err
  67         }
  68
  69         dir, err := dataDir()
  70         if err != nil {
  71                 return err
  72         }
  73
  74         config, err := loadConfig(dir)
  75         if err != nil {
  76                 return err
  77         }
  78
  79         address, auth, err := modelEndpoint(config, dir)
  80         if err != nil {
  81                 return err
  82         }
  83
  84         root := filepath.Join(dir, "probe", time.Now().Format("20060102-150405"))
  85         err = os.MkdirAll(root, 0o700)
  86         if err != nil {
  87                 return fmt.Errorf("create probe directory: %w", err)
  88         }
  89
  90         usagePath := filepath.Join(root, "usage.jsonl")
  91         client := newClient(address, auth, "onechat-"+probeName, usagePath)
  92         client.LimitCalls(probeCallLimit)
  93         summarizer := slotSummarizer{
  94                 inner: newCompactor(client, probePrompt, config.Compactor),
  95                 slots: make(chan struct{}, builds),
  96         }
  97
  98         memory, err := openMemory(ctx, root, time.Now, summarizer)
  99         if err != nil {
 100                 return err
 101         }
 102
 103         _, err = fmt.Fprintf(out, "probe: %d messages into %s with %s at %s effort, %d builds at once\n", len(entries), root, config.Compactor.Model, config.Compactor.Effort, builds)
 104         if err != nil {
 105                 return errors.Join(err, memory.Close())
 106         }
 107
 108         run := probeRun{
 109                 memory:    memory,
 110                 client:    client,
 111                 usagePath: usagePath,
 112         }
 113
 114         appended, stop := run.Run(ctx, entries)
 115         sizes, err := modelLines(memory)
 116         err = errors.Join(err, memory.Close())
 117         if err != nil {
 118                 return err
 119         }
 120
 121         records, err := readUsageFile(usagePath)
 122         if err != nil {
 123                 return err
 124         }
 125
 126         return writeProbeReport(out, appended, stop, records, sizes)
 127 }
 128
 129 // probeRun appends the messages of a probe run to its chat and stops the run
 130 // by the rules of probeStop.
 131 type probeRun struct {
 132         memory    *Memory
 133         client    *Client
 134         usagePath string
 135 }
 136
 137 // Run appends the entries. It waits for the builds only before a user message,
 138 // as a turn does, so up to maxBuilds builds run at once in between, and it
 139 // waits for all builds at the end. It returns the number of messages appended
 140 // and why the run stopped early, or "" when it did not. After a stop it waits
 141 // for the calls in flight, so no sent call is cancelled.
 142 func (r *probeRun) Run(ctx context.Context, entries []probeEntry) (int, string) {
 143         appended, reason := r.append(ctx, entries)
 144         if reason == "" {
 145                 return appended, ""
 146         }
 147
 148         err := r.memory.Wait(ctx)
 149         if err != nil {
 150                 reason += "; " + err.Error()
 151         }
 152
 153         return appended, reason
 154 }
 155
 156 // append appends the entries and stops at the first stop rule.
 157 func (r *probeRun) append(ctx context.Context, entries []probeEntry) (int, string) {
 158         for n, entry := range entries {
 159                 if entry.Kind == "user" {
 160                         reason := r.wait(ctx)
 161                         if reason != "" {
 162                                 return n, reason
 163                         }
 164                 }
 165
 166                 _, err := r.memory.Append(entry.Kind, entry.Text)
 167                 if err != nil {
 168                         return n, err.Error()
 169                 }
 170
 171                 reason := r.check()
 172                 if reason != "" {
 173                         return n + 1, reason
 174                 }
 175         }
 176
 177         return len(entries), r.wait(ctx)
 178 }
 179
 180 // wait returns when no build runs, or when a stop rule ends the run. It checks
 181 // the rules each second, so a run stops soon also during a long wait.
 182 func (r *probeRun) wait(ctx context.Context) string {
 183         for {
 184                 reason := r.check()
 185                 if reason != "" {
 186                         return reason
 187                 }
 188
 189                 waitCtx, cancel := context.WithTimeout(ctx, time.Second)
 190                 err := r.memory.Wait(waitCtx)
 191                 cancel()
 192                 if err == nil {
 193                         return r.check()
 194                 }
 195
 196                 if ctx.Err() != nil {
 197                         return ctx.Err().Error()
 198                 }
 199         }
 200 }
 201
 202 // check returns why the run must stop, or "" when it can go on.
 203 func (r *probeRun) check() string {
 204         if r.client.LimitReached() {
 205                 return fmt.Sprintf("call limit of %d reached", r.client.limit)
 206         }
 207
 208         records, err := readUsageFile(r.usagePath)
 209         if err != nil {
 210                 return err.Error()
 211         }
 212
 213         return probeStop(records)
 214 }
 215
 216 // slotSummarizer lets at most cap(slots) builds call inner at once. A build
 217 // past the limit waits for a slot.
 218 type slotSummarizer struct {
 219         inner Summarizer
 220         slots chan struct{}
 221 }
 222
 223 // Summarize waits for a slot and builds the node with inner.
 224 func (s slotSummarizer) Summarize(ctx context.Context, task Task) (string, error) {
 225         select {
 226         case s.slots <- struct{}{}:
 227         case <-ctx.Done():
 228                 return "", ctx.Err()
 229         }
 230
 231         defer func() {
 232                 <-s.slots
 233         }()
 234
 235         return s.inner.Summarize(ctx, task)
 236 }
 237
 238 // probePrompt returns the system prompt of a probe run: the prompt of the agent
 239 // probeName, without instructions.
 240 func probePrompt() (string, error) {
 241         return prompt(probeName, ""), nil
 242 }
 243
 244 // probeEntry is one message of a probe log.
 245 type probeEntry struct {
 246         Kind string `json:"kind"`
 247         Text string `json:"text"`
 248 }
 249
 250 // readProbeLog reads the first count messages of the probe log at path.
 251 func readProbeLog(path string, count int) (entries []probeEntry, err error) {
 252         file, err := os.Open(path)
 253         if err != nil {
 254                 return nil, fmt.Errorf("open probe log: %w", err)
 255         }
 256
 257         defer func() {
 258                 err = errors.Join(err, file.Close())
 259         }()
 260
 261         scanner := bufio.NewScanner(file)
 262         scanner.Buffer(make([]byte, 64*1024), probeLineBytes)
 263         for len(entries) < count && scanner.Scan() {
 264                 var entry probeEntry
 265                 err = json.Unmarshal(scanner.Bytes(), &entry)
 266                 if err != nil {
 267                         return nil, fmt.Errorf("probe log line %d: %w", len(entries)+1, err)
 268                 }
 269
 270                 entries = append(entries, entry)
 271         }
 272
 273         err = scanner.Err()
 274         if err != nil {
 275                 return nil, fmt.Errorf("read probe log: %w", err)
 276         }
 277
 278         if len(entries) < count {
 279                 return nil, fmt.Errorf("probe log has %d messages, fewer than %d", len(entries), count)
 280         }
 281
 282         return entries, nil
 283 }
 284
 285 // probeStop returns why a probe run must stop: a failed call, or a quota window
 286 // whose used percent grew by more than probeQuotaLimit points since the first
 287 // call. It returns "" when the run can go on.
 288 func probeStop(records []usageRecord) string {
 289         for _, record := range records {
 290                 if record.Error != "" {
 291                         return "call failed: " + record.Error
 292                 }
 293         }
 294
 295         if len(records) == 0 {
 296                 return ""
 297         }
 298
 299         first := usedPercents(records[0])
 300         for name, used := range usedPercents(records[len(records)-1]) {
 301                 start, found := first[name]
 302                 if found && used-start > probeQuotaLimit {
 303                         return fmt.Sprintf("%s grew from %g to %g", name, start, used)
 304                 }
 305         }
 306
 307         return ""
 308 }
 309
 310 // modelLines returns the sizes of the nodes that the model wrote, in tree
 311 // order. A node that fits its source with no model call is not one of them.
 312 func modelLines(memory *Memory) ([]int, error) {
 313         memory.mutex.Lock()
 314         defer memory.mutex.Unlock()
 315
 316         keys, err := memory.tree.Keys()
 317         if err != nil {
 318                 return nil, err
 319         }
 320
 321         var sizes []int
 322         for _, key := range keys {
 323                 node, _, err := memory.tree.Node(key.level, key.index)
 324                 if err != nil {
 325                         return nil, err
 326                 }
 327
 328                 model, err := builtByModel(memory, key)
 329                 if err != nil {
 330                         return nil, err
 331                 }
 332
 333                 if model {
 334                         sizes = append(sizes, node.Size)
 335                 }
 336         }
 337
 338         return sizes, nil
 339 }
 340
 341 // builtByModel tells if the node key needed a model call: a leaf whose source
 342 // is over nodeBytes, or a merge whose children do not fit in one node.
 343 func builtByModel(memory *Memory, key nodeKey) (bool, error) {
 344         if key.level == 0 {
 345                 message, err := memory.log.Message(key.index)
 346                 if err != nil {
 347                         return false, err
 348                 }
 349
 350                 _, free := freeLeaf(message)
 351
 352                 return !free, nil
 353         }
 354
 355         left, right, err := memory.children(key)
 356         if err != nil {
 357                 return false, err
 358         }
 359
 360         _, free := freeMerge(left, right)
 361
 362         return !free, nil
 363 }
 364
 365 // readUsageFile reads the records of usage.jsonl at path, in the order of the
 366 // start of their calls. The file has them in the order of the end of their
 367 // calls, which differs when calls run at once.
 368 func readUsageFile(path string) (records []usageRecord, err error) {
 369         file, err := os.Open(path)
 370         if errors.Is(err, os.ErrNotExist) {
 371                 return nil, nil
 372         }
 373
 374         if err != nil {
 375                 return nil, fmt.Errorf("open usage file: %w", err)
 376         }
 377
 378         defer func() {
 379                 err = errors.Join(err, file.Close())
 380         }()
 381
 382         scanner := bufio.NewScanner(file)
 383         scanner.Buffer(make([]byte, 64*1024), probeLineBytes)
 384         for scanner.Scan() {
 385                 var record usageRecord
 386                 err = json.Unmarshal(scanner.Bytes(), &record)
 387                 if err != nil {
 388                         return nil, fmt.Errorf("decode usage: %w", err)
 389                 }
 390
 391                 records = append(records, record)
 392         }
 393
 394         err = scanner.Err()
 395         if err != nil {
 396                 return nil, fmt.Errorf("read usage file: %w", err)
 397         }
 398
 399         slices.SortStableFunc(records, func(a, b usageRecord) int {
 400                 return callStart(a).Compare(callStart(b))
 401         })
 402
 403         return records, nil
 404 }
 405
 406 // callStart returns the start of the call of record, or the zero time when its
 407 // date is not valid.
 408 func callStart(record usageRecord) time.Time {
 409         start, err := time.Parse(time.RFC3339Nano, record.Date)
 410         if err != nil {
 411                 return time.Time{}
 412         }
 413
 414         return start
 415 }
 416
 417 // usedPercents returns the used percent of each quota window of record, by
 418 // header name.
 419 func usedPercents(record usageRecord) map[string]float64 {
 420         used := make(map[string]float64)
 421         for name, value := range record.Quota {
 422                 if !strings.HasSuffix(name, "-used-percent") {
 423                         continue
 424                 }
 425
 426                 percent, err := strconv.ParseFloat(value, 64)
 427                 if err == nil {
 428                         used[name] = percent
 429                 }
 430         }
 431
 432         return used
 433 }
 434
 435 // writeProbeReport writes the result of a probe run.
 436 func writeProbeReport(out io.Writer, appended int, stop string, records []usageRecord, sizes []int) error {
 437         var input, cached, output, failed int
 438         for _, record := range records {
 439                 input += record.InputTokens
 440                 cached += record.CachedTokens
 441                 output += record.OutputTokens
 442                 if record.Error != "" {
 443                         failed++
 444                 }
 445         }
 446
 447         var lines []string
 448         if stop != "" {
 449                 lines = append(lines, "stopped early: "+stop)
 450         }
 451
 452         lines = append(lines,
 453                 fmt.Sprintf("messages: %d", appended),
 454                 fmt.Sprintf("calls: %d (%d failed), %.2f per message", len(records), failed, ratio(len(records), appended)),
 455                 fmt.Sprintf("model lines: %d, retries: %d, %.2f calls per model line", len(sizes), len(records)-failed-len(sizes), ratio(len(records), len(sizes))),
 456                 fmt.Sprintf("tokens: %d input, %d cached (%.1f%%), %d output", input, cached, 100*ratio(cached, input), output),
 457         )
 458
 459         if len(sizes) > 0 {
 460                 lines = append(lines, sizeText(sizes))
 461         }
 462
 463         if len(records) > 0 {
 464                 lines = append(lines, timeText(records))
 465         }
 466
 467         if len(records) > 0 {
 468                 lines = append(lines,
 469                         "quota at the first call: "+quotaText(records[0]),
 470                         "quota at the last call: "+quotaText(records[len(records)-1]),
 471                 )
 472         }
 473
 474         _, err := io.WriteString(out, strings.Join(lines, "\n")+"\n")
 475
 476         return err
 477 }
 478
 479 // sizeText describes the sizes of the model lines.
 480 func sizeText(sizes []int) string {
 481         sorted := slices.Sorted(slices.Values(sizes))
 482         total, over := 0, 0
 483         for _, size := range sorted {
 484                 total += size
 485                 if size > nodeBytes {
 486                         over++
 487                 }
 488         }
 489
 490         return fmt.Sprintf("line bytes: min %d, median %d, mean %.0f, max %d, %d over %d", sorted[0], sorted[len(sorted)/2], ratio(total, len(sorted)), sorted[len(sorted)-1], over, nodeBytes)
 491 }
 492
 493 // timeText describes the time per call and how many calls ran at once. A call
 494 // runs from its date for its seconds.
 495 func timeText(records []usageRecord) string {
 496         type event struct {
 497                 at    time.Time
 498                 delta int
 499         }
 500
 501         var events []event
 502         seconds := make([]float64, 0, len(records))
 503         total := 0.0
 504         for _, record := range records {
 505                 start, err := time.Parse(time.RFC3339Nano, record.Date)
 506                 if err != nil {
 507                         continue
 508                 }
 509
 510                 length := time.Duration(record.Seconds * float64(time.Second))
 511                 events = append(events, event{
 512                         at:    start,
 513                         delta: 1,
 514                 }, event{
 515                         at:    start.Add(length),
 516                         delta: -1,
 517                 })
 518                 seconds = append(seconds, record.Seconds)
 519                 total += record.Seconds
 520         }
 521
 522         if len(events) == 0 {
 523                 return "time: no dated calls"
 524         }
 525
 526         slices.SortFunc(events, func(a, b event) int {
 527                 return cmp.Or(a.at.Compare(b.at), cmp.Compare(a.delta, b.delta))
 528         })
 529
 530         running, most := 0, 0
 531         for _, e := range events {
 532                 running += e.delta
 533                 most = max(most, running)
 534         }
 535
 536         wall := events[len(events)-1].at.Sub(events[0].at).Seconds()
 537         slices.Sort(seconds)
 538
 539         return fmt.Sprintf("time: %.0f s in all, %.1f calls per minute, %.1f s per call (median %.1f, max %.1f), calls at once: at most %d, %.1f on average", wall, 60*float64(len(seconds))/max(wall, 1e-9), total/float64(len(seconds)), seconds[len(seconds)/2], seconds[len(seconds)-1], most, total/max(wall, 1e-9))
 540 }
 541
 542 // quotaText returns the quota headers of record, sorted by name.
 543 func quotaText(record usageRecord) string {
 544         names := slices.Sorted(maps.Keys(record.Quota))
 545         parts := make([]string, len(names))
 546         for n, name := range names {
 547                 parts[n] = strings.TrimPrefix(name, "x-codex-") + "=" + record.Quota[name]
 548         }
 549
 550         return strings.Join(parts, " ")
 551 }
 552
 553 // ratio returns a / b, or 0 when b is 0.
 554 func ratio(a, b int) float64 {
 555         if b == 0 {
 556                 return 0
 557         }
 558
 559         return float64(a) / float64(b)
 560 }