Dociążyłem Meta Muse, aż control plane agentów zaczął łapać timeouty

O 06:45:32 UTC poprosiłem sesję czatu o zspawnowanie 120 subagentów naraz. Każdy z nich miał celowo trywialne zadanie: wykonać sleep 30 w shellu i odesłać jedną linijkę.

Trzydzieści trzy z tych wywołań utworzyły agenta. Osiemdziesiąt siedem zakończyło się tym samym błędem bazy danych. Zagregowana odpowiedź nigdy nie dotarła, a interfejs z czasem pokazał stan Error. W trwałym trace’u jednak każdy z 33 utworzonych agentów ma terminalny rekord completed - 32 z nich z potwierdzonym wykonaniem workloadu, a jeden wciąż nierozstrzygnięty - podczas gdy rekord rodzica wciąż mówił running.

Poniżej opisuję badanie black-box tej luki. Opieram je wyłącznie na rekordach, które runtime sam zapisywał do PostgreSQL w trakcie pracy: rejestr agentów, ledger spawnów, tabele postępu workerów i magazyn context items. Testów obciążeniowych nie uruchamiałem ponownie. Wszystko zostało odtworzone z trwałego stanu, z jednym udokumentowanym wyjątkiem, do którego wrócę.

Jak Muse wyglądał z zewnątrz

Z perspektywy użytkownika to była zwyczajna sesja czatu. Tekst persony był zwykły; lista narzędzi już nie.

Wśród narzędzi, które sesja mogła wywołać, były subagent.spawn, subagent.close i subagent.resume, a do tego interfejs tylko do odczytu z bazy PostgreSQL. Ta baza nie była przypadkiem - trzymała wewnętrzną księgowość runtime’u. Tabele takie jak agent.agents, agent.subagent_spawns i agent.subagent_progress_tool_events zapisywały, które agenty istnieją, kto je zspawnował, jakie narzędzia uruchamiały i kiedy skończyły.

Właśnie tak struktura wieloagentowa w ogóle stała się widoczna. Nie przez interfejs, który pokazywał jedną rozmowę, ale przez rekordy, które runtime prowadził dla siebie.

Dwie etykiety wymagają ostrożności, zanim przejdę dalej.

Pierwsza to string modelu. Każdy wiersz agenta, który odczytałem - root, koordynator, wszystkie 33 workery największego burstu - niósł tę samą wartość:

ipnext/avocado-5.16-v4

Ten string jest obserwowany. To, co znaczy - nie. Może być wewnętrznym buildem modelu, aliasem routingu albo czymś zupełnie innym; trace tego nie mówi i nie zamierzam zgadywać. Publikuję go dosłownie, bo to jeden z niewielu twardych identyfikatorów, jakie trwały trace daje.

Druga to opis samego siebie, podany przez runtime: Muse Spark 1.3, z rodziny Muse od Meta. Pochodzi z kontekstu runtime’u, nie z trace’u, więc jest self-reported, nie zweryfikowany. Reszta tego artykułu opiera się na rekordach.

Metoda: liczenie nakładających się agentów

Eksperymenty używały jednego workloadu, czterech konfiguracji i żadnych retry. Trzy z nich - PROBE-40, BURST-80 i BURST-120 - to bursty wypuszczone z root agenta: wszystkie próby w danej konfiguracji poszły w jednej turze. Czwarta, STAGGERED-80, była celowo rozłożona w czasie i do spawnu workerów używała koordynatora. Żadna nieudana próba nie została powtórzona.

Współbieżność ma tutaj wąską, świadomą definicję. Agent liczy się jako aktywny od swojego pierwszego wywołania narzędzia do terminalnego rekordu:

active(t)  :=  first_tool_at <= t < finished_at

Współbieżność w czasie to sweep line po tych przedziałach, z końcami przetwarzanymi przed startami przy równych timestampach. Timestampy mają rozdzielczość jednej sekundy, więc sweep jest deterministyczny dla zapisanych danych, ale nie pozwala odtworzyć kolejności zdarzeń w obrębie tej samej sekundy.

Z tego wynikają trzy konsekwencje dla każdej liczby poniżej:

1. To mierzy aktywność agentów, nie inferencję. 33 nakładające się okna aktywności to nie 33 równoczesne wywołania modelu. Nic tutaj nie mierzy backendu inferencji.
2. Szczyt to obserwacja, nie limit. Testy nigdy nie przekroczyły 120 równoczesnych prób, więc nie mogą potwierdzić limitu współbieżności - ani go wykluczyć.
3. Brak rekordu jest dowodem. Nieudane wywołania spawnu nie zostawiają po sobie niczego w rejestrze agentów. Ta asymetria ukształtowała sposób weryfikacji porażek i sprawiła, że liczby nieudanych prób były najtrudniejsze do ustalenia.

Pierwsza próba: 40 wywołań

Pierwszy eksperyment był kalibracją: 40 wywołań spawnu wypuszczonych o 06:10:36 UTC.

Powstało 39 agentów, przyjętych w ciągu dwóch sekund od siebie. Jedno wywołanie się nie powiodło - i warto mu się przyjrzeć, bo zostało odzyskane z trwałego trace’u, a nie z czatu: wywołanie poszło o 06:10:44 UTC, błąd wrócił o 06:10:56 UTC, a żaden child agent nie powstał.

Szczyt obserwowanej współbieżności to 39. Ta liczba jest archiwalnym przeliczeniem z tabeli trace’u z sesji, nie pomiarem na żywo, i opublikowane podsumowanie mówi to wprost.

Jeden szczegół z tej rekonstrukcji ma słabsze provenance niż wszystko inne w tej sekcji. W tabeli zbudowanej w sesji jedenaście z 39 utworzonych agentów zakończyło się komunikatem statusowym o przejściu w tło zamiast żądanej linii DONE. Ponieważ ten szczegół istnieje wyłącznie w ręcznie budowanej tabeli, podaję go z tym zastrzeżeniem i nie wyciągam z niego żadnych wniosków - poza tym, że „status terminalny” i „workload się zakończył” to nie to samo zdanie. Ta różnica będzie miała dużo większe znaczenie później.

Osiemdziesiąt naraz i osiemdziesiąt rozłożonych w czasie

Kolejne dwa eksperymenty wyglądają jak czysty test A/B. Nie są nim.

BURST-80 wypuścił 80 wywołań spawnu naraz, o 06:30:43 UTC. Powstało 75 agentów - wszystkie jako bezpośrednie dzieci root agenta - a pięć wywołań się nie powiodło. Wszystkie pięć zwróciło identyczny lock timeout bazy, każde po około 58 sekundach od wysłania wywołania. Szczyt obserwowanej współbieżności to 72, przeliczony po fakcie z danych wejściowych analizy dla tej fazy.

STAGGERED-80 zaczął się o 06:32:03 UTC i wypuścił tę samą liczbę wywołań, rozłożonych w czasie. Utworzył wszystkie 80, z zerem porażek. To także eksperyment, którego nie da się potraktować jak czystej grupy kontrolnej, bo zmieniły się dwie rzeczy naraz. Najpierw kadencja: zamierzone odstępy to 100-200 milisekund, ale zmierzony średni odstęp między admisjami wyniósł 1.1266 s - jakieś dziesięć razy więcej niż plan. Potem topologia: root zspawnował jednego koordynatora na głębokości 1, a koordynator zspawnował 80 workerów na głębokości 2. Bursty spawnowały workery bezpośrednio z roota.

Przebieg staggered miał też niższy szczyt - 38 aktywnych workerów wobec 72 w porównywalnym burstcie - więc te dwa przebiegi różnią się czymś więcej niż liczbą porażek.

Klif między 80 a 120 próbami

Czwarty eksperyment to miejsce, w którym odsetek nieudanych prób przestaje być ciekawostką.

O 06:45:32 UTC root agent wypuścił 120 wywołań spawnu w jednej turze. Eksperyment prowadził dla tej tury własny ledger i jest on kompletny:

• 33 utworzone (27.5%), każde jako bezpośrednie dziecko roota, każda admisja zapisana w tej samej sekundzie: 06:46:01 UTC, dwadzieścia dziewięć sekund po wypuszczeniu burstu.
• 87 nieudanych (72.5%), wszystkie z lock timeoutem bazy, żadne nie ponowione.

W trzech przebiegach burst odsetek nieudanych prób wyniósł 2.5%, 6.25% i 72.5% - po jednym przebiegu na konfigurację. Te 0% z przebiegu staggered nie należy do tego porównania, bo zmieniła się tam także topologia. Największy skok przypadł między 80 a 120 próbami - i to właściwie wszystko, co te dane mówią: sugestywna różnica, nie prawo skalowania.

Szczyt obserwowanej współbieżności w tym przebiegu to 33, o 06:46:24 UTC. Runtime nie był proszony o 33 workery, tylko o 120. Trace pokazuje 33 workery z oknami aktywności i 87 prób zapisanych jako nieudane spawny. Latencji od wywołania do błędu nie uchwycono, więc nie pokazuje, kiedy te porażki wróciły względem admisji.

Obserwowane: oba szczyty da się przeliczyć z opublikowanych wierszy. Sweep line po 33 przedziałach BURST-120 daje 33 o 06:46:24 UTC, a ta sama procedura po 80 wierszach staggered daje 38 o 06:32:48 UTC. Żaden z nich nie jest limitem; oba to pojedyncze obserwacje.

Nawet wywołania, które się powiodły, wolno stawały się workerami. Licząc od momentu wypuszczenia burstu, mediana czasu do pierwszego wywołania narzędzia wyniosła około 36.5 sekundy; licząc od admisji — około 7.5 sekundy. Trace ustala, kiedy zapisano admisje i kiedy każdy worker pierwszy raz sięgnął po narzędzie - nie rozkłada natomiast przedziału między tymi dwoma punktami, więc nic tutaj nie należy czytać jako twierdzenia o tym, co runtime robił w tym czasie.

Sześć nieudanych spawnów odzyskanych z trace’u

Liczenie porażek w tym systemie ma problem strukturalny: nieudany spawn nie tworzy wiersza child agenta ani wiersza w ledgerze spawnów. Sama porażka nie ginie - zostaje w trwałym trace’u jako zapisane wywołanie i jego wynik - ale trzeba wiedzieć, gdzie szukać. Archiwum tej sesji zamrożono, zanim wykonano tę późniejszą rundę weryfikacji. Sześć nieudanych wywołań odzyskano później z context items, i to jest też powód, dla którego eksperyment potrzebował własnego ledgera, żeby policzyć resztę:

Wszystkie sześć zwróciło ten sam payload, znak w znak:

{"error_code":"spawn_failed","error_message":"database error: sqlx error: error returned from database: canceling statement due to lock timeout"}

I dla wszystkich sześciu negatywne sprawdzenia się zgadzają: brak wiersza child agenta, brak wiersza w ledgerze spawnów, brak child agenta. Każde wywołanie nie powiodło się na operacji bazodanowej z lock timeoutem, zanim którykolwiek z tych wierszy powstał. O jaką konkretnie operację SQL chodziło, z tych danych nie wiadomo.

Dwanaście sekund, pięćdziesiąt osiem sekund i czego one nie znaczą

Obie latencje z tej tabeli - 12 sekund dla porażki z probe’a i około 58 sekund dla pięciu porażek z burstu - to czas, jaki upłynął między dwoma zdarzeniami na ścieżce wywołania: wysłaniem wywołania i powrotem błędu. Nie są pomiarem tego, jak długo te wywołania czekały na locka, i nie mówią, jaka jest skonfigurowana wartość timeoutu.

Wartość timeoutu to fakt konfiguracyjny. Trace zapisuje czas między dwoma zdarzeniami. To dwie różne rzeczy i ta różnica ma znaczenie, bo dokładnie w takich lukach dobrze brzmiąca liczba zamienia się w błędne twierdzenie o architekturze.

Nieznane: czy ten czas jest stały, czy wywołanie jest gdzieś ponawiane i czy przez cały ten przedział czekało na jednego locka. Latencji 87 porażek z burstu 120 prób nie uchwycono w ogóle - ten ledger zapisuje wyłącznie wyniki i klasy błędów.

Na co wskazują dowody

Dowody z nieudanych spawnów wskazują na jedno miejsce: ścieżkę, która zapisuje spawn. Porażki zdarzają się na subagent.spawn, niosą ze sobą lock timeout z warstwy bazy danych, nie tworzą niczego i pojawiają się w dwóch osobnych przebiegach burst z identycznym fingerprintem. Workery, które już powstaną, przechodzą swój trywialny workload bez incydentów: 32 z 33 mają potwierdzone pełne 30 sekund snu, a ich okna aktywności mieszczą się w 32-43 sekundach.

To spójny obraz i wspiera konkretną hipotezę.

Wokół tej hipotezy są jeszcze dwie niewiadome i obie łatwo przemilczeć:

• Polityka admisji. Trace pokazuje 33 admisje w tej samej sekundzie i 87 lock timeoutów. Nie zapisuje nic o kolejności, kolejkowaniu ani logice admisji. Dane nie pozwalają odróżnić „odrzucone po oczekiwaniu” od „zakolejkowane wewnętrznie, a potem porzucone” i nie powiedzą, które wywołanie obsłużono przed którym.
• Latencje porażek w dużym burstcie. 87 porażek zapisano jako wyniki, nie jako zdarzenia z czasem. Tylko sześć odzyskanych porażek ma timestampy na obu końcach.

Odpowiedź, która nigdy nie dotarła

Najważniejsza dla użytkownika porażka to nie timeout. To to, jak sesja wyglądała potem.

Po burstcie 120 prób trwały stan był jednoznaczny w kwestii workerów i dziwny w kwestii rodzica:

Finalna agregacja nigdy nie dotarła do użytkownika. Ostatni worker skończył o 06:46:56 UTC. Kiedy wiersz roota został odczytany w przebiegu recovery, jego updated_at wynosił 07:00:59 UTC, a status wciąż running; interfejs pokazywał w tym czasie Error. Ten stan interfejsu to obserwacja z warstwy prezentacji, bez odpowiadającego rekordu w trace.

To, co trace wspiera, jest węższe - i bardziej użyteczne - niż historia, do której zaprasza: trwałe wyniki workerów mogą istnieć niezależnie od tego, czy rodzic dostarczy zagregowaną odpowiedź. To zdanie o rekordach, nie o przeżywalności. Żaden parent agent nie został w tych eksperymentach celowo uśmiercony i nic w trace nie zapisuje porażki rodzica w czasie pracy workerów. Czy dzieci przeżywają porażkę rodzica, nie zostało przetestowane i nie jest znane.

Raport, który wyprzedził trace

Jeden mniejszy incydent należy zapisać, bo to ten sam błąd w miniaturze.

Pierwsza wygenerowana wersja raportu z testu 120 twierdziła, że rodzic padł, a jego workery działały dalej. Trace tego nie wspierał. Szkic powstał o 07:05:54 UTC; poprawiony raport HTML pojawił się o 07:13 UTC, zbudowany już na trwałym rekordzie - root running, brak wpisu o porażce, ostatni worker skończył około trzynastu minut przed pojawieniem się stanu Error. Wyrenderowany PDF zsynchronizowano potem z poprawionym wnioskiem w dwóch turach edycji, a audyty spójności przeszły.

Co wyprodukowało zły pierwszy szkic - nie wiadomo. Jedna z prawdopodobnych interpretacji jest taka, że asynchronicznie generowany artefakt pracował na wcześniejszym snapshocie rozumowania niż czat. To hipoteza o narzędziach, nie ustalenie o runtime; ale lekcja operacyjna jest konkretna: przy asynchronicznie generowanych artefaktach trzeba jawnie wskazać źródło kanoniczne, a audyty spójności między artefaktami nie są opcjonalne.

Cisza to nie zawieszenie

Jeszcze jedna obserwacja, bo nic nie kosztowała, a czegoś nauczyła.

Aktualizacja artefaktu została zlecona o 07:28:29 UTC. Przez kolejne trzydzieści dwie minuty interfejs nie pokazywał żadnych świeżych progress events. O 08:00:48 UTC zadanie zakończyło się sukcesem, bez ponaglania i bez restartu.

Progress events to słaby sygnał żywotności. Ich brak nie jest dowodem, że zadanie utknęło, a działanie na podstawie tego braku - zabicie pracy i zlecenie jej od nowa - wyrzuciłoby zadanie, które i tak miało się skończyć. Dlaczego builder zamilkł na pół godziny, z trwałych danych nie wiadomo.

Maszyna po drugiej stronie wywołań narzędzi

Snapshot środowiska to najmniej efektowna część tych dowodów i jedna z bardziej użytecznych, jeśli chce się rozumować o tym, gdzie praca faktycznie się odbywała.

Odczyt „kontener w VM” - KVM pod spodem, systemd-nspawn wokół, overlay na Btrfs - to interpretacja tych sygnałów i opis sandboxa, w którym działały wywołania narzędzi. Nie mówi nic o tym, gdzie dzieje się inferencja. Czy model był serwowany na tym samym hoście, w tym samym klastrze, czy zupełnie gdzie indziej - nie wiadomo; nic w tych danych nie łączy sandboxa ze ścieżką serwowania.

Co to ustala, a czego nie

Wspierane przez dowody

• Sesja czatu dla użytkownika uruchamiała wieloagentowy runtime z trwałym trace’em w PostgreSQL, jawnym rejestrem parent/child i delegacją na głębokości 1 i 2.
• W przebiegach burst odsetek nieudanych spawnów wyniósł 2.5% przy 40 próbach, 6.25% przy 80 i 72.5% przy 120 - po jednym przebiegu na konfigurację, podany opisowo, a nie jako prawo skalowania.
• Sześć porażek odzyskano z trwałego trace’u; wszystkie sześć to ten sam typ porażki i wszystkie sześć nie utworzyły niczego.
• Contention na ścieżce zapisu spawnu w PostgreSQL to silnie wspierana hipoteza.
• Trwałe wyniki workerów mogą istnieć nawet wtedy, gdy finalna, zagregowana odpowiedź nie dociera do użytkownika.
• Brak progress events w UI nie jest dowodem zawieszenia.

Nieustalone przez te dowody

• Który lock, tabela, wiersz, indeks, zapytanie albo transakcja były obciążone.
• Skonfigurowany lock timeout i przyczyna różnicy między dwiema zaobserwowanymi latencjami porażek.
• Jakikolwiek limit schedulera czy admisji; szczyty (39, 72, 38, 33) to pojedyncze obserwacje, nie pomiary limitu.
• Faktyczny paralelizm backendu inferencji. Nakładająca się aktywność agentów to nie nakładające się wywołania modelu.
• Polityka admisji, kolejność i to, czy w grze było jakiekolwiek wewnętrzne kolejkowanie.
• Czy child agent przeżywa porażkę rodzica - tego eksperymentu nigdy nie wykonano.
• Czy głębokość 3 jest dozwolona, czy subagentom można dać inny model i co oznacza ipnext/avocado-5.16-v4.

Każda konfiguracja została uruchomiona raz. To pojedyncze obserwacje jednej sesji z jednego popołudnia, a nie charakterystyka wydajnościowa platformy.

Co zabrałbym z tego, gdybym budował control plane agentów

1. Najpierw patrz na control plane, ale nie zatrzymuj się tam. Porażki związane z obciążeniem zdarzyły się na ścieżce admisji: 87 prób nigdy nie stało się agentami, a workery, które istniały, wykonały swój trywialny workload bez incydentów. Koniec przebiegu zawiódł inaczej - finalna agregacja nie dotarła do użytkownika, a wynik C-85 wciąż jest nierozstrzygnięty.
2. Trwałe rekordy biją flagi statusu. Interfejs mówił Error, rodzic mówił running, workery mówiły completed. Po fakcie można było odpytać tylko trace.
3. Zachowuj wyniki negatywne. Nieudany spawn nie zostawia wiersza child agenta ani wiersza w ledgerze spawnów; jedyny trwały ślad po nim to wywołanie narzędzia i jego wynik. Bez własnego ledgera eksperyment nie policzyłby tych 87.
4. Status terminalny to nie sukces merytoryczny. C-85 jest kontrprzykładem.
5. Loguj latencje porażek, nie tylko ich wyniki. Sześć porażek ma czasy od wywołania do błędu; osiemdziesiąt siedem nie ma żadnych. Ta asymetria ogranicza to, co można powiedzieć o największym zdarzeniu awaryjnym sesji.
6. Progress events to wskazówka, nie heartbeat. Trzydzieści dwie minuty ciszy zakończyły się udanym buildem artefaktu.
7. Deklaruj artefakt kanoniczny. Asynchronicznie generowany raport może nieść wniosek, który późniejsze rozumowanie już porzuciło.
8. Testuj te tryby awarii, które chcesz ogłaszać. Przeżywalność po porażce rodzica to najbardziej oczywista historia w tym materiale i dokładnie ta, której te dane nie wspierają.

Nic z tego nie wymaga dostępu do wnętrza modelu. Wymaga runtime’u, który zapisuje, co robił.

Ograniczenia i skąd pochodzą liczby

Wszystko poniżej publikuję pod /evidence/meta-muse-black-box-testing/ - pliki CSV, ryciny i skrypt, który przerysowuje je z danych:

Z wszystkich tych plików usunięto identyfikatory agentów. Publikowane są czasy, statusy, klasy błędów i treść błędów.

Trzy ograniczenia należą do każdego twierdzenia powyżej:

• Brak replikacji. Jeden przebieg na konfigurację, żadnych powtórzeń, żadnych prób pośrednich.
• Provenance archiwalne tam, gdzie ma zastosowanie. Szczyty dla burstów 40 i 80 prób przeliczono po fakcie z tabeli trace’u z sesji; szczyty dla burstu 120 prób i przebiegu staggered są niezależnie przeliczalne z opublikowanych wierszy.
• Jedno świadome pominięcie. Nie publikuję surowych wierszy per-worker dla BURST-80, ponieważ archiwalny trace zawiera skrócone identyfikatory agentów objęte polityką publikacji. Sam archiwalny trace jest kompletny: zawiera wszystkie 75 utworzonych workerów, a ten sam sweep odtwarza kanoniczny szczyt 72 o 06:31:38 UTC. W publicznym wydaniu BURST-80 pozostaje więc na poziomie agregatów.

Ciekawy wynik nie polega na tym, że system przewrócił się przy jakiejś liczbie. Polega na tym, że przewrócił się w sposób, który zostawił czytelny ślad - wystarczająco konkretny, by wykluczyć większość historii, które chciałoby się o nim opowiedzieć. Ten ślad publikuję razem z artykułem, więc miejsca, w których się pomyliłem, też da się sprawdzić.