¿Por qué mis llamadas SOAP v2 WS-I son tan lentas (7-10 segundos por actualización de producto)?

16

Estamos utilizando la API Magento SOAP v2 con WS-I.

El problema es que las llamadas SOAP son extremadamente lentas (¡7-10 segundos por producto!). Llamamos catalogProductUpdate sin imágenes. La tienda en sí funciona bien, solo la llamada SOAP es lenta. Activamos el Caché y desactivamos el Índice para aumentar el rendimiento (eso ayudaba en muchas otras tiendas cuando la importación de SOAP era lenta).

Pongo mensajes de registro en varios archivos para averiguar dónde sale mal. Este es el registro combinado de llamadas a funciones y eventos de despacho:

20.03.2013 14:17:43: Mage_Api_V2_SoapController
20.03.2013 14:17:43: dispatchEvent: controller_action_postdispatch_api_v2_soap_index
20.03.2013 14:17:43: dispatchEvent: controller_action_postdispatch_api
20.03.2013 14:17:43: dispatchEvent: controller_action_postdispatch
20.03.2013 14:17:43: dispatchEvent: controller_front_send_response_before
20.03.2013 14:17:43: dispatchEvent: http_response_send_before
20.03.2013 14:17:43: dispatchEvent: controller_front_send_response_after
20.03.2013 14:17:43: Mage::run
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: core_collection_abstract_load_before
20.03.2013 14:17:51: dispatchEvent: core_collection_abstract_load_after
20.03.2013 14:17:51: dispatchEvent: core_collection_abstract_load_before
20.03.2013 14:17:51: dispatchEvent: core_collection_abstract_load_after
20.03.2013 14:17:51: dispatchEvent: core_collection_abstract_load_before
20.03.2013 14:17:51: dispatchEvent: core_collection_abstract_load_after
20.03.2013 14:17:51: dispatchEvent: controller_front_init_before
20.03.2013 14:17:51: dispatchEvent: controller_front_init_routers
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: model_load_after
20.03.2013 14:17:51: dispatchEvent: core_abstract_load_after
20.03.2013 14:17:51: Mage_Core_Controller_Varien_Front
20.03.2013 14:17:51: Mage_Core_Controller_Varien_Front
20.03.2013 14:17:51: Mage_Core_Controller_Varien_Router_Standard
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: core_locale_set_locale
20.03.2013 14:17:51: dispatchEvent: controller_action_predispatch
20.03.2013 14:17:51: dispatchEvent: controller_action_predispatch_api
20.03.2013 14:17:51: dispatchEvent: controller_action_predispatch_api_v2_soap_index
20.03.2013 14:17:51: Mage_Core_Controller_Varien_Action
20.03.2013 14:17:51: Mage_Api_Model_Server
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: Mage_Api_Model_Server_Handler_Abstract
20.03.2013 14:17:51: Neues Update: 2110000438920 
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: model_load_after
20.03.2013 14:17:51: dispatchEvent: core_abstract_load_after
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: model_load_before
20.03.2013 14:17:51: dispatchEvent: catalog_product_load_before
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: model_load_after
20.03.2013 14:17:51: dispatchEvent: catalog_product_load_after
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: prepareDataForSave Dauer: 0.75447800 1363789071-0.77473800 1363789071=0.02026
20.03.2013 14:17:51: dispatchEvent: catalog_product_validate_before
20.03.2013 14:17:51: dispatchEvent: catalog_product_validate_after
20.03.2013 14:17:51: dispatchEvent: application_clean_cache
20.03.2013 14:17:51: dispatchEvent: model_save_before
20.03.2013 14:17:51: dispatchEvent: catalog_product_save_before
20.03.2013 14:17:51: dispatchEvent: model_load_after
20.03.2013 14:17:51: dispatchEvent: core_abstract_load_after
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: catalog_product_media_save_before
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
20.03.2013 14:17:51: dispatchEvent: application_clean_cache
20.03.2013 14:17:51: dispatchEvent: model_save_after
20.03.2013 14:17:51: dispatchEvent: catalog_product_save_after
20.03.2013 14:17:51: dispatchEvent: model_save_after
20.03.2013 14:17:52: dispatchEvent: cataloginventory_stock_item_save_after
20.03.2013 14:17:52: dispatchEvent: resource_get_tablename
20.03.2013 14:17:52: dispatchEvent: core_collection_abstract_load_before
20.03.2013 14:17:52: dispatchEvent: core_collection_abstract_load_after
20.03.2013 14:17:52: dispatchEvent: resource_get_tablename
20.03.2013 14:17:52: dispatchEvent: model_load_before
20.03.2013 14:17:52: dispatchEvent: core_abstract_load_before
20.03.2013 14:17:52: dispatchEvent: resource_get_tablename
20.03.2013 14:17:52: dispatchEvent: model_load_after
20.03.2013 14:17:52: dispatchEvent: core_abstract_load_after
20.03.2013 14:17:52: dispatchEvent: start_process_event_cataloginventory_stock_item_save
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: model_save_before
20.03.2013 14:17:52: dispatchEvent: core_abstract_save_before
20.03.2013 14:17:52: dispatchEvent: resource_get_tablename
20.03.2013 14:17:52: dispatchEvent: resource_get_tablename
20.03.2013 14:17:52: dispatchEvent: model_save_after
20.03.2013 14:17:52: dispatchEvent: core_abstract_save_after
20.03.2013 14:17:52: dispatchEvent: end_process_event_cataloginventory_stock_item_save
20.03.2013 14:17:52: dispatchEvent: start_index_events_catalog_product_mass_action
20.03.2013 14:17:52: dispatchEvent: end_index_events_catalog_product_mass_action
20.03.2013 14:17:52: dispatchEvent: resource_get_tablename
20.03.2013 14:17:52: dispatchEvent: core_collection_abstract_load_before
20.03.2013 14:17:52: dispatchEvent: core_collection_abstract_load_after
20.03.2013 14:17:52: dispatchEvent: start_process_event_catalog_product_save
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: index_process_change_status
20.03.2013 14:17:52: dispatchEvent: model_save_before
20.03.2013 14:17:52: dispatchEvent: core_abstract_save_before
20.03.2013 14:17:52: dispatchEvent: model_save_after
20.03.2013 14:17:52: dispatchEvent: core_abstract_save_after
20.03.2013 14:17:52: dispatchEvent: end_process_event_catalog_product_save
20.03.2013 14:17:52: dispatchEvent: model_save_commit_after
20.03.2013 14:17:52: dispatchEvent: core_abstract_save_commit_after
20.03.2013 14:17:52: dispatchEvent: model_save_commit_after
20.03.2013 14:17:52: dispatchEvent: cataloginventory_stock_item_save_commit_after
20.03.2013 14:17:52: dispatchEvent: model_save_commit_after
20.03.2013 14:17:52: dispatchEvent: core_abstract_save_commit_after
20.03.2013 14:17:52: dispatchEvent: model_save_commit_after
20.03.2013 14:17:52: dispatchEvent: catalog_product_save_commit_after
20.03.2013 14:17:52: update Dauer: 0.02026

La parte interesante es:

20.03.2013 14:17:43: Mage::run
20.03.2013 14:17:51: dispatchEvent: resource_get_tablename
...
20.03.2013 14:17:51: Mage_Core_Controller_Varien_Front

Siempre hay entre 7 Mage::runy 10 segundos entre el siguiente evento / llamada de función Mage_Core_Controller_Varien_Front. ¿Alguna idea de qué puede salir mal aquí?

Tenemos el mismo problema con otra tienda (en otro servidor, cliente diferente) con la misma configuración, donde una actualización tarda 15 segundos.

ce-1.7.0.2 api soap event-observer Anna Völkl
fuente
¿Has intentado depurar los tiempos de carga de configuración? Esa parece ser la razón más probable de un retraso
Petar Dzhambazov
¿Podría explicar qué quiere decir con "depurar los tiempos de carga de configuración"?
Anna Völkl
Supongo que Petar está hablando del tiempo que lleva compilar el árbol del nodo de configuración.
Matthias Zeis
Sí, me refiero al tiempo que lleva arrancar Magento antes de que se procese la solicitud real. Además, ¿por qué Mage :: se ejecuta en el registro? No veo esa llamada en api.php
Petar Dzhambazov
Tengo un consejo de rendimiento rápido a continuación, pero si usted / sus desarrolladores están interesados ​​en profundizar en la API, esta serie de API cubre el envío en detalle y puede ayudar a rastrear problemas de rendimiento: alanstorm.com/category/magento# magento_api
Alan Storm

Respuestas:

17

¿Tiene configuración de PHP para almacenar en caché los archivos WSDL? La SoapServerimplementación de PHP (utilizada por Magento) necesita examinar el archivo WSDL al menos una vez durante una llamada SOAP, a veces más de una vez. Esto puede crear un crecimiento exponencial en los tiempos de solicitud. Verifique la configuración en

System -> Configuration -> Magento Core Api -> Enable WSDL Cache

y asegúrese de que esté configurado en yes. Esto le indicará a PHP que guarde en caché el archivo WSDL, lo que debería mejorar su rendimiento.

Alan Storm
fuente
3
También estoy trabajando en el mismo proyecto, así que sé que sí, ya hemos habilitado el caché WSDL. Hizo una diferencia de aproximadamente 1 segundo, pero eso todavía no es demasiado teniendo en cuenta que toda la llamada de actualización tarda 8-10 segundos ...
Daniel Lang
2
Derecha, Habilitar caché WSDL en el backend está configurado en "Sí".
Anna Völkl
Aunque esta no era la solución real, seleccioné esta respuesta para cerrar la pregunta.
Anna Völkl
Esto me llevó de 30 segundos a hacer una actualización a 4 segundos. Ganar.
dgig