Long Time to First Byte - Over 30 Seconds

[jerome_leung]

Like the subject says, it's taking the better part of a minute to load any page the website. Profiler shows "mage" having a 34s execution time

Here's some of the profiler output:

[Mageworx Team]

Hey @jerome_leung,

Could you please provide the full data from profiler? Do you use 3rd party extensions btw?

[jerome_leung]

 @Mageworx Team will this work?

Code Profiler	Time	Cnt	Emalloc	RealMem
mage	36.5241	1	0	0
CORE::create_object_of::Mage_Core_Model_Cache	0.0006	1	89,352	0
mage::app::init::config::load_cache	0.0044	1	552	0
mage::app::init::stores	0.825	1	226,416	262,144
CORE::create_object_of::Mage_Core_Model_Resource_Website_Collection	0.821	1	148,816	262,144
DISPATCH EVENT:resource_get_tablename	0.0019	167	10,272	0
DISPATCH EVENT:core_collection_abstract_load_before	0.0009	85	4,488	0
DISPATCH EVENT:core_collection_abstract_load_after	0.0012	85	4,488	0
init_config_section:stores_usa	0.0015	1	880	0
mage::app::init_front_controller	0.0025	1	170,512	262,144
DISPATCH EVENT:controller_front_init_before	0.0004	1	70,056	0
OBSERVER: mana_core	0.0096	75	118,504	0
mage::app::init_front_controller::collect_routers	0.0016	1	79,752	262,144
DISPATCH EVENT:controller_front_init_routers	0.0003	1	13,344	0
CORE::create_object_of::Mage_Core_Model_Url_Rewrite	0.0003	10	6,008	0
mage::dispatch::db_url_rewrite	0.1575	1	10,008	0
DISPATCH EVENT:model_load_after	0.0009	57	3,208	0
DISPATCH EVENT:core_abstract_load_after	0.0003	32	2,008	0
mage::dispatch::routers_match	35.5298	1	0	0
mage::dispatch::controller::action:redispatch	0.3691	1	592,312	1,048,576
CORE::create_object_of::Mage_Core_Model_Session	0.002	2	42,856	0
Mage_Core_Model_Session_Abstract_Varien::start/start	0.0009	1	19,856	0
mage::dispatch::controller::action:redispatch::load_area::frontend::design	0.158	1	48,408	0
CORE::create_object_of::Mage_Core_Model_Design_Package	0.0004	1	28,112	0
mage::dispatch::controller::action:redispatch::load_area::frontend::translate	0.2043	1	52,888	1,048,576
Mage_Core_Model_Design_Package::getFilename	0.0183	146	152,776	0
DISPATCH EVENT:controller_action_predispatch	0.0041	1	402,568	0
OBSERVER: xmlconnect	0.0002	1	71,336	0
CORE::create_object_of::Mage_XmlConnect_Model_Observer	0.0001	1	64,040	0
OBSERVER: mana_db	0.0007	1	107,688	0
CORE::create_object_of::Mage_Index_Model_Indexer	0.0005	1	88,448	0
CORE::create_object_of::Mage_Index_Model_Resource_Process_Collection	0.0004	1	34,472	0
OBSERVER: log	0.0007	1	10,568	0
OBSERVER: pagecache	0.0003	1	18,248	0
OBSERVER: persistent	0.0007	3	148,656	0
mage::dispatch::controller::action::cms_index_index	35.1604	1	0	0
DISPATCH EVENT:model_load_before	0.0005	47	2,664	0
mage::dispatch::controller::action::cms_index_index::layout_load	1.218	1	115,744	0
layout/package_update: default	0.1112	1	65,280	0
layout/db_update: default	34.7317	1	0	0
layout/db_update: cms_page	34.5735	1	0	0
layout/db_update: STORE_usa	34.4157	1	0	0
layout/db_update: THEME_frontend_default_v-tac	34.2579	1	0	0
layout/db_update: cms_index_index	34.0998	1	0	0
layout/db_update: page_one_column	33.942	1	0	0
layout/db_update: customer_logged_out	33.7838	1	0	0
DISPATCH EVENT:controller_action_layout_generate_blocks_before	0.0022	1	29,872	0
Mana_Core_Helper_Js:rocessFiles	0.0018	1	9,576	0
mage::dispatch::controller::action::cms_index_index::layout_generate_blocks	0.0352	1	2,219,240	2,097,152
BLOCK: formkey	0.0005	1	16,120	0
DISPATCH EVENT:core_block_abstract_prepare_layout_before	0.0011	109	5,640	0
DISPATCH EVENT:core_block_abstract_prepare_layout_after	0.0084	109	12,544	262,144
OBSERVER: currencypricing_add_product_tabs	0.0024	109	18,856	0
DISPATCH EVENT:core_layout_block_create_after	0.0009	109	5,640	0
BLOCK ACTION: head -> addJs	0.0002	10	15,552	0
BLOCK ACTION: head -> addItem	0.0003	17	24,760	0
BLOCK: js_cookies	0.0003	1	67,232	0
BLOCK ACTION: head -> addCss	0.0003	17	26,080	0
BLOCK: global_notices	0.0003	1	65,992	0
BLOCK: catalog.topnav	0.0005	1	112,256	262,144
BLOCK: top.container	0.0003	1	57,280	0
BLOCK: welcome	0.0003	1	64,344	0
BLOCK: global_cookie_notice	0.0003	1	65,304	0
BLOCK ACTION: top.links -> addLink	0.0034	4	38,536	262,144
CORE::create_object_of::Mage_Core_Model_Url	0.0036	128	76,168	0
BLOCK: catalog.compare.sidebar	0.0004	1	158,744	0
BLOCK ACTION: footer_links -> addLink	0.0024	4	13,848	0
BLOCK: catalog_product_price_template	0.0003	1	56,648	0
BLOCK: return_link	0.0008	1	72,552	0
BLOCK ACTION: checkout_cart_link -> addCartLink	0.0016	1	41,424	0
BLOCK: paypal.partner.top_cart.shortcut	0.0004	1	155,112	262,144
BLOCK: wishlist_sidebar	0.0004	1	176,136	0
BLOCK: paypaluk.partner.top_cart.shortcut	0.0003	1	66,936	262,144
BLOCK: head_rss	0.0005	1	69,096	0
BLOCK: addthis_smartlayers	0.0003	1	68,720	0
BLOCK: right.clnews.menu	0.0007	1	142,672	262,144
BLOCK: right.clnews.latest	0.0005	1	74,200	0
BLOCK ACTION: top.clnews.link -> getTopLink	0.0007	1	26,192	0
BLOCK: ipredirect	0.003	1	94,320	262,144
BLOCK: m_core_singletons	0.0003	1	57,800	0
BLOCK: paypal.partner.right.logo	0.0003	1	65,032	0
BLOCK: bml.center.logo	0.0003	1	66,360	0
BLOCK: sale.reorder.sidebar	0.0003	1	67,056	0
DISPATCH EVENT:controller_action_layout_generate_blocks_after	0.0004	1	16,984	0
mage::dispatch::controller::action::cms_index_index::layout_render	33.5866	1	0	0
DISPATCH EVENT:core_block_abstract_to_html_before	0.0006	69	3,704	0
frontend/default/v-tac/template/page/1column.phtml	33.5136	1	6,246,752	6,553,600
frontend/default/v-tac/template/page/html/head.phtml	0.0223	1	222,312	262,144
DISPATCH EVENT:core_block_abstract_to_html_after	0.3045	68	365,360	524,288
OBSERVER: modify	0.0033	68	15,656	0
OBSERVER: mana_core_require	0.0034	68	15,680	0
OBSERVER: mana_filters	0.0028	68	20,816	0
OBSERVER: sharingtool	0.0031	68	18,800	0
OBSERVER: apptrian_minify_core_block_abstract_to_html_after	0.2733	68	352,664	524,288
frontend/default/v-tac/template/directory/js/optional_zip_countries.phtml	0.0003	1	21,512	0
frontend/default/v-tac/template/googleanalytics/ga.phtml	0.0004	1	18,504	0
frontend/default/default/template/addthis/smartlayers/smartlayers.phtml	0.0017	1	9,160	0
frontend/default/v-tac/template/page/html/header.phtml	8.3935	1	894,048	1,048,576
frontend/default/default/template/unibanner/banner.phtml	9.4994	15	505,344	262,144
CORE::create_object_of::Uni_Banner_Model_Bannergroup	0.0008	31	17,704	0
CORE::create_object_of::Uni_Banner_Model_Mysql4_Bannergroup_Collection	0.0097	31	211,512	0
CORE::create_object_of::Uni_Banner_Model_Mysql4_Bannergroup	0.0011	32	15,584	0
CORE::create_object_of::Uni_Banner_Model_Banner	0.0009	38	21,624	0
CORE::create_object_of::Uni_Banner_Model_Mysql4_Banner_Collection	0.012	38	225,128	0
CORE::create_object_of::Uni_Banner_Model_Mysql4_Banner	0.0013	39	18,888	0
frontend/default/default/template/unibanner/effects/custom.phtml	4.7418	15	232,896	0
CORE::create_object_of::Mage_Catalog_Model_Category	0.323	67	224,240	0
DISPATCH EVENT:core_abstract_load_before	0.0003	26	1,720	0
DISPATCH EVENT:catalog_category_load_before	0.0002	19	1,392	262,144
DISPATCH EVENT:catalog_category_load_after	0.0002	19	1,376	0
CORE::create_object_of::Mage_Catalog_Model_Category_Url	0.0004	34	6,440	0
REWRITE: Mage_Catalog_Model_Category_Url::getCategoryUrl	1.4268	34	138,216	0
DISPATCH EVENT:catalog_category_flat_loadnodes_before	0.0001	10	888	0
CORE::create_object_of::Mage_Widget_Model_Template_Filter	0.0001	13	13,896	0
Mage_Core_Model_Design_Package::getSkinUrl	0.0036	32	34,288	0
frontend/default/v-tac/template/searchautocomplete/topsearch.phtml	0.0018	1	16,680	0
frontend/default/v-tac/template/page/custom.phtml	24.4223	1	4,961,744	4,980,736
frontend/default/v-tac/template/clnews/eventlist.phtml	2.2098	2	449,496	524,288
CORE::create_object_of::CommerceLab_News_Model_Mysql4_News_Collection	0.0005	2	10,464	0
CORE::create_object_of::CommerceLab_News_Model_Mysql4_Category_Collection	0.0003	2	10,264	0
CORE::create_object_of::CommerceLab_News_Model_Mysql4_Comment_Collection	0.0007	4	18,352	0
CORE::create_object_of::Int_Featuredproducts_Model_Mysql4_Featuredproducts_Collection	0.0004	2	10,304	0
CORE::create_object_of::Mage_Catalog_Model_Resource_Product	0.1579	1	16,656	0
EAV: Mage_Eav_Model_Config::getEntityType	0.7872	120	46,792	0
__EAV_LOAD_MODEL__	0.8144	1	1,515,520	1,572,864
EAV: Mage_Eav_Model_Config::_initAttributes	0.4815	1	916,096	1,048,576
CORE::create_object_of::Mage_Catalog_Model_Resource_Product_Attribute_Collection	0.1599	1	67,888	0
CORE::create_object_of::Mage_Catalog_Model_Resource_Eav_Attribute	0.0018	101	66,584	0
EAV: Mage_Eav_Model_Config::getAttribute	2.5173	150	79,208	0
__EAV_LOAD_MODEL_AFTER_LOAD__	0.1655	1	524,560	524,288
CORE::create_object_of::Mage_Eav_Model_Entity_Attribute_Backend_Default	0.0003	53	11,176	0
DISPATCH EVENT:catalog_product_load_after	0.6313	1	310,152	262,144
OBSERVER: inventory	0.4736	2	231,056	0
OBSERVER: currencypricing_load_product_compound_price	0.1585	1	119,152	262,144
OBSERVER: currencypricing_load_product_compound_special_price	0.1571	1	1,728	0
CORE::create_object_of::Innoexts_CurrencyPricing_Model_Mysql4_Catalog_Product_Collection	0.4766	1	373,328	524,288
DISPATCH EVENT:catalog_product_collection_apply_limitations_after	0.002	5	182,960	262,144
OBSERVER: currencypricing_after_product_collection_apply_limitations	0.0016	5	180,224	262,144
DISPATCH EVENT:catalog_block_product_list_collection	1.425	2	427,152	262,144
OBSERVER: review	1.4248	2	424,424	262,144
__EAV_COLLECTION_LOAD_ENT__	0.4743	1	155,368	0
__EAV_COLLECTION_AFTER_LOAD__	0.6344	1	163,376	262,144
DISPATCH EVENT:catalog_product_collection_load_after	0.4765	1	152,880	262,144
OBSERVER: tax	0.0007	1	71,408	0
OBSERVER: currencypricing_load_product_collection_compound_price	0.1585	1	10,968	0
OBSERVER: currencypricing_load_product_collection_compound_special_price	0.1581	1	3,288	0
frontend/default/v-tac/template/videogallery/videogallery.phtml	1.573	2	170,712	0
CORE::create_object_of::Krishinc_Videogallery_Model_Videogallery	0.0003	10	6,024	0
CORE::create_object_of::Krishinc_Videogallery_Model_Mysql4_Videogallery_Collection	0.0008	4	18,656	0
frontend/default/v-tac/template/page/custom_files/looking_for.phtml	3.3208	2	306,648	524,288
_LOAD_ATTRIBUTE_BY_CODE__	1.8844	4	30,736	0
CORE::create_object_of::Mage_Eav_Model_Resource_Entity_Attribute_Option_Collection	0.0021	5	53,632	0
frontend/default/v-tac/template/page/html/footer.phtml	0.5112	1	137,592	0
frontend/default/v-tac/template/newsletter/subscribe.phtml	0.0014	1	6,384	0
CACHE_URL	0.0043	1	124,848	0

[Mageworx Team]

Hey @jerome_leung,

Thanks for providing extra data.

We'd say that  the prolonged page load time is directly related to the issues in certain blocks, as a great deal of time takes layout load: (mage::dispatch::controller::action::cms_index_index::layout_render    33.5866, that's where header loads for too long as well: (frontend/default/v-tac/template/page/html/header.phtml    8.3935) , banner (frontend/default/default/template/unibanner/banner.phtml    9.4994) and some impossibly slow block (set of blocks) - (frontend/default/v-tac/template/page/custom.phtml    24.4223).

We'd recommend to start with disabling the extension that slowly loads banners. Then try to switch to the standard theme. Then review all the blocks that it takes too long to load, one after another (check out all the blocks with time higher than 0.5 seconds in profiler).

It's highly likely that huge collection loads are called in those blocks.

---------------------------------------------------------

If you've found one of our answers useful, please give 'Kudos' or 'Accept as Solution'.

[jerome_leung]

@Mageworx Team, is there a way for me to show you a list of the extensions that this site has?

[Mageworx Team]

@jerome_leung, sure. Copy paste the list of files from app/etc/modules.

Anyways, to deal with the issue, switch to the default theme and debug a block after block. This should work out.

[jerome_leung]

@Mageworx Team, here is the list of extensions

AddThis_Sharingtool.xml
AjaxNewsletter_Ajaxnewsletter.xml
Anowave_Price.xml
Aoe_Scheduler.xml
Apptrian_Minify.xml
Aschroder_SMTPPro.xml
BusinessKing_OutofStockSubscription.xml
Clarion_Customerattribute.xml
Clearandfizzy_EnhancedCMS.xml
Cm_RedisSession.xml
CommerceLab_News.xml
Creation_Afipredirect.xml
Dexxtz_Productzoom.xml
ET_Lytebox.xml
Inchoo_Shipping.xml
Innoexts_Core.xml
Innoexts_CurrencyPricing.xml
Int_Featuredproducts.xml
Int_Pdfupload.xml
Italian_locale.xml
Jain_Bought.xml
Kanavan_Searchautocomplete.xml
Krishinc_Videogallery.xml
Mage_All.xml
Mage_Api.xml
Mage_Api2.xml
Mage_Authorizenet.xml
Mage_Bundle.xml
Mage_Captcha.xml
Mage_Centinel.xml
Mage_Compiler.xml
Mage_Connect.xml
Mage_CurrencySymbol.xml
Mage_Downloadable.xml
Mage_ImportExport.xml
Mage_Oauth.xml
Mage_PageCache.xml
Mage_Persistent.xml
Mage_Weee.xml
Mage_Widget.xml
Mage_XmlConnect.xml
Magehouse_Infinity.xml
Magpleasure_Filesystem.xml
Mana_Core.xml
Mana_Db.xml
Mana_Filters.xml
Netzarbeiter_CustomerActivation.xml
Phoenix_Moneybookers.xml
Pulsestorm_Tinymceconfig.xml
Raveinfosys_Deleteorder.xml
SaveTheMage_CustomInvoiceAndOrderNumber.xml
SF9_Realex.xml
Uni_Banner.xml
Uni_Banner_13012016.xml
V2store_Catalog.xml
V2store_Checkout.xml
V2store_Sales.xml
V2store_Shipping.xml
Vestrics_Casestudies.xml
Vestrics_ConnectorSales.xml
Vestrics_Core.xml
Vestrics_Coreextended.xml
Vestrics_Custom.xml
Vestrics_Lightingcal.xml
Vestrics_ProductCurrency.xml
Vestrics_Quickorder.xml
Vestrics_Sap.xml
Vestrics_Sapapi.xml
Vestrics_Tracking.xml
WP_CustomMenu.xml

Which directory are the blocks kept in?

[Mageworx Team]

@jerome_leung,

Magehouse_Infinity Mana_* BusinessKing_OutofStockSubscription Anowave_Price Int_Featuredproducts Innoexts_CurrencyPricing Jain_Bought Kanavan_Searchautocomplete Krishinc_Videogallery Uni_Banner V2store_* Vestrics_*  are potentially 'dangerous' modules. We'd recommend to turn off all of them and check the speed without them. If it gets better, enable them in turns and check. Don't forget to update cache each time you enable/disable modules. 

* are modules of the same vendor.

This should help, but without having a look at the code, it's hard to tell for sure.

---------------------------------------------------------

If you've found one of our answers useful, please give 'Kudos' or 'Accept as Solution'.

[jerome_leung]

@Mageworx Team

Disabling Int_Featuredproducts and Innoexts_CurrencyPricing reduce the load time by about 8 seconds but makes the main part of the site disappear. Disabling Uni_Banner breaks the site altogether, but it loads almost immediately. All the other extensions don't seem to have much effect on the site.

[Mageworx Team]

@jerome_leung,

Hm, I checked module code with the banners, requests to collections and image resize are the heaviest requests. But there are attempts to use cache and maximally decrease the load. So, that's unlikely what's causing the issue. You should check out why the module breaks the site and fix it (that's not the way a module should operate), and then take a look what will be next. The banner block is likely to be wired within the cms page, which may cause the error when the module is disabled. I'd recommend to off it and try further.

---------------------------------------------------------

If you've found one of our answers useful, please give 'Kudos' or 'Accept as Solution'.