rob_dewing

Admin pages running slow

Recommended Posts

We've updated a site from v4 to v6, which all seemed to go through fine and the front end pages are running superfast, like 0.5 sec loadtime, but admin pages are shockingly slow, taking 45sec to 90sec to save changes to products for example.

Any thoughts on where we should begin to look for causes of this? I've tried running Yslow but the results have not moved us forward any.

Share this post


Link to post
Share on other sites

I see that as well. But, 90 secs... not that long.

Running a few dev versions on an in-house server, 1-3 secs for both frontside and backside.

Running a production store on a commercial hosting provider, (relatively) a lot longer for admin pages, but really decent speed on the frontside. (Plus, my email is hosted by the commercial provider, and that is very slow.) So, it may be the server, it may be the pipe from there to here.

But I concur that, overall, CC3/4 is wickedly faster than CC5/6.

Share this post


Link to post
Share on other sites

check for long running SQL queries... could be a sign of indexes not correct. note that I've not seen the "debug" output fro CubeCart every correctly report SQl query times, so you may want to check manually

Also, if you have a large store there could be caching of images ongoing which can murder performance until it's done. quick way to check is go to the filemanager. if you can load it, not caching.

when you did your upgrade, did you clean up all the old modules? they won't work in v6 so deleting them all is a good idea. I've sen conflicts caused by these in the past.

What modules do you have installed?

Share this post


Link to post
Share on other sites

All good suggestions from @Noodleman  and you should definitely look at what plugins you have installed - delete everything and re-install the latest versions of only those you are using.  Also check and see what caching you have enabled - are you using default "file" based caching or memcache (by far the best is REDIS which we use for all clients but most hosting providers dont make that available).  

Ian

Share this post


Link to post
Share on other sites

Thanks to all of you for valuable advice. I already disabled caching (Cubecart default was in use) in order to get a true picture of front end load time. I found front end remained very fast, and it made no difference to the back end problems.

I will look at legacy extensions, I think there is only one though and that is a front end slideshow which surely would not slow down the backend. Am going to get my hosting support guys to take a look. 

Share this post


Link to post
Share on other sites

It's only slow on admin updating products or categories. Editing pages or changing site settings runs fast, And everything on the front end is completely fine too.

Share this post


Link to post
Share on other sites

To recap, the front end of the site is perfect, and admin side is perfect except for product edting pages or category editing pages. These run at 25 - 100 sec load time. Everything else admin side is <2 sec, front end is <1 sec pageload.

So I've worked through the admin panel generated list of database errors and corrected all of them, about a dozen, mostly duplicate or missing keys or wrong type of key, and now have no DB errors showing in admin list (yes Noodleman I note your comment that this admin generated list is not always definitive). Presumably to look at slow running SQL queries I can examine the debug log on affected pages. So below is an extract showing some of what I think are relevant lines. Note there are no PHP errors reported in this log.

I've put the suspect queries in bold, everything else shows query time around 0.000X sec, these two (items [22] and [23]) show no times at all, presumably they exceeded some limit. They refer to Product Options Matrix, however we have no product options in use on this site, and none show up in the product options listing:

[20] SELECT SQL_CALC_FOUND_ROWS `cart_order_id`, `name`, `first_name`, `last_name`, `order_date`, `customer_id`, `total`, `status` FROM `CubeCart_order_summary` WHERE status IN (1,2) OR `dashboard` = 1 ORDER BY `dashboard` DESC, `order_date` ASC LIMIT 25 OFFSET 0; -- (0.0017428398132324 sec) [NOT CACHED]
[21] SELECT SQL_CALC_FOUND_ROWS * FROM `CubeCart_reviews` WHERE CubeCart_reviews.approved = '0' LIMIT 25 OFFSET 0; -- (0.00012493133544922 sec) [NOT CACHED]
[22] SELECT I.name, I.product_code, I.stock_level AS I_stock_level, I.stock_warning AS I_stock_warning, I.product_id, M.stock_level AS M_stock_level, M.use_stock as M_use_stock, M.cached_name FROM `CubeCart_inventory` AS `I` LEFT JOIN `CubeCart_option_matrix` AS `M` on `I`.`product_id` = `M`.`product_id` WHERE use_stock_level = 1 AND (((I.stock_warning > 0 AND M.stock_level [NOT CACHED]
[23] SELECT SQL_CALC_FOUND_ROWS I.name, I.product_code, I.stock_level AS I_stock_level, I.stock_warning AS I_stock_warning, I.product_id, M.stock_level AS M_stock_level, M.use_stock as M_use_stock, M.cached_name FROM `CubeCart_inventory` AS `I` LEFT JOIN `CubeCart_option_matrix` AS `M` on `I`.`product_id` = `M`.`product_id` WHERE use_stock_level = 1 AND (((I.stock_warning > 0 AND M.stock_level [NOT CACHED]

[24] SELECT FOUND_ROWS() as Count; -- (7.5817108154297E-5 sec) [NOT CACHED]
[25] SELECT * FROM `CubeCart_extension_info` WHERE `file_id` IN (-1) ; -- (0.0010781288146973 sec) [NOT CACHED]
[26] SELECT COUNT(product_id) AS Count FROM `CubeCart_inventory` ; -- (0.00054216384887695 sec) [NOT CACHED]

 

The System error log in admin shows entries such as:

Today, 23:43 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/seo.class.php:323 - Undefined variable: path
Today, 23:43 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/seo.class.php:323 - Undefined variable: path
Today, 23:43 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/seo.class.php:323 - Undefined variable: path
Today, 23:43 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/catalogue.class.php:307 - Undefined index:
Today, 23:40 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/catalogue.class.php:307 - Undefined index:
Today, 23:39 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/ajax.class.php:46 - Undefined index: function
Today, 23:39 [Notice] /home/northerwood/G0DG68Q0/htdocs/ronlines/classes/seo.class.php:323 - Undefined variable: path

 

What is to be concluded from this? Any comments would be gratefully received.

 

Share this post


Link to post
Share on other sites

SQL statements 22 and 23 are not complete. Specifically:

... AND (((I.stock_warning > 0 AND M.stock_level [NOT CACHED]

Note that there are three open parens with no matching closing parens, and missing any kind of limit.

These statements should have shown as SQL errors in a list just following the SQL Statements list.

I will look for where these SQL statements are constructed.

Share this post


Link to post
Share on other sites

The aforementioned statements have characters in them that confuse the proper HTML display of them. Specifically, the characters that follow what appear to be the truncation location are:

<= I.stock_warning ...

We will assume the statements are correct. (A bug report has been submitted.)

Also, note statement 24: the time shown may be confusing to all except scientists. The E-5 scientific notation makes this value very small.

The bug report is: https://github.com/cubecart/v6/issues/1354

If you wish to make this edit yourself:

In classes/debug.class.php, near line 201, find:

$this->_sql[$type][] = '<span style="color:#'.$colour.'">'.htmlentities(strip_tags($message).' ['.$tag.']', ENT_COMPAT, 'UTF-8').'</span>';

Change to:

$this->_sql[$type][] = '<span style="color:#'.$colour.'">'.htmlentities( $message.' ['.$tag.']', ENT_COMPAT, 'UTF-8').'</span>'; // strip_tags($message)

 

Share this post


Link to post
Share on other sites

Hi Brian

Sorry, that was me truncating the information:

Page Load Time:
0.007737 seconds

The full set of data is copied into the attached. This particular one is for the login page, which is slowed down presumably by the loading of product info into the admin landing page. If I modify the login URL in the address bar so that it lands on for example docs, login takes about 2 sec instead of 120sec +

 

login log.doc

Share this post


Link to post
Share on other sites

Obviously, eight milliseconds is fast. On my local dev server, it takes 0.3 seconds.

I have also just discovered that the time hacks may be getting calculated erroneously. See: https://github.com/cubecart/v6/issues/1814

Also, please make the edit I discussed earlier, as well as the edit proposed in the Github issue.

This will get us better time hacks.

I will also probably suggest an edit to enhance the SQL Query list to show the time the query was made, not just the time it took to get the resultset.

Share this post


Link to post
Share on other sites

I have made a small edit to the statement edited previously:

$this->_sql[$type][] = '<span style="color:#'.$colour.'">'.str_pad($this->_getTime(),16,'0') .' '. htmlentities( $message.' ['.$tag.']', ENT_COMPAT, 'UTF-8').'</span>';

This prepends the time to the logged SQL query. Thus, if any part of CubeCart (other than Smarty) takes an abnormal amount of time to do something, that time span should show up when comparing when the queries get executed.

Share this post


Link to post
Share on other sites

Thanks. I have changed classes/debug.class.php with your code snippet and retested. Files of debug info and system errors are attached for the product editing page. We still seem to be looking at query times which are mostly in the order of 10E-5 apart from a couple around 0.02sec. Doesn't seem to add up to the observed 30 second page load time.   

The error log relates entirely to this page call; I cleared the log before visiting the page. I look forward to your further thoughts on the logs. Thanks.

171129debugsingleproduct.doc

171129systemerrorlog.doc

Share this post


Link to post
Share on other sites

If you are willing to share FTP & admin area login details with me privately, I can look at this for you...  shouldn't take long to fix :)

Share this post


Link to post
Share on other sites

From my initial examination of program flow based on your debugsingleproduct.doc* file, the 15 second duration mentioned above should be caused by CubeCart asking for a "Google Taxonomy" listing.

The other instances of long duration page delivery times may be caused by similar scenarios. That is, CubeCart making requests for external data.

It could just be the case that the server hosting your CubeCart simply sucks at fetching outside content (dashboard stuff, for example).

In admin, PHP Info, scroll to the table where "curl" would be displayed. (They are in alphabetical order.) Is that table present? If so, is CURL enabled?

In admin, Request Log, scan for any evidence of a CURL Error.

Try this:

In CC6112, products.index.inc.php, near line 685, find:

$google_cats = false;
$store_country = $GLOBALS['config']->get('config', 'store_country');
$taxonomy_lang = ($store_country==826) ? 'en-GB' : 'en-US';

$request = new Request('www.google.com', '/basepages/producttype/taxonomy.'.$taxonomy_lang.'.txt');
$request->setMethod('get');
$request->skiplog(true);
$request->cache(true);

if($response = $request->send()) {
  $google_cats = explode("\n",$response);
}

Change to:

$google_cats = false;
/*
$store_country = $GLOBALS['config']->get('config', 'store_country');
$taxonomy_lang = ($store_country==826) ? 'en-GB' : 'en-US';

$request = new Request('www.google.com', '/basepages/producttype/taxonomy.'.$taxonomy_lang.'.txt');
$request->setMethod('get');
$request->skiplog(true);
$request->cache(true);

if($response = $request->send()) {
  $google_cats = explode("\n",$response);
}
*/

Does that make getting an Edit Product page any faster?

Share this post


Link to post
Share on other sites

it's fixed.

Issue was the upgrade from v4 ported several thousand cached folders/images from the magictoolbox module to images/source. these are not being used, but killed the performance. moved them out of source, rebuilt image library... instant page loads.

Share this post


Link to post
Share on other sites

Thanks very much Noodleman, brilliant news to have this tracked down and now fixed. I've tested and the site runs really well now . I had another V4-6 upgrade go really well a couple of months back, so this one was flummoxing me - but looking back, the main difference between the two was this one module. You mentioned deleting old modules way back in this thread, but I hadn't deleted the cache which it had created.

Thanks again. 

Share this post


Link to post
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now