Епидемиологија core dump-ова: исправка бага старог 18 година

OpenAI-јеви модели и агенти све више се ослањају на скалабилну инфраструктуру података како би у време инференције тражили релевантне податке: док модели размишљају о вашем питању. Неки од тих сервиса написани су у C++-у, чија нисконивоска контрола система омогућава да максимално повећамо перформансе и сведемо употребу меморије на минимум. Те предности у ефикасности важне су док се ширимо, али недостатак безбедности меморије у C++-у значи да багови могу да изазову падове уписом на погрешне или непостојеће меморијске адресе.

Пре неколико месеци уочили смо падове унутар сервиса Rockset, посебног дела наше ChatGPT инфраструктуре података који је кључан за многе додатке за податке и за претрагу разговора. У сваком од тих падова, изгледало је као да се нормална C++ функција завршила, а затим вратила на лажну адресу, због чега је кернел зауставио програм јер показивач инструкције више није показивао на код. Понекад је место за повратну адресу у стек оквиру било NULL. Понекад је сам CPU регистар показивача стека изгледао померен за 8 бајтова, као да је %rsp некако декрементиран усред нормалног извршавања. У оба случаја пад се дешавао при повратку.

То нису уобичајени начини отказивања апликационог кода. Залутали упис који погађа само сачувану повратну адресу јесте могућ, али је изузетно мало вероватан. Баг који помери поравнање %rsp за 8 без inline assembly-ја, setcontext-а или longjmp-а (ништа од тога не користимо) још је чуднији, јер компајлирани код тај регистар директно подешава само у прологу и епилогу функције. За сваку хипотезу које смо ми (или ChatGPT) могли да се сетимо постојали су снажни докази против ње, па је баг деловао немогуће.

Оно што смо претпостављали да је један проблем на крају се испоставило као два неповезана бага, случајно откривена у исто време. Прво, тиха хардверска корупција на једном Azure хосту, где CPU једноставно није исправно рачунао. Друго, race condition стар 18 година у GNU libunwind-у, непримећен баг у широко коришћеној библиотеци отвореног кода.

Овај текст је прича о томе како смо препознали и исправили наизглед необјашњиве падове тако што смо размишљали као епидемиолози и изградили квалитетан скуп података о целој популацији падова.

Прво, хајде да мало дубље погледамо Rockset. То је cloud-native систем података за претрагу и аналитику у реалном времену који користимо за многе интерне случајеве употребе у OpenAI-ју, као што су sync конектори (OpenAI је купио Rockset 2024. године). Стримоване исправке користе се за одржавање ажурног индекса базе знања радног простора, како би ChatGPT могао да тражи релевантне информације када одговара на питања или извршава радње.

Rockset-ов слој извршавања написан је у C++-у. Језик C++ омогућава нисконивоски приступ CPU-у, што је добро за перформансе и ефикасност, али значи да багови у апликацији могу довести до неважећих приступа меморији и segfault-ова. Да бисмо лакше ушли у траг таквим проблемима, користимо folly-јев handler за фаталне сигнале да забележимо stack trace када се пад деси, а одговарајуће core dump-ове (снимак стања програма у тренутку пада) отпремамо у Azure blob storage за каснију анализу. Сви Rockset-ови листови за обраду упита су реплицирани, што умањује утицај пада на клијента. Ипак, сваки segfault одговара багу који треба исправити како бисмо испунили циљеве поузданости и квалитета.

Наш почетни приступ био је да ове core dump-ове третирамо као уобичајен проблем дебаговања: пажљиво прегледамо неколико њих, формирамо хипотезе и редом их елиминишемо.

Већина падова дешавала се у методу под називом DocumentTree::updateDocument. У тим падовима изгледало је да је updateDocument позвао неку непознату функцију X, да је стек корумпиран док је X била активна, а затим се X вратила на адресу која није извршни код. У неким случајевима X-ов управо скинути оквир изгледао је важеће, осим што му је сачувана повратна адреса била NULL. У другим случајевима сам показивач стека изгледао је погрешно, али је следећи важећи оквир и даље деловао као updateDocument.

Нисмо знали када се стек корумпира, што је остављало огроман простор за претрагу. updateDocument је велики метод са много inline-овања, па је број кандидата за X био застрашујуће велик.

Да ли је то био баг у нашем C++ коду? Проблем са компајлером или линковањем? Проблем у некој од наших runtime библиотека? Баг у Linux кернелу око испоруке сигнала или промене контекста? Нешто још ређе? Ако је ово био залутали упис, зашто га није ухватило наше ASAN staging окружење?

Покушали смо да користимо логове на нивоу апликације да идентификујемо све појаве проблема, али багове корупције стека тешко је класификовати само из логова, јер су забележени stack trace-ови и сами корумпирани или недостају. Нисмо успели да саставимо упит над логовима који није имао и лажно позитивне и лажно негативне резултате. Ручно смо прегледали још core dump-ова и нашли неколико додатних примера, али је тај процес био превише радно интензиван да би нам дао поуздан скуп података.

У овој фази истраге (погрешно) смо искључили хардверски баг, јер смо видели падове у више региона и на више типова хардвера, па смо и даље тражили искључиво софтверске узроке. Неколико дана смо веома дубоко анализирали један пад са погрешно поравнатим %rsp, реконструишући историју пре пада из садржаја стека и регистара. То је дало неке могуће трагове, али пошто нисмо напустили почетни закључак да сви багови имају исти узрок, није нас извукло из ћорсокака.

Пре него што дођемо до прекретнице у нашој истрази, важно је објаснити какве смо информације извлачили из core датотека.

Rockset се компајлира са -fno-omit-frame-pointer, па је активни стек оквир увек доступан преко %rbp, а позиваоци формирају повезану листу показивача оквира.

На Linux x86_64, AMD64 System V ABI такође резервише 128 бајтова испод %rsp као red zone. Та област је доступна userspace коду и, што је важно, кернел обећава да је неће преписати када испоручује сигнал, као део ABI уговора.

Red zone је била кључна у нашем дебаговању пада после повратка, јер чува део информација од пре повратка. Када се активира SIGSEGV, folly-јев handler за фаталне сигнале ради на стеку нити која се срушила. Стек оквири који више нису активни (јер се њихова функција вратила) биће преписани handler-ом сигнала, осим последњих 128 бајтова. Зато можемо да кажемо ствари попут „X-ов управо скинути стек оквир изгледао је важеће, осим NULL повратне адресе.“ Red zone чува неке неактивне оквире, или понекад само крај једног неактивног оквира.

Пронашли смо један пад са погрешно поравнатим стеком у којем су све укључене функције биле веома мале. То нам је омогућило да видимо да је %rsp постао погрешно поравнат током извршавања релативно једноставне функције и да су после тога додатни позиви успели. Програм се срушио тек када је активна функција најзад покушала да се врати. Ниједна од тих путања кода није користила изузетке, inline assembly, setcontext или longjmp, па ако се показивач стека заиста променио онако како је core указивао, ниједан уверљив баг у userspace коду није објашњавао проблем.

То нас је усмерило ка кернелу.

Rockset користи сигнале агресивније од већине програма. Извршавање упита разбијено је на много лаких задатака који размењују податке. То је важно за ефикасну обраду оптерећења са високим QPS-ом, али отежава обрачун CPU-а по упиту јер се рад за многе упите мултиплексира на исти pool нити.

Наше решење је нешто што зовемо coarse_thread_cputime_clock, што приближно рачуна clock_gettime(CLOCK_THREAD_CPUTIME_ID, ...) довољно јефтино да узоркујемо на свакој граници задатка. API timer_create може да се користи за заказивање периодичне испоруке сигнала на основу више појмова протока времена, укључујући акумулацију CPU времена. Заказујемо да се сигнал (SIGUSR2) испоручује на сваких неколико милисекунди CPU времена, када handler сигнала ажурира вредност локалну за нит. Иако многи задаци не виде да груби сат напредује док се извршавају, сабирање свих делти даје непристрасну процену стварног CPU времена за упит.

Пошто сигнале испоручујемо тако често, редак баг у кернелу око промене контекста или испоруке сигнала деловао је уверљиво. Провели смо време читајући извештаје о баговима, изворни код кернела и Azure-ове специфичне закрпе кернела. Покушали смо са stress тестовима. Нисмо успели да пронађемо ништа што је деловало повезано.

У том тренутку решили смо да се одмакнемо и пробамо другачији приступ.

Постоје два широка начина да се дебагује овакав проблем.

Један је да се понашате као нека врста лекара: фокусирате се на једног пацијента, радите много тестова и покушавате да дијагностикујете један случај на основу детаљних доказа.

Други је да се понашате више као епидемиолог: погледате целу популацију и питате да ли постоје обрасци које један случај не може да открије. Да ли је баг почео у одређеном издању? Да ли корелира са једним хардверским SKU-ом (конкретним CPU-ом и моделом сервера), једним регионом или једном верзијом кернела? Да ли се унутар онога што личи на један синдром крије више различитих кластера?

Углавном смо били у лекарском режиму. Кључни помак био је закључак да морамо да прикупимо квалитетне податке о популацији.

Наши претходни покушаји да аутоматски пронађемо све примерке проблема пропали су јер смо покушавали да користимо текстуалне претраге по логовима. Сами core dump-ови имају много више информација, али њихово ручно прегледање није могло да се скалира. Одлучили смо да уложимо труд у изградњу pipeline-а који би могао аутоматски да анализира core dump-ове.

Задужили смо ChatGPT да напише скрипту која је преузимала префикс сваке core датотеке, издвајала регистре, филтрирала познате лажно позитивне случајеве помоћу логова и аутоматски означавала пад као return-to-null, misaligned-stack или other. Затим смо ту скрипту паралелно покренули над сваким продукционим Rockset core dump-ом из претходне године.

То је била прекретница.

Чим смо добили чист скуп података, корелације су се одмах појавиле. Оно што смо третирали као један чудан баг заправо су биле две одвојене популације падова.

Return-to-null core dump-ови били су распоређени кроз многе кластере и географске регионе. Њихова учесталост је недавно порасла, али није било јасног датума почетка нити чисте инфраструктурне границе.

Падови са погрешно поравнатим стеком изгледали су потпуно другачије. Сви су долазили из једног региона, имали су јасан датум почетка и никада се нису дешавали на чворовима који су дуго радили. Иако су укључивали више Azure VM-ова (виртуелних машина хостованих у облаку), образац је личио на једну физичку машину са лошим хардвером која прави проблеме сваком VM-у који се случајно на њој нађе.

Тада смо схватили да смо у глави спојили два бага. Пошто смо мешали контрапримере из оба бага, нисмо могли да нађемо једно кохерентно објашњење.

Са чистом листом Kubernetes чворова и временских ознака, могли смо да пратимо падове са погрешно поравнатим стеком до једног физичког хоста, који је било лако ставити на denylist.

Нисмо успели да репродукујемо корупцију регистара на том хосту у контролисаном окружењу, чак ни после неколико недеља stress тестирања. Међутим, чим је проблематични хост повучен из употребе, падови са погрешно поравнатим стеком су нестали.

Уклањање лошег хоста није трајно решење, у смислу да не спречава нову појаву истог проблема. Можемо, међутим, да променимо софтвер тако да се сличан проблем, ако се понови, лако открије и обради. Унапредили смо handler за фаталне сигнале тако да укључује стање регистара, како бисмо поновну појаву могли да откријемо само из логова (без потребе за core dump-ом). Променили смо control plane тако да се VM-ови обично поново користе уместо да се рециклирају, што на нашем нивоу инфраструктурног стека знатно олакшава откривање лошег чвора. Такође смо ажурирали runbook-ове (и менталне моделе нашег тима) да укључе и ту могућност.

Када смо издвојили падове са лошег хоста, о преосталим return-to-null core dump-овима било је много лакше размишљати. Раније смо искључили exception unwinding јер смо мислили да имамо контрапримере: падове у путањама кода где се изузеци дефинитивно нису користили. Али сви ти контрапримери били су из кластера хардверске корупције.

Када смо се с тим на уму вратили преосталим core dump-овима, открили смо да је тај закључак био потпуно обрнут: сви падови су се дешавали током exception unwinding-а.

Када C++ баци изузетак, runtime мора да открије који catch блок треба да га прими и који деструктори или handler-и за чишћење треба успут да се изврше. Компајлер емитује те метаподатке, али се стварно упаривање дешава динамички током извршавања.

Exception unwinding заправо не изводи функција која позива throw, већ помоћне функције које позива настали компајлирани код. Те runtime рутине испитују стек, прибављају метаподатке о функцијама пронађеним на стеку, динамички траже handler-е за чишћење и catch блокове, а затим преносе контролу на једну од тих локација. Пренос контроле обухвата unwinding свих међуоквира стека (укључујући оквире помоћних функција).

Оперативно, то је много ближе longjmp-у или пребацивању fiber-а него нормалном позиву и повратку. Callee-save регистри морају бити враћени, као и регистри стек оквира %rbp и %rsp.

Наш бинарни фајл се линкује са две библиотеке које садрже имплементације функција за C++ exception unwinding: libgcc и GNU libunwind. Динамички linker је изабрао дефиниције из GNU libunwind-а. То нас је изненадило; очекивали смо да ће победити libgcc имплементација због правила верзионисања симбола; међутим, преглед покренутих бинарних фајлова показао је да није тако.

У овом тренутку наша радна хипотеза се променила, јер смо олабавили још једну претпоставку коју смо направили док смо мислили да постоји само један баг.

Можда нисмо гледали обичан повратак функције на NULL. Можда смо гледали unwind пренос — у суштини враћање регистара у стилу setcontext-а — где је одредишни показивач инструкције постао NULL пре преноса контроле. Другим речима, нетачни подаци из unwind библиотеке, а не нетачно место за повратну адресу на стеку.

То је драматично сузило проблем. Или је GNU libunwind израчунавао погрешно одредишно стање, или је израчунавао исправно стање, а нешто га је корумпирало пре него што је могло да се примени.

Прочитали смо изворни код GNU libunwind-а и открили да он синтетише ucontext_t на стеку, попуњава жељено стање регистара за оквир handler-а за чишћење, а затим предаје показивач на ту структуру интерној assembly рутини: _Ux86_64_setcontext.

У овом тренутку имали смо све делове.

Синтетисани ucontext_t живи у једном од стек оквира које _Ux86_64_setcontext unwinds током извршавања те функције. Да ли _Ux86_64_setcontext чита из структуре након што промени %rsp, у тренутку када структура више није део активног стека? То би је учинило рањивом на преписивање при испоруци сигнала, као што је наш чести SIGUSR2.

Одговор је био да.

Ево последњих шест инструкција _Ux86_64_setcontext у верзији GNU libunwind-а коју смо користили, које се углавном састоје од mov инструкција које учитавају из меморије у одредишни регистар:

(%rdi показује на ucontext_t алоциран на стеку, а макрои UC_MCONTEXT_* се само проширују у фиксни помак на којем је одређени регистар сачуван.)

Прва инструкција је почетак race window-а. Она ажурира %rsp тако да показује на ново дно активног стека. Чим се то деси, структура на коју показује %rdi више није део активног стека (нити red zone-а) и више није недодирљива за кернел.

Обично то не прави проблеме, али ако сигнал стигне у тачно правом (погрешном?) тренутку, кернел ће направити сигнални оквир на %rsp-128. То може да препише меморију на коју показује %rdi.

Ако се то деси пре него што следећа инструкција прочита UC_MCONTEXT_GREGS_RIP(%rdi), враћени показивач инструкције може бити корумпиран. У нашим падовима постао је NULL.

То је баг.

Овај assembly такође објашњава једно запажање које нас је збуњивало: зашто је функција X имала NULL у месту за повратну адресу претходног стек оквира.

setcontext је написан тако да враћа све регистре, укључујући %rdi, па тај регистар не може да користи за читање UC_MCONTEXT_GREGS_RIP(%rdi) у последњем тренутку преноса контроле. Уместо тога, вредност чита раније, чува је на стеку, враћа још неколико регистара, а затим користи retq да прочита сачувану вредност и пренесе контролу.

Оно што је у core dump-овима изгледало као „функција се вратила на NULL“ заправо је било „unwinder је синтетисао циљну повратну адресу на стеку, али је тај циљ корумпиран пре него што је пренос завршен“. Претпостављали смо да корупција места за повратну адресу мора да се деси на лицу места, јер нисмо знали ни за једно место где се (коруптибилни) подаци намерно уписују у место за повратну адресу.

Оно што овај баг чини апсурдним јесте колико је тај race window узак. У овој врсти race condition-а, спољни догађај (сигнал) мора да се деси између два корака која изводи друга нит. Што су ти кораци ближи један другом, мања је вероватноћа да ће се race condition десити.

У овом случају рањиви прозор је дословно широк једну инструкцију! Сигнал мора да буде испоручен након што је %rsp промењен, али пре него што следећа инструкција учита %rip. Неколико једноставних инструкција попут ове може да се изврши по циклусу на модерном superscalar out-of-order CPU-у, па је race window отприлике сто пикосекунди.

Када смо пронашли овај race, прва реакција нам је била да мора бити превише редак да објасни уочену стопу падова. Видели смо више од десетак return-to-null падова дневно у целој флоти. Да ли race од једне инструкције током чишћења изузетака заиста може то да објасни?

Окренули смо се Фермијевој процени. Ако је рањиви прозор реда величине $10^{-10}$ секунди, а SIGUSR2 стиже на сваких $10^{-2}$ секунди CPU времена, онда сваки handler за чишћење изузетка или catch блок има приближно $10^{-8}$ вероватноће да изгуби трку.

Rockset користи изузетке као део свог интерног механизма за backpressure при уносу. Један преоптерећен хост може да баци реда величине $10^{4}$ изузетака у секунди. То значи да је средње време између отказа хоста који користи backpressure $10^{4}$ секунди, односно један пад на сваких неколико сати. На нивоу флоте, то је више него довољно да објасни уочену учесталост падова.

Баг у GNU libunwind-у је стар — више од 18 година, присутан у првој x86_64 верзији која је подржавала C++ exception unwinding.

Зашто се онда појавио сада?

Стопа падова је приближно пропорционална броју бачених изузетака и броју испоручених сигнала. Такође зависи од тога колико стека троши handler сигнала.

Rockset је необичан по све три осе. Изузетке бацамо великом брзином као део нормалне контроле преоптерећења; SIGUSR2 испоручујемо неуобичајено често због coarse_thread_cputime_clock; а раније ове године учинили смо да handler за SIGUSR2 користи више стека додавањем позива timer_getoverrun, како бисмо могли да обрачунамо спојене сигнале.

Изгледа да је та последња промена била важна. Ако handler користи довољно мало стека, можда неће досегнути и преписати застарелу ucontext_t меморију. Пре те промене уопште не уочавамо ове падове. После промене стопа је остала ниска док нисмо повећали оптерећење за неке случајеве употребе који су напрегли механизам backpressure-а.

Другим речима, баг у libunwind-у је одувек био ту, али је производ наше стопе изузетака, стопе сигнала и употребе стека у handler-у тек недавно прешао праг на којем је постао оперативно видљив.

Овај механизам такође објашњава случајност да су и хардверски баг и баг у libunwind-у падали углавном унутар DocumentTree::updateDocument. Падови из libunwind-а били су снажно пристрасни ка овом методу, јер је он увек активан у тренутку када бацамо изузетак да применимо backpressure при уносу. Такође је био снажно издвојен код падова са погрешним поравнањем %rsp, јер је лош хардверски чвор био SKU који користимо за масовни унос, а он већину CPU времена проводи у том методу.

Наша непосредна мера ублажавања била је прелазак са GNU libunwind-а на libgcc-ов unwinder. То је и само по себи био добар компромис: libgcc-ова имплементација је имала користи од много рада на смањењу lock contention-а, што је важно при скалирању на велике VM-ове.

Такође смо у upstream послали самостални reproducer и исправку⁠(отвара се у новом прозору) за GNU libunwind, и проверили да други unwinder-и немају сличан проблем.

Ово дебагерско путовање научило нас је много о конкретним детаљима динамичког линковања, DWARF unwind метаподатака, испоруке Linux сигнала, System V ABI-ја и механизма C++ изузетака. Али главна лекција била је једноставнија од свега тога.

Најважнији корак није било паметно читање assembly-ја нити дубоко познавање детаља. Била је то изградња квалитетног скупа података. Без тог скупа података, мешали смо две различите појаве у једну причу и покушавали да се размишљањем извучемо из збрке. Када смо добили тачне и потпуне податке о популацији, структура проблема постала је очигледна: једна популација падова припадала је лошем хосту, а друга race-у у libunwind-у. Када су подаци постали бољи, дебаговање је постало лакше.

За инфраструктурне системе као што је Rockset, то је веома важно. Ова истрага је ојачала нашу посвећеност дубокој инструментацији, аутоматизованим истрагама и сталном унапређењу наших оперативних алата. Поузданост није само исправљање багова након што се десе — већ изградња података, токова рада и вештина који немогуће проблеме претварају у дијагностиковане и решиве.