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.
