Por que minhas chamadas SOAP v2 WS-I são tão lentas (7 a 10 segundos por atualização do produto)?

16

Estamos usando a API Magento SOAP v2 com WS-I.

O problema é que as chamadas SOAP são extremamente lentas (7 a 10 segundos por produto!). Estamos chamando catalogProductUpdate sem imagens. A loja em si funciona bem, apenas a chamada SOAP é lenta. Ativamos o cache e desativamos o índice para melhorar o desempenho (que ajudava em muitas outras lojas quando a importação do SOAP era lenta).

Coloquei mensagens de log em vários arquivos para descobrir onde isso dá errado. Este é o log de combinação de chamadas de função e 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

A parte interessante é:

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

Há sempre 7 a 10 segundos entre Mage::rune o próximo evento / chamada de função noMage_Core_Controller_Varien_Front . Alguma idéia do que pode dar errado aqui?

Temos o mesmo problema com outra loja (em outro servidor, cliente diferente) com as mesmas configurações, em que uma atualização leva 15 segundos.

Anna Völkl
fonte
Você tentou depurar os tempos de carregamento da configuração? Isso parece mais provável razão para o atraso
Petar Dzhambazov
Você poderia explicar o que você quer dizer com "tempos de carregamento da configuração de depuração"?
Anna Völkl 20/03/2013
Eu acho que Petar está falando sobre o tempo que leva para compilar a árvore do nó de configuração.
Matthias Zeis
Sim, quero dizer, o tempo necessário para inicializar o Magento antes do processamento da solicitação real. Além disso, por que o Mage :: run no log? Eu não vejo como chamada em api.php
Petar Dzhambazov
Tenho uma dica rápida de desempenho abaixo, mas se você / seus desenvolvedores estiverem interessados ​​em se aprofundar na API, esta série de API abrange o envio em detalhes e pode ajudar a rastrear problemas de desempenho: alanstorm.com/category/magento# magento_api
Alan Storm

Respostas:

17

Você tem a configuração do PHP para armazenar em cache os arquivos WSDL? A SoapServerimplementação do PHP (usada pelo Magento) precisa examinar o arquivo WSDL pelo menos uma vez durante uma chamada SOAP, às vezes mais de uma vez. Isso pode criar um crescimento exponencial nos tempos de solicitação. Verifique a configuração em

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

e verifique se está definido como sim. Isso instruirá o PHP a armazenar em cache o arquivo WSDL, o que deve melhorar seu desempenho.

Alan Storm
fonte
3
Também estou trabalhando no mesmo projeto, então sei que sim, já ativamos o cache WSDL. Ele fez cerca de 1 segundo diferença, mas isso não é stil em muito, considerando que toda a chamada atualização leva 8-10 segundos ...
Daniel Lang
2
Certo, a opção Ativar cache WSDL no back-end está definida como "Sim".
Anna Völkl 21/03/2013
Mesmo que essa não fosse a solução real, seleciono esta resposta para fechar a pergunta.
Anna Völkl
Isso me levou de 30 segundos para fazer uma atualização para 4 segundos. Ganhar.
Dgig