Análisis de rendimiento de Tryton

Análisis de rendimientode Tryton

En esta entrada vamos a enseñar como se realiza un análisis de rendimiento de una acción de Tryton. Para ello vamos a utilitzar la librería cProfile que nos facilita el propio lenguaje de programación Python.

Lo primero que haremos será declarar la siguiente función al principio del fichero trytond/trytond/protocols/dispatcher.py

import cProfile
def do_cprofile(func):
    def profiled_func(*args, **kwargs):
        profile = cProfile.Profile()
        try:
            profile.enable()
            result = func(*args, **kwargs)
            profile.disable()
            return result
        finally:
             for arg in args:
                print arg
            profile.print_stats()
    return profiled_func

Y justo encima de la función dispatch, añadimos el decorador do_cprofile de esta forma

@do_cprofile
def dispatch(host, port, protocol, database_name, user, session, object_type,
        object_name, method, *args, **kwargs):
    [...]

A continuación arrancamos el servidor Tryton tunelizando la salida estandard a un fichero para poder leerlo posteriormente:

$ ./bin/trytond -c trytond/etc/trytond.conf > /tmp/logs.txt

Una vez arrancado el servidor nos conectamos con el cliente de escritorio y ejecutamos la acción que queremos analizar y finalmente abrimos el fichero donde hemos volcado la salida del análisis para estudiarla.

$ pluma /tmp/logs.txt

 En dicho fichero podremos ver algo como esto:

[1]
::1
56894
JSON-RPC
db_name
1
c428287398bd415da1a8fff1422a69e1
model
product.template
read
[25278]
[u'customer_taxes', u'code', u'list_price', u'width_digits', u'weight', u'taxes_category', u'thumb_filename', u'height', u'review_location', u'magento_attribute_configurables', u'default_uom', u'template_attribute_set', u'direct_stock_supply', u'height_digits', u'category', u'manufacturer_name', u'thumb', u'review_types', u'purchasable', u'review', u'salable', u'forecast_quantity', u'esale_active', u'width', u'height_uom', u'length_uom', u'base_code', u'products', u'magento_product_type', u'technical_description', u'type', u'cost_price', u'weight_digits', u'product_suppliers', u'length_digits', u'review_description', u'sale_uom', u'esale_available', u'unique_variant', u'purchase_uom', u'width_uom', u'supplier_taxes', u'active', u'medicament', u'consumable', u'list_price_supplier', u'default_uom_category', u'manufacturer', u'delivery_time', u'weight_uom', u'account_expense', u'name', u'account_category', u'esale_slug', u'attachments', u'length', u'attribute_set', u'template_attributes', u'shops', u'account_revenue', u'cost_price_method', u'quantity', u'default_uom.rec_name', u'template_attribute_set.rec_name', u'category.rec_name', u'height_uom.rec_name', u'length_uom.rec_name', u'sale_uom.rec_name', u'purchase_uom.rec_name', u'width_uom.rec_name', u'default_uom_category.rec_name', u'manufacturer.rec_name', u'weight_uom.rec_name', u'account_expense.rec_name', u'attribute_set.rec_name', u'account_revenue.rec_name', u'rec_name', u'_timestamp']
{keys: values}
         8055053 function calls (6667984 primitive calls) in 10.650 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
[...]
        2    0.076    0.038   10.435    5.217 move.py:1120(compute_quantities)
[...]
        2    0.000    0.000   10.457    5.228 move.py:50(_get_quantity)
[...]
        2    0.012    0.006   10.456    5.228 product.py:123(products_by_location)
        2    0.000    0.000   10.463    5.231 product.py:14(get_quantity)
        2    0.000    0.000   10.486    5.243 product.py:14(sum_product)
[...]
        2    0.000    0.000   10.462    5.231 product.py:29(get_quantity)
        2    0.000    0.000   10.474    5.237 product.py:34(sum_product)
[...]
        2    0.000    0.000   10.462    5.231 product.py:54(get_quantity)
[...]
        2    0.000    0.000   10.457    5.228 product.py:94(get_quantity)
[...]
En este caso vemos que el método read del modelo product.template se ejecuta 2 veces y cada una de las veces ha tardado unos 5 segundos.