Com vam millorar 20 vegades el temps de processament de 500GB diaris i estalviar 3800€ anuals

Crònica d’una tarda de profiling i optimitzacions amb Python

Published in

Calidae Blog

7 min readMay 29, 2017

A Calidae tenim un projecte que és bastant “cosa pepina” on ingerim i transformem uns ~5GB de dades cada 15 minuts i els preparem per ser analitzats per un Business intelligence. Algun dia escriuré un post fent una explicació general de com hem resolt el projecte, què ens hem trobat pel camí i què hem après. Però avui em centraré en una part en concret.

El problema

El sistema origen extreu centenars de mètriques, i al nostre client només l’interessen una part d’aquestes. Per això, una part de la nostra ETL és un processador de fórmules, on permetem que el client defineixi el subconjunt de les dades que necessita i, a més, que aprofiti per fer algun pre-càlcul.

Llegiu el codi amb calma. La intenció és poder crear objectes Formula amb expressions de l’estil f1 = Formula('X=A+B.C'). La classe, en resum:

Guarda el nom de la fórmula.
Prepara i precompila la fórmula. Això implica netejar caràcters especials (com els punts, que Python interpretaria com a objecte), trobar les variables de la fórmula (llegint gramàtica de Python) i precompilar l’expressió amb el parser de Python.
Després, espera crides a calc. Rep un diccionari representant una línia de mètriques d’origen, li treu els . de nou, i omple qualsevol variable que estigui a la fórmula però no a la línia amb None (per evitar errors de not defined). Després avalua la Fórmula contra la línia.

Amb això, creem les 10 o 15 fórmules que el client necessita i avaluem cada línia contra totes elles per generar una línia filtrada.

A més, aquest codi es troba dins una funció AWS Lambda, i el que fem és aixecar-ne vàries que ens permeten filtrar un munt de fitxers a l’hora.

Però les coses fallen

Total, que l’altre dia moltes d’aquestes Lambdas fallaven perquè arribaven al límit de temps que havíem establert (3 minuts).

Procediment habitual: mirar logs per trobar un cas reproduïble.

Trobo un cas on una Lambda que processava un únic fitxer d’origen de ~300MB estava fallant. Descarrego el fitxer, i comença la festa.

Preparant el profiler

Necessito saber qui és el responsable que fa trigui tant, perquè tot plegat és estrany i em fa pujar la mosca al nas.

Busco ladocumentació del profiler de Python, tot i que en realitat un ús bàsic és bastant senzill:

import cProfile
from awesome_module import filter_metric_filedef main():
  file = ... # llegir el fitxer
  formulas = # crear els objectes Formula    
  cProfile.runctx('filter_metric_file(file, formulas')if __name__ == '__main__':
  main()

Analitzant els resultats del profiler

Un cop ho executo, em surt una cosa com aquesta (resumida):

309588524 function calls (309588515 primitive calls) in 134.137 secondsOrdered by: standard namencalls  tottime filename:lineno(function)
[...]  
     2448    0.015 decoder.py:361(decode)
     2448    5.282 decoder.py:372(raw_decode)
        1    0.000 encoder.py:101(__init__)
     2448    0.003 encoder.py:186(encode)
     2448    0.021 encoder.py:212(iterencode)
    56304    0.017 encoder.py:33(encode_basestring)
     2461    0.003 formula_filter.py:103(<genexpr>)
       21    0.000 formula_filter.py:15(__init__)
       21    0.000 formula_filter.py:23(_set_cleaned_name)
154224021   26.681 formula_filter.py:26(_clean_problematic...)
       21    0.000 formula_filter.py:31(_set_operation)
       21    0.000 formula_filter.py:34(_set_vars)
       21    0.000 formula_filter.py:36(<setcomp>)
    51408    0.019 formula_filter.py:40(name)
    51408    0.067 formula_filter.py:44(calc)
    51408    0.093 formula_filter.py:52(_get_prepared_line)
    51408    0.082 formula_filter.py:57(_get_line_without_prob...)
    51408   42.950 formula_filter.py:59(<dictcomp>)
    51408    0.069 formula_filter.py:63(_set_line_defaults)
   237456    0.065 formula_filter.py:64(<lambda>)
        1    0.315 formula_filter.py:67(filter_jsonlines_file)
        1    0.000 formula_filter.py:81(_alert_skipped_lines)
     2448    5.146 formula_filter.py:90(get_filtered_line)
     2448    0.009 formula_filter.py:91(<dictcomp>)
[...]
    51408    0.098 {eval}
[...]
154224000   52.042 {method 'replace' of 'unicode' objects}
        1    0.000 {method 'rfind' of 'str' objects}
   237456    0.114 {method 'setdefault' of 'dict' objects}
[...]

Al meu ordinador tarda uns 134 segons, i té més del doble de capacitat de processament que una AWS Lambda. Així que sí, el problema és reproduïble.

Ara, us deixo uns segons perquè intenteu trobar vosaltres mateixos on està focalitzat la majoria de temps de processament.

Exacte! 52 segons per un replace, 42 per una dict comprehension, 26 per la funció _clean_problematic_characters i 5 a raw_decode.

Anem per ordre. Els 5 segons del raw_decode els descartem, ja que són la part de llegir un fitxer json lines de 300 MB. Fins aquí ens agrada.

Ara, la resta de problemes… si ho mirem amb calma podrem veure que tot acaba venint de…

def _get_line_without_problematic_characters(self, line):
  return {
    self._clean_problematic_characters(name): value
    for name, value in line.iteritems()
}

Premi! La dict comprehension, la funció _clean_problematic_characters i el replace (que està escrit dins d’aquesta funció). Tot juntet.

Què està passant? Identificant el culpable

El primer que intento és buscar altres formes de fer el mateix. No cal entrar en detall, però vaig intentar fer un map amb una funció lambda de Python. Va empitjorar.

Així que vaig fer el que havia d’haver fet al principi, que és indagar més en el problema abans de buscar solucions disparant a cegues.

Què vaig veure?

D’entrada, en el processament d’aquest fitxer de ~300MB es fan moltíssimes crides a aquestes funcions (més de 150 milions), mentre que l’eval, que es fa un cop per línia/fórmula, “només” es fa uns 50.000 cops i triga la ridícula suma de 0,09 segons en total.

Intento obrir el fitxer, a veure si veig alguna cosa clara.
I sí. “Només” té unes 2000 línies. És a dir, uns ~150KB per línia: és una animalada. Com dèiem al principi, cada línia origen té centenars de mètriques.

I aquesta dict comprehension recorre toootes aquestes mètriques netejant-les (treure tots els ., recordeu?).

Imagineu la formula que us heu posat d’exemple abans.

f1 = Formula('X=A+B.C').

Imagineu que, a l’origen, A i B.C són part de un conjunt de línies amb 300 mètriques. Estem netejant 298 mètriques a cada línia cop de forma inútil.

Buscant la solució

D’acord, en teoria és fàcil. En comptes de netejar tota la línia per poder fer l’eval, vull que l’eval sigui el que transforma les dades i així només apliqui la neteja quan la necessiti.

Ara, l’eval és una funció interna de Python i no es pot heredar. I si vull avaluar codi Python de forma extremadament ràpida l’he de fer servir.

El que puc fer és jugar és amb els seus paràmetres:

eval(expression[, globals[, locals]])

Què pot rebre un eval com a paràmetre? Un string amb l’expressió, un diccionari de globals i un diccionari de locals.

Aquí és on entra en joc la Magia de Python™ i el seu duck typing. No puc canviar l’eval, però puc canviar el diccionari que li passo. No puc heredar dict perquè també és built-in, però puc passar una cosa que s’assembi molt a un diccionari. Si veig un ocell que camina com un ànec, neda com un ànec i claca com un ànec, jo en dic un ànec.

Així doncs, començo a documentar-me. Veig que Python té classes abstractes a heredar quan vols implementar un mapping, que respecta perfectament el contracte d’un diccionari. L’únic que he de fer és que l’amic eval netegi la clau si veu que és necessari al demanar-la.

Passada una estona de provar-ho, intentar passar tests, arreglar-ho, intentar passar tests… etc, em queda alguna semblant a això:

Com veieu, la funció calcés molt similar a abans. Només que ara eliminem completament el _get_prepared_line , i per tant no fem la neteja global de la línia. En canvi, prepara la línia creant un objecte _FormulaLocalsDict.

Quan l’eval demani alguna cosa del diccionari de locals, comprovem si la tenim detectada com una de les nostres variables. Si és així, desfem la neteja del . que havíem fet i ho busquem a la línia. A més, retorna None si la clau no està a la línia.

Si no, seguim el procediment habitual d’un diccionari.

Acabem d’eliminar d’un sol tret dues iteracions que es feien sobre cada línia a filtrar.

I el resultat?

Si tornem a executar el codi amb el profiler, sorpresa!

1833350 function calls (1833341 primitive calls) in 12.113 secondsOrdered by: standard namencalls  tottime  filename:lineno(function)
[...]
       21    0.000  formula_filter.py:22(__init__)
       21    0.000  formula_filter.py:30(_set_cleaned_name)
       21    0.000  formula_filter.py:33(_remove_problematic_...)
       21    0.000  formula_filter.py:36(<lambda>)
   237456    0.071  formula_filter.py:40(_add_problematic_...)
   237456    0.066  formula_filter.py:43(<lambda>)
       21    0.000  formula_filter.py:47(_set_operation)
       21    0.000  formula_filter.py:50(_set_vars)
       21    0.000  formula_filter.py:52(<setcomp>)
    51408    0.013  formula_filter.py:56(name)
    51408    0.067  formula_filter.py:60(calc)
    51408    3.782  formula_filter.py:71(__init__)
   237456    0.139  formula_filter.py:76(__getitem__)
        1    0.267  formula_filter.py:90(filter_jsonlines_file)
[...]
     4896    0.006  {method 'match' of '_sre.SRE_Pattern' objects}
      388    0.000  {method 'popleft' of 'collections.deque'...
   237478    0.079  {method 'replace' of 'str' objects}
        1    0.000  {method 'rfind' of 'str' objects}
       22    0.000  {method 'split' of 'str' objects}
        1    0.000  {method 'startswith' of 'str' objects}
    56304    0.028  {method 'sub' of '_sre.SRE_Pattern' objects}
        1    0.000  {method 'translate' of 'str' objects}
     2448    0.002  {method 'update' of 'dict' objects}
[...]

12 segons. És uns ~11 cops més ràpid.

I espera.

A formula_filter.py:71 (__init__) s’hi està quasi 4 segons.

Per què?

def __init__(self, original_dict, vars_):
  self._storage = dict(original_dict)
  [...]

Doncs molt probablement perquè estem copiant el diccionari origen. I en realitat no cal, ja que només hi accedirem per llegir, així que en comptes de copiar-lo guardem la seva referència:

def __init__(self, original_dict, vars_):
  self._storage = original_dict
  [...]

Sembla un canvi mínim, una ximpleria.

Però ara tarda 6,77 segons, quasi la meitat que abans de fer aquest últim canvi.

Total: Hem aconseguit una millora de velocitat de quasi 20 cops respecte a l’original de 134 segons.

Conclusió

A vegades donem poca importància a com fem les coses quan desenvolupem mentre funcioni. Es pot implementar una cosa de mil maneres diferents. Però no tot s’hi val.

Sempre s’han de seguir en la mesura del possible les bones pràctiques per mantenir un codi net i escalable.
A vegades, tot i seguir aquestes practiques hi ha altres factors a tenir en compte. En aquest cas, el rendiment. I aquí és on conèixer el llenguatge de programació amb el que treballes, les eines que tens a l’abast i com documentar-te és molt important.
I quan treballem al núvol amb Software as a Service, el rendiment és important encara que a priori no ho sembli. En el cas de AWS Lambda, es paga per execució i segons consumits. Amb aquesta millora, tenint el compte l’alt nivell de cops que s’executa en paral·lel, el nostre client passarà a pagar uns 200 euros l’any per a aquesta funcionalitat en comptes de uns 4000 si no haguéssim fet la millora.

El pròxim dia que tingueu problemes de rendiment, feu servir les eines de profiling que ofereixi el vostre llenguatge/framework. Disparar a cegues és car en temps i en coneixement, ja que normalment acabaràs solucionant el problema sense entendre el perquè.