Spåra PostgreSQL med perf

Profileringsverktyget perf som levereras med Linux-kärnan är extremt användbar för att undersöka systemomfattande och multiprocessbeteende – men det gör mycket mer än CPU-profileringen den ofta används för. Du har förmodligen tittat på perf top -az eller perf top -u postgres output, men det är bara det minsta av vad den kan göra. (Om du vill ha TL/DR-versionen, hoppa ner till "User space dynamic probes").

En av de stora fördelarna med perf är att det inte är påträngande. Du behöver inte bifoga en debugger och avbryta körningen. Du behöver inte köra kommandon direkt under en profilerare i en speciell miljö. Det finns inget behov av att starta om servern för att felsöka en problematisk arbetsbelastning, och ofta inget behov av att kompilera om med felsökningsalternativ. Detta är extremt användbart när du försöker spåra prestandaproblem i ett livesystem, eftersom det låter dig testa teorier om vad som kan hända snabbt och med minimal påverkan.

perf är inte bara en profilerare, den har också spårningsstöd. Profilering baseras på sampling av systemets tillstånd när det utlöses av maskin- eller mjukvaruprestandaräknare; det ger ett statistiskt urval av punkter där systemet tillbringar mest tid. Spårning tar istället prover när en viss spårningshändelse inträffar, så det är mycket mer användbart för sällsynta men viktiga händelser.

När du arbetar med PostgreSQL en av de mest spännande funktionerna i perf är förmågan att spåra processer i användarutrymmet . Vill du veta hur ofta din PostgreSQL byter WAL-segment, hur ofta den gör uppslagningar av främmande nyckel, etc? För en PostgreSQL-backend eller över hela klustret? perf kan hjälpa till med det.

Spårpunkter för användarutrymme och kärn-utrymme kan blandas och kan användas samtidigt som prestandaräknareprofilering för att hjälpa dig att få en bra bild av systemet. perf kan fånga stackspår från både kärnan och användarutrymmet, och kan även göra statistiska visualiseringar. Användarutrymmesspårpunkter skapas med dynamiska sonder; kernel-space kan vara fördefinierade eller kan vara dynamiska prober.

Så, hur använder du några av dessa funktioner?

Installera verktygen

Se först till att du använder en aktuell perf . Den här artikeln skrevs på Fedora 19 med perf 3.11.6 på x86_64, och några av funktionerna är relativt nya.

Om du vill ha resultat från användarutrymmesstack vill du att koden du tittar på ska byggas med -Og -ggdb -fno-omit-frame-pointer . Om du använder en perf byggd med libunwind du behöver inte rampekare; se detta Stack Overflow-inlägg och RH Bugzilla #1025603. Inget av detta behövs om du bara är intresserad av kärnsidedata. Om du använder distropaket kan du behöva installera -debuginfo paket också.

Alla följande tester kördes med lager PGDG PostgreSQL 9.2-paket från http://yum.postgresql.org/ med en perf ombyggd med libunwind stöd enligt ovanstående instruktioner.

Kärnspårpunkter och sonder

perf kan fånga data från fördefinierade kärnspårpunkter, av vilka några är informativa när man tittar på problem med minnesfragmentering, disk I/O, etc. Du kan få en lista över spårpunkter med sudo perf list . Spårpunktslistor kan anges och jokertecken stöds. Till exempel, om vi vill få skriv- och diskrensningsstatistik för en körande PostgreSQL-instans kan vi köra:

sudo perf record -g dwarf -e block:block_rq_issue,syscalls:sys_enter_fsync -u postgres sleep 10

för att fånga data. Istället för en sömn kan du inte använda något kommando och trycka på kontroll-C när du är klar med att fånga, eller så kan du använda något annat kommando som en psql -c för att utlösa den arbetsbelastning du vill mäta.

-u postgres profilerar alla processer som körs som användare postgres . Du kan istället använda -a för profilering av hela systemet över alla processorer. Det är också möjligt att spåra bara en backend. Starta psql , kör select pg_backend_pid() , kör perf med -p $the_pid , starta sedan arbetsbelastningen i samma psql session.

När du arbetar med PostgreSQL standardmålprocessen, vilket är kommandot som körs under kontroll av perf , är vanligtvis inte särskilt användbar eftersom backend gör det mesta av arbetet, inte psql . Det är fortfarande användbart att använda underkommandot för att kontrollera testets arbetsbelastning och timing.

När du har samlat in data kan du använda perf report att undersöka det. Det finns för många alternativ att diskutera här – för att kontrollera resultataggregering och förenkling, stackspårningsvisning, interaktiva förbannelser kontra utdata från textrapporter och mer.

Ta den här sessionen som ett exempel, där det finns en skalsession (terminal "T2") och en postgres-session kopplad till databasen "regress" (terminal "T1"):

T1| regress=> välj pg_backend_pid();T1| pg_backend_pid T1| ----------------T1| 4495T1|(1 rad)

T2| $ sudo perf record -g dwarf -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync -p 4495

T1| regress=> skapa tabell x som välj en FROM gener_series(1,1000000) a;T1| regress=>

T2| $ ^CT2| [ perf record:Vaknade 332 gånger för att skriva data ]T2| [ perf record:Fångade och skrev 86,404 MB perf.data (~3775041 exempel) ]T2|T2| $ sudo perf rapport -g

Du kan använda perf report 's curses gui för att gräva ner i spåret, eller så kan du använda perf-rapporten --stdio alternativ för att få den att strömma data till stdout. Om du till exempel vill ha stackspårningar kan du köra:

$ sudo perf report -g --stdio... blah blah ...# Exempel:1 av händelsen 'syscalls:sys_enter_fsync'# Antal händelser (ungefär):1## Overhead Command Shared Object Symbol# .. ...... ........ ............. .....................# 100,00 % postgres libc-2.17.so [.] __GI___libc_fsync | --- __GI___libc_fsync mdimedsync heap_sync intorel_shutdown standard_ExecutorRun ExecCreateTableAs PortalRunUtility PortalRunMulti PortalRun PostgresMain ServerLoop PostmasterMain main __libc_start_main _start (noll)... blah blah... 

 visar det för händelsen syscalls:sys_enter_fsync det fanns en händelse med ovanstående stack, en fsync som anropades via ExecCreateTableAs .
 

 (Av en anledning har jag ännu inte kunnat fästa den sista fsync() verkar inte fångas av perf när psql körs direkt under kontroll av perf . Det här är inte ett problem med perf stat , endast perf record . Det är därför jag hoppar genom bågar för att förvälja backend av pid ovan.)
 
Dynamiska prober för användarutrymme
 

 Ibland är du mer intresserad av att något händer inom PostgreSQL än händelser inom kärnan som triggas av PostgreSQL. Nyare versioner av perf kan hjälpa till med detta genom att infoga dynamiska spårpunkter som utlöser anrop i program för användarutrymme.
 

 Låt oss säga att du är intresserad av att titta på WAL-aktivitet och vill se när XLogFlush , XLogFileInit eller XLogFileOpen kallas. Du kan infoga dynamiska spårpunkter för dessa samtal med perf :
 
sudo perf probe -x `which postgres` XLogFileInitsudo perf probe -x `which postgres` XLogFileOpensudo perf probe -x `which postgres` XLogFlush
 

 Du kan bara undersöka externa symboler (icke-statiska, inte dolda av -fvisibility-flaggor) om du inte byggt med -ggdb . perf kommer att klaga på inga symboler hittades om du försöker använda en symbol som inte finns. I skrivande stund perf stöder inte användning av extern debuginfo för att leta upp symboler för sonder, även om den kan använda den för stackanalys. I allmänhet, om det är en extern i src/include du kan använda den med perf .
 

 Varje spårpunkt kommer att skriva ut namnet på den skapade spårpunkten och du kan använda perf probe -l för att lista dem alla ändå:
 
$ sudo perf sond -l probe_postgres:XLogFileInit (på 0x000000000009a360) probe_postgres:XLogFileOpen (på 0x000000000009a860) probe_postgres:XLogpres:XLogpre>07 (på 000000)
 Dessa sonder är nu användbara som perf-händelser. Låt oss ta en titt på xlog-aktivitet under ett exempel på arbetsbelastning, övervaka hela klustret medan jag kör en pgbench-körning:
 
sudo perf record -g dwarf -u postgres -e probe_postgres:XLogFileInit,probe_postgres:XLogFileOpen,probe_postgres:XLogFlush
 

 Prova själv med perf report -g  . Så här ser resultatet ut. Du kan använda alternativ som -g fractal,0 för att kontrollera detaljer. Du kommer att kunna se procentandelen av en given räknares träffar som kom från en eller annan stackgren, pid och process, etc. --sort alternativ ger dig mer kontroll över aggregering och gruppering.
 
Men vänta, det finns mer
 

 Du bör också kolla in perf-statistiken och perf top kommandon. De kan ta samma händelselistor som perf record , även om deras processfilterstöd av någon konstig anledning är annorlunda.
 

 Här är ett exempel som kör en dummy-arbetsbelastning och tittar på I/O-kärnans spårpunkter under körningen:
 
$ sudo perf stat -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync -a -r 5 -- psql -q -U postgres craig -c "släpp tabell om det finns x; skapa tabell x som välj en FROM generera_serier(1,1000000) a;"; Prestandaräknarestatistik för 'psql -U postgres craig -c släpptabell om det finns x; skapa tabell x som välj en FROM gener_series(1,1000000) a;' (5 körningar):0 block:block_rq_abort [100.00%] 0 block:block_rq_requeue [100.00%] 97 block:block_rq_complete ( +- 14.82% ) [100.00%] 96 block:block_rq_requeue [100.00%] 97 block:block_rq_complete ( +- 14.82% ) [100.00%] 96 block:block_rq_insert ( +- 0.9 %) 1.0 % 0. block:block_rq_issue ( +- 14.67% ) [100.00%] 0 block:block_rq_remap [100.00%]10 607 syscalls:sys_enter_write ( +- 0.17% ) [100.00%] 1 syscalls.5_fsys 8.8 sekund 8.5_0syns /pre> 

 Du kan se att det gör i genomsnitt cirka 100 blocklager I/O-förfrågningar över 10k write()s och gör en enda fsync(). En del av det är systembakgrundsljud eftersom vi gör all systemprofilering (-a ), men eftersom systemet är ganska inaktivt är det inte mycket, och det är ett medelvärde över fem körningar.
 

 På liknande sätt, med hjälp av de dynamiska sonderna vi lade till tidigare, håll ett öga på xlog-aktivitet under en pgbench-körning:
 
$ sudo perf stat -e probe_postgres:XLogFileInit,probe_postgres:XLogFileOpen,probe_postgres:XLogFlush -a -- /usr/pgsql-9.2/bin/pgbench -U postgres craig -c 2 -t 10000startvakuum...slut. transaktionstyp:TPC-B (typ av) skalningsfaktor:100frågeläge:enkelt antal klienter:2antal trådar:1antal transaktioner per klient:10000antal transaktioner som faktiskt behandlas:20000/20000tps =715.854663 (inklusive)16tps2 (inklusive)16tps2 (inklusive 16tps2. exklusive anslutningar som upprättas) Prestandaräknarestatistik för '/usr/pgsql-9.2/bin/pgbench -U postgres craig -c 2 -t 10000':64 probe_postgres:XLogFileInit [100.00%] 0 probe_postgres:XLogFileOpen:XLogFileOpen [%050.40] probe_postgres:XLogFileInit XLogFlush 27,987364469 sekunder förflutit
 

 Det finns mycket mer du kan göra, inklusive att fånga tillståndet för lokala variabler med perf probe . Jag kommer att skriva upp några användbara exempel på det senare. Under tiden kan du leka, utforska och ha kul med ett nytt diagnostiskt verktyg.
 

 Uppdatering: Michael Paquier skrev nyligen en relaterad artikel om att spåra PostgreSQL med systemtap som kan vara av intresse för läsarna av denna. Du måste kompilera om Pg för att använda det tillvägagångssättet, men syntaxen är trevligare och den erbjuder några andra fördelar.