Linux heeft een groot aantal tools voor het debuggen van de kernel en applicaties. De meeste daarvan hebben een negatieve invloed op de applicatieprestaties en kunnen niet in de productie worden gebruikt.
Een paar jaar geleden was dat zo - eBPF. Het maakt het mogelijk om de kernel en gebruikersapplicaties te traceren met weinig overhead en zonder de noodzaak om programma's opnieuw op te bouwen en modules van derden in de kernel te laden.
Er zijn al veel applicatiehulpprogramma's die eBPF gebruiken, en in dit artikel zullen we bekijken hoe u uw eigen profileringshulpprogramma kunt schrijven op basis van de bibliotheek . Het artikel is gebaseerd op echte gebeurtenissen. We gaan van probleem naar oplossing om te laten zien hoe bestaande hulpprogramma's in specifieke situaties kunnen worden gebruikt.
Ceph is langzaam
Er is een nieuwe host toegevoegd aan het Ceph-cluster. Nadat we een deel van de gegevens ernaar hadden gemigreerd, merkten we dat de snelheid waarmee schrijfverzoeken werden verwerkt veel lager was dan op andere servers.
In tegenstelling tot andere platforms gebruikte deze host bcache en de nieuwe Linux 4.15-kernel. Dit was de eerste keer dat een host van deze configuratie hier werd gebruikt. En op dat moment was het duidelijk dat de oorzaak van het probleem in theorie van alles kon zijn.
Onderzoek naar de gastheer
Laten we beginnen met te kijken naar wat er gebeurt binnen het ceph-osd-proces. Hiervoor zullen we gebruiken и (waarover u meer kunt lezen ):
De afbeelding vertelt ons dat de functie fdatasync() besteedde veel tijd aan het verzenden van een verzoek naar functies generieke_make_request(). Dit betekent dat de oorzaak van de problemen hoogstwaarschijnlijk ergens buiten de osd-daemon zelf ligt. Dit kan de kernel of schijven zijn. De iostat-uitvoer vertoonde een hoge latentie bij het verwerken van verzoeken door bcache-schijven.
Bij het controleren van de host ontdekten we dat de systemd-udevd-daemon een grote hoeveelheid CPU-tijd verbruikt - ongeveer 20% op verschillende cores. Dit is vreemd gedrag, dus je moet uitzoeken waarom. Omdat Systemd-udevd met uevents werkt, hebben we besloten ze eens door te nemen udevadm-monitor. Het blijkt dat er voor elk blokapparaat in het systeem een groot aantal wijzigingsgebeurtenissen is gegenereerd. Dit is nogal ongebruikelijk, dus we zullen moeten kijken naar de oorzaak van al deze gebeurtenissen.
Met behulp van de BCC-toolkit
Zoals we al hebben ontdekt, besteedt de kernel (en de ceph-daemon in de systeemaanroep) veel tijd in generieke_make_request(). Laten we proberen de snelheid van deze functie te meten. IN Er is al een prachtig hulpprogramma - funclatentie. We zullen de daemon traceren aan de hand van zijn PID met een interval van 1 seconde tussen de uitvoer en het resultaat in milliseconden uitvoeren.
Deze functie werkt meestal snel. Het enige wat het doet is het verzoek doorgeven aan de wachtrij van het apparaatstuurprogramma.
Bcache is een complex apparaat dat eigenlijk uit drie schijven bestaat:
- back-upapparaat (gecachte schijf), in dit geval is het een trage HDD;
- caching-apparaat (caching-schijf), hier is dit één partitie van het NVMe-apparaat;
- het virtuele bcache-apparaat waarmee de applicatie wordt uitgevoerd.
We weten dat de verzending van verzoeken traag is, maar voor welke van deze apparaten? We zullen dit iets later behandelen.
We weten nu dat gebeurtenissen waarschijnlijk problemen zullen veroorzaken. Het vinden van wat precies de oorzaak is van hun generatie is niet zo eenvoudig. Laten we aannemen dat dit een soort software is die periodiek wordt gelanceerd. Laten we eens kijken wat voor soort software op het systeem draait met behulp van een script execsnoop van hetzelfde . Laten we het uitvoeren en de uitvoer naar een bestand sturen.
Bijvoorbeeld als volgt:
/usr/share/bcc/tools/execsnoop | tee ./execdump
We zullen hier niet de volledige uitvoer van execsnoop laten zien, maar een voor ons interessante regel zag er als volgt uit:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
De derde kolom is de PPID (ouder-PID) van het proces. Het proces met PID 5802 bleek een van de rode draden van ons monitoringsysteem. Bij het controleren van de configuratie van het monitoringsysteem werden foutieve parameters gevonden. De temperatuur van de HBA-adapter werd elke 30 seconden gemeten, wat veel vaker is dan nodig. Nadat we het controle-interval hadden gewijzigd naar een langer interval, ontdekten we dat de latentie bij het verwerken van verzoeken op deze host niet langer opviel in vergelijking met andere hosts.
Maar het is nog steeds onduidelijk waarom het bcache-apparaat zo traag was. We hebben een testplatform met een identieke configuratie voorbereid en geprobeerd het probleem te reproduceren door fio op bcache uit te voeren, en periodiek de udevadm-trigger uit te voeren om uevents te genereren.
Op BCC gebaseerde tools schrijven
Laten we proberen een eenvoudig hulpprogramma te schrijven om de langzaamste oproepen te traceren en weer te geven generieke_make_request(). We zijn ook geïnteresseerd in de naam van de schijf waarvoor deze functie werd aangeroepen.
Het schema is eenvoudig:
- Register kprobe op generieke_make_request():
- We slaan de schijfnaam op in het geheugen, toegankelijk via het functieargument;
- We bewaren de tijdstempel.
- Register Kretprobe voor terugkeer van generieke_make_request():
- We krijgen de huidige tijdstempel;
- We zoeken naar de opgeslagen tijdstempel en vergelijken deze met de huidige;
- Als het resultaat groter is dan het opgegeven resultaat, vinden we de opgeslagen schijfnaam en geven deze weer op de terminal.
Ksondes и Kretprobes gebruik een breekpuntmechanisme om functiecode direct te wijzigen. Jij kunt lezen и artikel over dit onderwerp. Als je naar de code van verschillende hulpprogramma's kijkt in , dan kun je zien dat ze een identieke structuur hebben. In dit artikel slaan we dus het parseren van scriptargumenten over en gaan we verder met het BPF-programma zelf.
De eBPF-tekst in het Python-script ziet er als volgt uit:
bpf_text = “”” # Here will be the bpf program code “””
Om gegevens tussen functies uit te wisselen, gebruiken eBPF-programma's . Wij zullen hetzelfde doen. We zullen het proces-PID als sleutel gebruiken en de structuur als waarde definiëren:
struct data_t {
u64 pid;
u64 ts;
char comm[TASK_COMM_LEN];
u64 lat;
char disk[DISK_NAME_LEN];
};
BPF_HASH(p, u64, struct data_t);
BPF_PERF_OUTPUT(events);
Hier registreren we een hashtabel genaamd p, met sleuteltype u64 en een waarde van type struct data_t. De tabel zal beschikbaar zijn in het kader van ons BPF-programma. De macro BPF_PERF_OUTPUT registreert een andere aangeroepen tabel EVENTS, waarvoor wordt gebruikt in de gebruikersruimte.
Bij het meten van vertragingen tussen het aanroepen van een functie en het terugkeren ervan, of tussen het aanroepen van verschillende functies, moet u er rekening mee houden dat de ontvangen gegevens tot dezelfde context moeten behoren. Met andere woorden, u moet rekening houden met de mogelijke parallelle lancering van functies. We hebben de mogelijkheid om de latentie te meten tussen het aanroepen van een functie in de context van het ene proces en het terugkeren van die functie in de context van een ander proces, maar dit is waarschijnlijk nutteloos. Een goed voorbeeld zou hier zijn , waarbij de hashtabelsleutel is ingesteld op een verwijzing naar struct verzoek, wat één schijfverzoek weerspiegelt.
Vervolgens moeten we de code schrijven die wordt uitgevoerd wanneer de onderzochte functie wordt aangeroepen:
void start(struct pt_regs *ctx, struct bio *bio) {
u64 pid = bpf_get_current_pid_tgid();
struct data_t data = {};
u64 ts = bpf_ktime_get_ns();
data.pid = pid;
data.ts = ts;
bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name);
p.update(&pid, &data);
}
Hier wordt het eerste argument van de aangeroepen functie vervangen door het tweede argument . Hierna krijgen we de PID van het proces in de context waarin we werken, en de huidige tijdstempel in nanoseconden. Wij schrijven het allemaal op in een vers geselecteerd struct data_t gegevens. We halen de schijfnaam uit de structuur bio, die wordt doorgegeven bij het bellen generieke_make_request()en sla het op in dezelfde structuur gegevens. De laatste stap is het toevoegen van een vermelding aan de eerder genoemde hashtabel.
Bij terugkomst uit wordt de volgende functie aangeroepen generieke_make_request():
void stop(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
u64 ts = bpf_ktime_get_ns();
struct data_t* data = p.lookup(&pid);
if (data != 0 && data->ts > 0) {
bpf_get_current_comm(&data->comm, sizeof(data->comm));
data->lat = (ts - data->ts)/1000;
if (data->lat > MIN_US) {
FACTOR
data->pid >>= 32;
events.perf_submit(ctx, data, sizeof(struct data_t));
}
p.delete(&pid);
}
}
Deze functie is vergelijkbaar met de vorige: we ontdekken de PID van het proces en de tijdstempel, maar wijzen geen geheugen toe voor de nieuwe datastructuur. In plaats daarvan zoeken we in de hashtabel naar een reeds bestaande structuur met behulp van de sleutel == huidige PID. Als de structuur wordt gevonden, achterhalen we de naam van het lopende proces en voegen deze eraan toe.
De binaire verschuiving die we hier gebruiken is nodig om de thread-GID te verkrijgen. die. PID van het hoofdproces waarmee de thread is gestart in de context waarin we werken. De functie die we noemen retourneert zowel de GID als de PID van de thread in een enkele 64-bits waarde.
Bij uitvoer naar de terminal zijn we momenteel niet geïnteresseerd in de thread, maar wel in het hoofdproces. Nadat we de resulterende vertraging hebben vergeleken met een bepaalde drempel, passeren we onze structuur gegevens in de gebruikersruimte via een tafel EVENTS, waarna we de vermelding verwijderen uit p.
In het Python-script dat deze code laadt, moeten we MIN_US en FACTOR vervangen door de vertragingsdrempels en tijdseenheden, die we door de argumenten zullen doorgeven:
bpf_text = bpf_text.replace('MIN_US',str(min_usec))
if args.milliseconds:
bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;')
label = "msec"
else:
bpf_text = bpf_text.replace('FACTOR','')
label = "usec"
Nu moeten we het BPF-programma voorbereiden via en registreer monsters:
b = BPF(text=bpf_text)
b.attach_kprobe(event="generic_make_request",fn_name="start")
b.attach_kretprobe(event="generic_make_request",fn_name="stop")
Wij zullen het ook moeten bepalen struct data_t in ons script, anders kunnen we niets lezen:
TASK_COMM_LEN = 16 # linux/sched.h
DISK_NAME_LEN = 32 # linux/genhd.h
class Data(ct.Structure):
_fields_ = [("pid", ct.c_ulonglong),
("ts", ct.c_ulonglong),
("comm", ct.c_char * TASK_COMM_LEN),
("lat", ct.c_ulonglong),
("disk",ct.c_char * DISK_NAME_LEN)]
De laatste stap is het uitvoeren van gegevens naar de terminal:
def print_event(cpu, data, size):
global start
event = ct.cast(data, ct.POINTER(Data)).contents
if start == 0:
start = event.ts
time_s = (float(event.ts - start)) / 1000000000
print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk))
b["events"].open_perf_buffer(print_event)
# format output
start = 0
while 1:
try:
b.perf_buffer_poll()
except KeyboardInterrupt:
exit()
Het script zelf is beschikbaar op . Laten we proberen het uit te voeren op een testplatform waarop fio draait, naar bcache schrijven en udevadm-monitor aanroepen:
Eindelijk! Nu zien we dat wat leek op een vastlopend bcache-apparaat in werkelijkheid een vastlopend gesprek is generieke_make_request() voor een cacheschijf.
Graaf in de Kernel
Wat vertraagt precies tijdens het verzenden van verzoeken? We zien dat de vertraging al optreedt vóór het begin van de aanvraagboekhouding, d.w.z. de verwerking van een specifiek verzoek om verdere uitvoer van statistieken hierover (/proc/diskstats of iostat) is nog niet begonnen. Dit kan eenvoudig worden geverifieerd door iostat uit te voeren terwijl het probleem wordt gereproduceerd, of , die is gebaseerd op het begin en het einde van de aanvraagboekhouding. Geen van deze hulpprogramma's zal problemen opleveren voor verzoeken aan de in de cache opgeslagen schijf.
Als we naar de functie kijken generieke_make_request(), dan zullen we zien dat voordat de aanvraagboekhouding begint, er nog twee functies worden aangeroepen. Eerst - generic_make_request_checks(), voert controles uit op de legitimiteit van het verzoek met betrekking tot de schijfinstellingen. Seconde - , dat een interessante uitdaging heeft :
ret = wait_event_interruptible(q->mq_freeze_wq,
(atomic_read(&q->mq_freeze_depth) == 0 &&
(preempt || !blk_queue_preempt_only(q))) ||
blk_queue_dying(q));
Daarin wacht de kernel tot de wachtrij weer vrijkomt. Laten we de vertraging meten blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end.
msecs : count distribution
0 -> 1 : 341 |****************************************|
msecs : count distribution
0 -> 1 : 316 |****************************************|
msecs : count distribution
0 -> 1 : 255 |****************************************|
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 1 | |
Het lijkt erop dat we dicht bij een oplossing zijn. De functies die worden gebruikt om een wachtrij te bevriezen/deblokkeren zijn: и . Ze worden gebruikt wanneer het nodig is om de instellingen van de verzoekenwachtrij te wijzigen, wat potentieel gevaarlijk is voor verzoeken in deze wachtrij. Bij het bellen blk_mq_freeze_queue() functie de teller wordt verhoogd q->mq_freeze_diepte. Hierna wacht de kernel tot de wachtrij leeg is .
De tijd die nodig is om deze wachtrij leeg te maken, is gelijk aan de schijflatentie terwijl de kernel wacht tot alle bewerkingen in de wachtrij zijn voltooid. Zodra de wachtrij leeg is, worden de wijzigingen in de instellingen toegepast. Daarna wordt gebeld , het verlagen van de teller bevriezen_diepte.
Nu weten we genoeg om de situatie te corrigeren. Het udevadm-triggercommando zorgt ervoor dat de instellingen voor het blokapparaat worden toegepast. Deze instellingen worden beschreven in de udev-regels. We kunnen ontdekken welke instellingen de wachtrij bevriezen door te proberen deze te wijzigen via sysfs of door naar de kernelbroncode te kijken. We kunnen ook het BCC-hulpprogramma proberen , die kernel- en gebruikersruimte-stack-traceringen uitvoert voor elke aanroep naar de terminal blk_freeze_queue, bijvoorbeeld:
~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U
PID TID COMM FUNC
3809642 3809642 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
elevator_switch+0x29 [kernel]
elv_iosched_store+0x197 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
3809631 3809631 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
queue_requests_store+0xb6 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
Udev-regels veranderen vrij zelden en meestal gebeurt dit op een gecontroleerde manier. We zien dus dat zelfs het toepassen van de reeds ingestelde waarden een piek veroorzaakt in de vertraging bij het overbrengen van het verzoek van de applicatie naar de schijf. Natuurlijk is het genereren van udev-gebeurtenissen wanneer er geen wijzigingen zijn in de schijfconfiguratie (het apparaat is bijvoorbeeld niet aangekoppeld/losgekoppeld) geen goede gewoonte. We kunnen de kernel echter helpen geen onnodig werk te doen en de wachtrij met verzoeken bevriezen als dit niet nodig is. corrigeer de situatie.
Conclusie
eBPF is een zeer flexibel en krachtig hulpmiddel. In het artikel hebben we één praktijkcasus bekeken en een klein deel gedemonstreerd van wat er kan worden gedaan. Als je geïnteresseerd bent in het ontwikkelen van BCC-hulpprogramma's, is het de moeite waard om er eens naar te kijken , waarin de basis goed wordt beschreven.
Er zijn nog andere interessante tools voor foutopsporing en profilering op basis van eBPF. Een van hen - , waarmee je krachtige oneliners en kleine programma's in de awk-achtige taal kunt schrijven. Een andere - , kunt u metrische gegevens op laag niveau en hoge resolutie rechtstreeks op uw prometheus-server verzamelen, met de mogelijkheid om later prachtige visualisaties en zelfs waarschuwingen te ontvangen.
Bron: www.habr.com