====== GUIDA DI PROFILAZIONE SU DJANGO ====== premessa: questa guida prevedede che dei file di profilazione siano stati preventivamente creati e che questi risultati vengano analizzati. Una buona libreria python per la profilazione è hotshot. Noi abbiamo scelto di profilare partendo dalle viste django, in quanto entry-point per l'utente finale, dato che lo scopo è di migliorare l'esperienza utente. Il workflow riportato è comunque applicabile a qualsiasi profilazione. * for i in `ls -1 /path/to/txt/files/*.txt` ; do printf "%s (Total Time) Profiling file: %s\n" `head -1 $i | awk '{print $8}'` `basename $i` >> profiling_stats.txt; done * sort -rn profiling_stats.txt -o profiling_stats.txt (mette in ordine decrescente i tempi) ===== WORKFLOW GENERALE ===== Qui si riporta il workflow da seguire una volta localizzate le parti del software che richidono un analisi. - **Guardare:** in questa fase si sceglie la profilazione che interessa (di solito quella che riporta un tempo maggiore) e si identifica la funzione (vista, funzione, ecc.) da cui è stata prodotta. - **Riprodurre:** in questa fase si riproduce in locale lo stato dell'installazione, compresi i dati, in modo da verificare la corrispondenza tra il comportamento monitorato dalla profilazione e quello effettivo. - **Misurare:** Una volta riprodotto il problema provare un'ottimizzazione alla volta e per ognuna registrare l'eventuale aumento/decremnto delle performance. **CONSIGLI:** Per l'ottimizzazione partire dagli indici del database ed eventualmente in seguito controllare l'eleganza del codice :) ===== NELLO SPECIFICO ===== Nel caso pratio del profiling di GasistaFelice si è scelto di profilare le viste, rispettivamente nelle installazioni sui server: * `ordini.desmacerata.it`, in `/var/www/gf_desmc; * `gasistafelice.befair.it`, in Una volta ottenuti i file di profilazione .prof creati dal software, è possibile produrre dei file file di testo da questi eseguendo: * for i in `ls /path/to/profs/*.prof` ; python /path/to/gasistafelice/manage.py profiled_code $i 20 > `basename $i .prof`.txt; done ==== Guardare ==== Si è scelta la vista `insolutes_orders`, profilata: * in data 2014/05/15 per un tempo totale di 192.639 sec nel server ordini.desmacerata.it * in data per un tempo totale di sec nel server gasistafelice.befair.it La vista puo essere relativa a una risorsa, il GAS. ==== Riprodurre ==== === ordini.desmacerata.it === In locale, è stato scelto di riprodurre la chiamata per il GAS gassosa: * //GAS// http://127.0.0.1:8000/gasistafelice/rest/gas/8/insolutes_orders/?render_as=list, tempo impiegato: in media ~22 sec === gasistafelice.befair.it === In locale, è stato scelto di riprodurre la chiamata per il GAS gassosa: * ,tempo impiegato: in media sec ==== Misurare ==== Un modo per controllare l'effettivo utilizo degli indici è lanciare dalla dbshell di django la query di **Utilizzo degli indici** alla pagina [[ops:postgresql]] I test in questa sezione sono stati eseguiti svuotando la cache di postgres prima di ogni test. In un sistema linux: * service postgresql stop; * echo 3 > /proc/sys/vm/drop_caches; * service postgresql start; - Ottimizzazione:si prende in cosiderazione la possibilità di inserire un indice multicolonna (content_type, state__name) alla tabella workflows_stateobjectrelation. 1° prova: senza indice multicolonna: * EXPLAIN ANALYZE SELECT "workflows_stateobjectrelation"."id", "workflows_stateobjectrelation"."content_type_id", "workflows_stateobjectrelation"."content_id", "workflows_stateobjectrelation"."state_id" FROM "workflows_stateobjectrelation" INNER JOIN "workflows_state" ON ("workflows_stateobjectrelation"."state_id" = "workflows_state"."id") WHERE ("workflows_state"."name" = 'Closed' AND "workflows_stateobjectrelation"."content_type_id" = 68 ); %% QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------- Nested Loop (cost=52.76..238.26 rows=495 width=16) (actual time=31.081..47.576 rows=195 loops=1) -> Seq Scan on workflows_state (cost=0.00..1.27 rows=1 width=4) (actual time=8.104..8.121 rows=2 loops=1) Filter: ((name)::text = 'Closed'::text) -> Bitmap Heap Scan on workflows_stateobjectrelation (cost=52.76..203.37 rows=2689 width=16) (actual time=11.530..19.676 rows=98 loops=2) Recheck Cond: (state_id = workflows_state.id) Filter: (content_type_id = 68) -> Bitmap Index Scan on workflows_stateobjectrelation_state_id (cost=0.00..52.42 rows=2689 width=0) (actual time=4.860..4.860 rows=98 loops=2) Index Cond: (state_id = workflows_state.id) Total runtime: 47.675 ms (9 righe) (END) %% 2° prova: dopo l'inserimento dell'indice multicolonna CREATE INDEX "workflows_stateobjectrelation_content_type_id_state_id" ON "workflows_stateobjectrelation" ("content_type_id","state_id"); * EXPLAIN ANALYZE SELECT "workflows_stateobjectrelation"."id", "workflows_stateobjectrelation"."content_type_id", "workflows_stateobjectrelation"."content_id", "workflows_stateobjectrelation"."state_id" FROM "workflows_stateobjectrelation" INNER JOIN "workflows_state" ON ("workflows_stateobjectrelation"."state_id" = "workflows_state"."id") WHERE ("workflows_state"."name" = 'Closed' AND "workflows_stateobjectrelation"."content_type_id" = 68 ); %% QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Nested Loop (cost=30.21..182.54 rows=495 width=16) (actual time=31.059..47.288 rows=195 loops=1) -> Seq Scan on workflows_state (cost=0.00..1.27 rows=1 width=4) (actual time=8.068..8.100 rows=2 loops=1) Filter: ((name)::text = 'Closed'::text) -> Bitmap Heap Scan on workflows_stateobjectrelation (cost=30.21..164.24 rows=1362 width=16) (actual time=11.548..19.552 rows=98 loops=2) Recheck Cond: ((content_type_id = 68) AND (state_id = workflows_state.id)) -> Bitmap Index Scan on workflows_stateobjectrelation_content_type_id_state_id (cost=0.00..29.87 rows=1362 width=0) (actual time=3.330..3.330 rows=98 loops=2) Index Cond: ((content_type_id = 68) AND (state_id = workflows_state.id)) Total runtime: 47.382 ms (8 righe) (END) %%