Questo documento contiene delle brevi istruzioni su come 1) Eseguire un test di startup time con la suite S 2) Attivare le tracce 3) Analizzare le tracce REQUISITI Meglio avere una ventina/trentina di GB liberi sul disco di sistema. PROCURARSI E FAMILIARIZZARE CON LA SUITE Il primo passo è procurarsi la suite, ad esempio: git clone https://github.com/Algodev-github/S.git Entrate nella cartella S, e leggetevi per bene il README, così da farvi un'idea generale. Eventualmente installatevi le dipendenze. Se non lo fate, gli script stessi dovrebbero poi segnalarvi man mano cosa dovete installare. Se volete anticiparvi, potreste eseguire: apt-get install fio sysstat gnuplot xterm mplayer time O comandi equivalenti in sistemi non apt-based NEL CASO PROVATE A FARE TEST DI START-UP DENTRO UNA MACCHINA VIRTUALE In questo caso, vi dovete assicurare che la macchina virtuale non usi la cache dell'host. Ad esempio, per VirtualBox, controllate, nel pannello "Archiviazione", se è selezionata la casellina "Usa cache host" per il controller utilizzato per il vostro disco virtuale. Attenti a non confondervi col controller IDE, che di norma è utilizzato per il CD. Purtroppo, su alcuni sistemi host, VirtualBox fa comunque caching anche se questa casellina non è selezionata. Ve ne accorgete dal fatto che nei test vedete dei throughput irrealisticamente alti e della latenze irrealisticamente basse. Al contrario, QEMU/KVM non da problemi da questo punto di vista, perché selezionate "none" in "Show Virtual Details"->"IDE/SATA Disk"->Performance->"Cache Mode". Le macchine virtuali danno poi una interessante possibilità: scegliere la velocità dell'I/O. Questa possibilità è presente quantomeno in VirtualBox, mediante il seguente comando (che forse deve essere preceduto da un ulteriore comando per creare il gruppo Limit): VBoxManage bandwidthctl set Limit --limit Ad esempio: VBoxManage bandwidthctl "Ubuntu 16.04" set Limit --limit 50M VBoxManage bandwidthctl "Ubuntu 16.04" set Limit --limit 2G # praticamente, no limiti Attenzione al fatto che un device virtuale limitato in banda ha comportamenti 'anomali' rispetto ad un dispositivo vero. Una delle anomalie più evidenti è che il dispositivo va a velocità non limitata per molto tempo (ordine del secondo), dopodiché recupera la velocità eccessiva rimanendo quasi fermo per il secondo successivo, e così via. Negli intervalli di tempo in cui va a velocità non limitata, se il dispositivo di storage fisico è molto veloce (o se i dati sono già nella cache dell'host), il tempo di completamento di una richiesta può facilmente essere comparabile se non inferiore al tempo di elaborazione di tale richiesta da parte dello stack di I/O del sistema operativo. Pertanto le garanzie di servizio fornite su un tale disco dipendono anche da cosa accade sulla CPU, e sono quindi in parte fuori del controllo dello scheduler dell'I/O. In aggiunta a questa perdita di controllo, la banda di I/O ricevuta da un processo dipende fortemente anche da quante volta ha avuto la sfortuna di avere le proprie richieste servite nell'intervallo di tempo in cui il disco virtuale si è fermato per recuperare l'alta velocità' raggiunta nell'intervallo precedente. ESEGUIRE IL TEST DI STARTUP Il test che ci interessa è comm_startup_lat. Quindi: cd comm_startup_lat/ sudo ./comm_startup_lat.sh -h # vi fate un'idea di come si usa Per eseguire un test che sta dando problemi ultimamente: sudo ./comm_startup_lat.sh bfq-mq 5 5 rand 3 "lowriter --terminate-after-init" ACCENDERE LE TRACCE Passiamo all'uso delle tracce. Per attivare le tracce basta modificare il file config_params.sh (nella cartella radice di S), e trasformare la riga TRACE=0 in TRACE=1 A questo punto, se si ripete il test, lo script provvederà ad accendere e spegnere il tracing per noi durante il test. RIDURSI ALLA SITUAZIONE PIU' SEMPLICE Quando si va a caccia di bachi, è sempre conveniente ridursi nella situazione più semplice possibile in cui il problema si verifica. Quindi, un primissimo passo potrebbe essere quello di far eseguire una sola iterazione allo script: sudo ./comm_startup_lat.sh bfq-mq 5 5 rand 1 "lowriter --terminate-after-init" COPIARSI E VISUALIZZARE LA TRACCIA Fatto questo, andiamo a prenderci la traccia. La troviamo nel seguente file di sistema, per accedere alla quale dobbiamo essere root: /sys/kernel/debug/tracing/trace La traccia è molto spesso enorme (centinaia di MB o anche qualche GB). Per lavorarci più velocemente, è necessario copiarsela in un file regolare. sudo cp /sys/kernel/debug/tracing/trace Uno dei visualizzatori che funziona meglio per analizzare dei file così grandi è less, io uso sempre quello ormai. COME SONO FATTI I MESSAGGI NELLA TRACCIA I messaggi di nostro maggiore interesse nella traccia sono quelli generati da BFQ stesso. Tali messaggi sono generati attraverso le macro bfq_log e bfq_log_bfqq. Ecco un esempio di riga di traccia contenente un messaggio generato da BFQ: comm_startup_la-3863 [000] dNh2 1121.261176: 8,0 m N bfq3956S / putting rq ffff8801f34b9a00 with 0 sects left, STARTED 2 Ed ecco il significato dei campi che ci interessano di più: comm_startup_la-3863 Nome e PID del processo in esecuzione quando il messaggio è stato generato 1121.261176 Timestamp del messaggio (quando è stato generato) in secondi 8,0 Major e minor number del dispositivo per cui è stato generato il messaggio bfq3956S Identificatore della coda per cui è generato il messaggio. L'identificatore è bfq Il PID può coincidere o meno col PID del processo in esecuzione quando il messaggio è generato. In particolare, coincide se il kernel è in user context quando il messaggio è generato, mentre tipicamente non coincide se è in interrupt context. In quanto alla lettera S oppure A, c'è la S se la code contiene richieste sincrone, e la A se la coda contiene richieste asincrone. Il resto del messaggio è pari pari quello che lo scheduler vuole che venga scritto. OTTENERE PIU' MESSAGGI DI LOG Per avere delle tracce complete è spesso opportuno che usiate bfq-mq e non bfq come scheduler. Infatti bfq-mq è la versione di sviluppo di bfq, che genera un numero enormemente maggiore di messaggi. Poi ovviamente dovete stare attenti che bfq non sia talmente indietro rispetto a bfq-mq (che contiene sempre tutti gli aggiornamenti) che un certo problema esiste con bfq ma non con bfq-mq, oppure cambia quando si passa a bfq-mq e così via. In pratica per usare bfq-mq, dovete prendervi il repository che lo contiene: git clone https://github.com/Algodev-github/bfq-mq.git Poi compilare il kernel nel tree bfq-mq, seguendo i soliti passi. Potete partire dal config che avete usato per il mainline, avendo cura di attivare però lo scheduler BFQ-MQ nel kernel. Col nuovo kernel in esecuzione, rieseguite il test per prendere la traccia usando bfq-mq: sudo ./comm_startup_lat.sh bfq 5 5 rand 1 "lowriter --terminate-after-init" ANALIZZARE LA TRACCIA Il tipico problema che si scopre con questi test di startup è che qualche applicazione non parte velocemente come sperato. Ecco i passi tipici con cui analizzare un problema di questo tipo. 1. Individuare i PID dei processi dell'applicazione dentro la traccia Un trucco per fare questo passo con relativa facilità è a) Fare partire l'applicazione problematica da sola e prendere la traccia b) Cercare il nome dell'applicazione nella traccia per beccare, con altissima probabilità il primo processo dell'applicazione. Per questo passo, può essere più facile effettuare la ricerca in una versione filtrata della traccia (vedi il seguente passo "2. Filtrare la traccia"). Se nella versione filtrata non trovate il nome di un processo per il quale si vede solo il PID nel formato bfq, vuol dire che nella versione filtrata ci sono solo messaggi stampati in contesto interrupt, e non è mai accaduta la coincidenza che il processo con quel PID fosse in esecuzione quando c'è stato uno degli interrupt che hanno generato tali messaggi. Cercate semplicemente quel PID nella traccia non filtrata. c) Annotarsi quali e quanti processi che hanno molto probabilmente o quasi sicuramente a che con l'applicazione, fanno I/O fino alla fine della traccia. d) Una volta capito qual è la sequenza di processi che fanno I/O per quell'applicazione, prendere la traccia per lo scenario in cui si verifica il problema che si vuole risolvere In merito al punto c, ecco alcuni schemi. bash ha un solo processo, che si chiama proprio bash lowriter, per avviarsi ha il seguente schema: lowriter-L oosplash-N Xorg-M javaldx-P soffice.bin-Q Per avviare xterm si ha il seguente schema: xterm-N: il processo xterm fa I/O ininterrottamente per un po', poi si ferma Xorg-M: fa pochissimo I/O e si ferma xterm-N: fa un altro po' di I/O ininterrottamente e si ferma Xorg-M: fa pochissimo I/O e si ferma xterm-N: fa pochissimo I/O e si ferma Xorg-M: fa ininterrottamente I/O per un po' e si ferma xterm-N: il processo xterm fa I/O ininterrottamente per un po' (con una micropausa nel mezzo, sufficiente ad avere un idling timeout), poi si ferma Per trovare tutti i processi coinvolti ci vuole un po' di intuito, ma alla fine sono sempre gli stessi per la stessa applicazione. 2. Filtrare la traccia Un modo per farsi un'idea di quello che succede durante il test, è capire quando e per quanto tempo è in servizio ciascuna coda. Per scoprirlo, si può filtrare la traccia così: egrep "set_in_service|expire" trace | less Ogni coda è in servizio tra una set_in_service ed una expire. La expire inoltre vi da almeno due informazioni utili: vi dice perché è espirata la coda (primo numero), e vi dice il peso con cui è espirata la coda. Dal peso potete capire, ad esempio, se la coda è in weight raising (tipicamente 1200 vuol dire weight raising per interattivi, e 120000 vuol dire weight raising per soft real time). Un filtraggio più completo vi permette invece di capire anche quanto tempo passa tra quando una coda diventa attiva (perché ci entra una richiesta dentro) e quando finalmente va in servizio. Per farlo, potete eseguire: egrep "bfq_add_request non-busy|set_in_service|expire" trace | less Ecco un esempio di verifica di buon funzionamento: data un'applicazione che BFQ dovrebbe privilegiare, controllare che, per tutti i processi dell'applicazione, 1) le code di tali processi siano sempre in weight raising, e lo si vede già col primo filtraggio 2) le code di tali processi inizino ad essere servite immediatamente dopo o molto presto dopo che diventano attive, e lo si vede col secondo filtraggio 3) le code di tali processi siano le uniche in weight raising, oppure, se ci sono altre code in weight raising, lo sono per motivi giusti (ad esempio, sono associate a processi interattivi o che fanno I/O sporadicamente per altri motivi) Una volta che si è capito che qualcosa non va per una data coda, ci sono due possibilità: 1) Si filtra la traccia per avere solo i messaggi relativi a tale coda. Per esempio, se la coda fosse bfq3170, si utilizza l'identificatore della coda come segue egrep bfq3170 trace | less 2) Se il filtraggio precedente non ci fa vedere abbastanza messaggi per capire cosa non sta funzionando, allora ci tocca andare sull'intera traccia. Il motivo per cui potremmo non avere abbastanza messaggi col filtraggio per identificatore di coda, è che certi eventi generano messaggi senza menzionare la coda. Ad esempio "bfq timer expired" non menziona la coda. Nella traccia completa è molto facile perdersi, a causa dell'enorme quantità di messaggi. Una tecnica per trovare i punti interessanti è la seguente a) Sulla traccia filtrata solo per set_in_service ed expire, si cerca l'istante più vicino all'evento anomalo che si vuole analizzare (ad esempio, se il peso va giù inspiegabilmente, si cerca il primo instante in cui si vede il problema sulla traccia filtrata). Per istante, intendo i timestamp nella traccia b) Si filtra la traccia per identificatore della coda interessata, utilizzando il timestamp trovato nel passaggio precedente per collocarsi nel punto più vicino al problema. A questo punto, ipotizzando sempre che neanche questo filtraggio basti a trovare il problema, si utilizza comunque questa traccia filtrata per trovare il prossimo istante, ancora più vicino all'inizio del problema c) Utilizzando l'istante trovato nel passaggio precedente, si salta direttamente a tale istante nella traccia completa, e si incrociano le dita :) ---------------------- TRUCCO PER OTTENERE RAPIDAMENTE LA STRINGA bfq PER UN DATO PROCESSO egrep trace | awk '{print $1}' | tail -n 1 | sed 's/.*-\(.*\)/bfq\1/g' Ad esempio: egrep mplayer trace | awk '{print $1}' | tail -n 1 | sed 's/.*-\(.*\)/bfq\1/g' Con questo trucco, si può passare direttamente al filtraggio "set_in_service|expire" per un dato processo: string=$(egrep trace | awk '{print $1}' | tail -n 1 | sed 's/.*-\(.*\)/bfq\1/g') && echo $string && egrep "set_in_service|expire \(|too much" trace | egrep $string | less --------------------- ALTRE MISURAZIONI UTILI Quantità totale di I/O che un processo fa: seq=$(egrep - trace | egrep " Q |expire \(" | awk '{print $10}' | less) ; for s in $seq; do sum=$(( $sum + $s )); echo $s $sum ; done | less