Linux té un gran nombre d'eines per depurar el nucli i les aplicacions. La majoria d'ells tenen un impacte negatiu en el rendiment de l'aplicació i no es poden utilitzar en producció.
Fa un parell d'anys n'hi havia - eBPF. Permet rastrejar el nucli i les aplicacions d'usuari amb poca sobrecàrrega i sense necessitat de reconstruir programes i carregar mòduls de tercers al nucli.
Ja hi ha moltes utilitats d'aplicacions que utilitzen eBPF, i en aquest article veurem com escriure la vostra pròpia utilitat de perfilació basada en la biblioteca . L'article està basat en fets reals. Passarem d'un problema a un altre per mostrar com es poden utilitzar les utilitats existents en situacions específiques.
Ceph és lent
S'ha afegit un nou amfitrió al clúster Ceph. Després de migrar-hi algunes de les dades, ens vam adonar que la velocitat de processament de les sol·licituds d'escriptura era molt inferior a la d'altres servidors.
A diferència d'altres plataformes, aquest amfitrió va utilitzar bcache i el nou nucli de Linux 4.15. Aquesta va ser la primera vegada que s'utilitzava un amfitrió d'aquesta configuració aquí. I en aquell moment estava clar que l'arrel del problema podia ser teòricament qualsevol cosa.
Investigant l'amfitrió
Comencem mirant què passa dins del procés ceph-osd. Per a això farem servir и (més sobre el qual podeu llegir ):
La imatge ens diu que la funció fdatasync() va passar molt de temps enviant una sol·licitud a les funcions generic_make_request(). Això vol dir que el més probable és que la causa dels problemes estigui en algun lloc fora del propi dimoni osd. Aquest pot ser el nucli o els discs. La sortida iostat va mostrar una alta latència en el processament de les sol·licituds dels discos bcache.
Quan comprovem l'amfitrió, vam trobar que el dimoni systemd-udevd consumeix una gran quantitat de temps de CPU, al voltant del 20% en diversos nuclis. Aquest és un comportament estrany, així que cal esbrinar per què. Com que Systemd-udevd funciona amb uevents, vam decidir examinar-los monitor udevadm. Resulta que es van generar un gran nombre d'esdeveniments de canvi per a cada dispositiu de bloc del sistema. Això és força inusual, així que haurem de mirar què genera tots aquests esdeveniments.
Ús del kit d'eines BCC
Com ja hem esbrinat, el nucli (i el dimoni ceph a la trucada del sistema) passa molt de temps a generic_make_request(). Intentem mesurar la velocitat d'aquesta funció. EN Ja hi ha una utilitat meravellosa: funcionalitat. Seguirem el dimoni pel seu PID amb un interval d'1 segon entre sortides i sortirem el resultat en mil·lisegons.
Aquesta característica sol funcionar ràpidament. Tot el que fa és passar la sol·licitud a la cua del controlador del dispositiu.
Bcache és un dispositiu complex que en realitat consta de tres discos:
- dispositiu de suport (disc en memòria cau), en aquest cas és un HDD lent;
- dispositiu de memòria cau (disc de memòria cau), aquí aquesta és una partició del dispositiu NVMe;
- el dispositiu virtual bcache amb el qual s'executa l'aplicació.
Sabem que la transmissió de sol·licituds és lenta, però per a quin d'aquests dispositius? Ens ocuparem d'això una mica més endavant.
Ara sabem que els esdeveniments poden causar problemes. Trobar què és exactament el que causa la seva generació no és tan fàcil. Suposem que es tracta d'un tipus de programari que es llança periòdicament. Vegem quin tipus de programari s'executa al sistema mitjançant un script execsnoop del mateix . Executem-lo i enviem la sortida a un fitxer.
Per exemple com aquest:
/usr/share/bcc/tools/execsnoop | tee ./execdump
No mostrarem la sortida completa d'execsnoop aquí, però una línia d'interès per a nosaltres semblava així:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
La tercera columna és el PPID (PID principal) del procés. El procés amb PID 5802 va resultar ser un dels fils del nostre sistema de monitorització. En comprovar la configuració del sistema de monitorització, s'han trobat paràmetres erronis. La temperatura de l'adaptador HBA es va prendre cada 30 segons, que és molt més freqüent del necessari. Després de canviar l'interval de comprovació a un de més llarg, vam trobar que la latència de processament de sol·licituds en aquest amfitrió ja no destacava en comparació amb altres amfitrions.
Però encara no està clar per què el dispositiu bcache era tan lent. Vam preparar una plataforma de prova amb una configuració idèntica i vam intentar reproduir el problema executant fio a bcache, executant periòdicament udevadm trigger per generar uevents.
Eines de redacció basades en BCC
Intentem escriure una utilitat senzilla per rastrejar i mostrar les trucades més lentes generic_make_request(). També ens interessa el nom de la unitat per a la qual es va cridar aquesta funció.
El pla és senzill:
- Registra't ksonda en generic_make_request():
- Desem el nom del disc a la memòria, accessible mitjançant l'argument de la funció;
- Guardem la marca de temps.
- Registra't kretprobe per tornar de generic_make_request():
- Obtenim la marca de temps actual;
- Busquem la marca de temps desada i la comparem amb l'actual;
- Si el resultat és superior a l'especificat, trobarem el nom del disc desat i el mostrem al terminal.
Ksondes и kretsondes utilitzeu un mecanisme de punt d'interrupció per canviar el codi de funció sobre la marxa. Pots llegir и article sobre aquest tema. Si mireu el codi de diverses utilitats a , llavors podeu veure que tenen una estructura idèntica. Per tant, en aquest article ens saltarem l'anàlisi dels arguments de l'script i passarem al propi programa BPF.
El text eBPF dins de l'script Python té aquest aspecte:
bpf_text = “”” # Here will be the bpf program code “””
Per intercanviar dades entre funcions, utilitzen programes eBPF . Farem el mateix. Utilitzarem el PID del procés com a clau i definirem l'estructura com el valor:
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);
Aquí registrem una taula hash anomenada p, amb tipus de clau u64 i un valor de tipus struct data_t. La taula estarà disponible en el context del nostre programa BPF. La macro BPF_PERF_OUTPUT registra una altra taula cridada events, que s'utilitza per a l'espai d'usuari.
Quan es mesuren els retards entre la trucada d'una funció i el retorn d'aquesta, o entre les trucades a diferents funcions, cal tenir en compte que les dades rebudes han de pertànyer al mateix context. En altres paraules, cal recordar el possible llançament paral·lel de funcions. Tenim la capacitat de mesurar la latència entre la crida d'una funció en el context d'un procés i el retorn d'aquesta funció en el context d'un altre procés, però és probable que això sigui inútil. Un bon exemple seria aquí , on la clau de la taula hash s'estableix en un punter a sol·licitud d'estructura, que reflecteix una sol·licitud de disc.
A continuació, hem d'escriure el codi que s'executarà quan es cridi la funció en estudi:
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);
}
Aquí el primer argument de la funció cridada es substituirà com el segon argument . Després d'això, obtenim el PID del procés en el context del qual estem treballant i la marca de temps actual en nanosegons. Ho anotem tot en un quadre acabat de seleccionar struct data_t dades. Obtenim el nom del disc de l'estructura bio, que es passa en trucar generic_make_request(), i deseu-lo a la mateixa estructura dades. L'últim pas és afegir una entrada a la taula hash que es va esmentar anteriorment.
La següent funció es cridarà en tornar de generic_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);
}
}
Aquesta funció és similar a l'anterior: descobrim el PID del procés i la marca de temps, però no assignem memòria per a la nova estructura de dades. En canvi, cerquem a la taula hash una estructura ja existent utilitzant la clau == PID actual. Si es troba l'estructura, descobrim el nom del procés en execució i l'afegim.
El desplaçament binari que fem servir aquí és necessari per obtenir el fil GID. aquells. PID del procés principal que va posar en marxa el fil en el context del qual estem treballant. La funció que anomenem retorna tant el GID del fil com el seu PID en un sol valor de 64 bits.
En sortir al terminal, actualment no ens interessa el fil, però sí el procés principal. Després de comparar el retard resultant amb un llindar determinat, passem la nostra estructura dades a l'espai d'usuari mitjançant una taula events, després del qual suprimim l'entrada de p.
A l'script Python que carregarà aquest codi, hem de substituir MIN_US i FACTOR amb els llindars de retard i les unitats de temps, que passarem pels arguments:
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"
Ara hem de preparar el programa BPF via i registre mostres:
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")
També haurem de determinar struct data_t al nostre guió, en cas contrari no podrem llegir res:
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)]
L'últim pas és enviar dades al 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()
El guió en si està disponible a . Provem d'executar-lo en una plataforma de prova on fio s'està executant, escrivint a bcache i trucant a udevadm monitor:
Per fi! Ara veiem que el que semblava un dispositiu bcache aturat és en realitat una trucada aturada generic_make_request() per a un disc a la memòria cau.
Exploreu el nucli
Què s'està alentint exactament durant la transmissió de la sol·licitud? Veiem que el retard es produeix fins i tot abans de l'inici de la comptabilitat de la sol·licitud, és a dir. La comptabilització d'una sol·licitud específica per obtenir més estadístiques (/proc/diskstats o iostat) encara no ha començat. Això es pot verificar fàcilment executant iostat mentre es reprodueix el problema, o bé , que es basa en l'inici i el final de la comptabilitat de la sol·licitud. Cap d'aquestes utilitats mostrarà problemes per a les sol·licituds al disc de la memòria cau.
Si mirem la funció generic_make_request(), llavors veurem que abans de començar la comptabilitat de la sol·licitud, es criden dues funcions més. Primer - generic_make_request_checks(), realitza comprovacions de la legitimitat de la sol·licitud pel que fa a la configuració del disc. segon - , que té un repte interessant :
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));
En ell, el nucli espera que la cua es descongeli. Mesurem el retard 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 | |
Sembla que estem a prop d'una solució. Les funcions que s'utilitzen per congelar/descongelar una cua són и . S'utilitzen quan cal canviar la configuració de la cua de sol·licituds, que són potencialment perilloses per a les sol·licituds d'aquesta cua. En trucar blk_mq_freeze_queue() funció el comptador s'incrementa q->mq_freeze_depth. Després d'això, el nucli espera que la cua es buidi .
El temps que triga a esborrar aquesta cua és equivalent a la latència del disc, ja que el nucli espera que es completin totes les operacions a la cua. Un cop la cua està buida, s'apliquen els canvis de configuració. Després del qual es diu , disminuint el comptador congelar_profunditat.
Ara en sabem prou per corregir la situació. L'ordre d'activació udevadm fa que s'apliquin la configuració del dispositiu de bloc. Aquests paràmetres es descriuen a les regles udev. Podem trobar quins paràmetres estan congelant la cua intentant canviar-los mitjançant sysfs o mirant el codi font del nucli. També podem provar la utilitat BCC , que generarà traces de pila del nucli i l'espai d'usuari per a cada trucada al terminal blk_freeze_queue, per exemple:
~# /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]
Les regles d'Udev canvien molt poques vegades i normalment això passa de manera controlada. Així doncs, veiem que fins i tot aplicar els valors ja establerts provoca un augment en el retard en la transferència de la sol·licitud de l'aplicació al disc. Per descomptat, generar esdeveniments udev quan no hi ha canvis en la configuració del disc (per exemple, el dispositiu no està muntat/desconnectat) no és una bona pràctica. Tanmateix, podem ajudar el nucli a no fer treballs innecessaris i congelar la cua de sol·licituds si no és necessari. corregir la situació.
Conclusió
eBPF és una eina molt flexible i potent. A l'article vam analitzar un cas pràctic i vam demostrar una petita part del que es pot fer. Si esteu interessats a desenvolupar utilitats BCC, val la pena fer-hi una ullada , que descriu bé les bases.
Hi ha altres eines de depuració i perfilació interessants basades en eBPF. Un d'ells - , que us permet escriure una línia potents i petits programes en el llenguatge awk. Un altre - , us permet recollir mètriques de baix nivell i alta resolució directament al vostre servidor Prometheus, amb la possibilitat d'obtenir més tard visualitzacions boniques i fins i tot alertes.
Font: www.habr.com