Parse time Options

[kbking]

Hi,

At the moment I am talking with my webhost about the parse time of the pages. I have noticed that everything is fine when people are not browsing the Internet. At least it appears so. Around lunch, around three o'clock in the afternoon, around seven o'clock in the evening, and a few other times of the day the browser has to struggle real hard in order to bring the page to the screen.

On my development server I have a parse time of 0,1 - 0,2 sek. It can be the same on my remote server (they are clones), but it is mostly late at night.

I don't know these things well enough to relly look after my interests visavi my webhost. I have been very careful not to touch the core code of the Oscommerce. The modifications I have done are mainly to serve performance and safety. The alterations emanates from coders like chemo, Monica in Germany, Vger, FWR Media, boxtel, Jack_mcs and a few other likewise renowned coders. This means I am not worried about the correctness of my application.

The fact that the parse time is lightening fast certain times of the day (0.1 or even below at its best), should be a clear justification for the sanity of my site, right?

I had a few hours off today and wanted to do the final adjustments before going live, but I couldn't stand the waiting time. I logged the parse time and heres what I found:


****START LOGG****

2008-02-27

11:25
10 sek. 42 queries customer_testimonials.php

11:30
44.120 sek. 42 queries customer_testimonials.php

11:34
33.973 sek. 42 queries customer_testimonials.php

11:35
25:235 sek. 42 queries customer_testimonials.php

11:37
12:225 sek. 42 queries customer_testimonials.php

11:43
15:162 sek. 42 queries customer_testimonials.php

11:46
15:162 sek. 43 queries allprod.php

11:46
14:892 sek. 47 queries links.php

11:49
10:454 sek. 41 queries contact_us.php

kl. 11:51
21:795 sek. 41 queries shop_by_price.php?range=1

11:52
9:793 sek. 41 queries shop_by_price.php?range=1

11:53
13:948 sek. 41 queries shop_by_price.php?range=1

11:56
32.029 sek. 41 queries shop_by_price.php?range=1

11:59
26.927 sek. 41 queries shop_by_price.php?range=1

12:01
116.070 sek. 73 queries
product_info.php?products_id=40

12:05
54.403 sek. 65 queries product_info.php?products_id=40

12:07
103.172 sek. 62 queries dynamic_sitemap.php

12:11
42.874 sek. 62 queries dynamic_sitemap.php

12:12
33.409 sek. 62 queries dynamic_sitemap.php

12:13
24.917 sek. 62 queries dynamic_sitemap.php

12:14
26.226 sek. 62 queries dynamic_sitemap.php

12:15
26.226 sek. 62 queries dynamic_sitemap.php

27 february 2008 12:23 from a colleagues computer -
/dynamic_sitemap

1053 - Server shutdown in progress

select configuration_key as cfgKey, configuration_value
as cfgValue from
configuration

[TEP STOP]

****END LOGG****

I wrote a letter to the webhost and told them pretty much the same as I've written here. They responded and offered me a brand new and newer MySql database. I accepted this and connected to it. But I don't see much differnce to the old one and when I compare the index page of the two, the only difference is the database name and the login username and password.

I think it all boils down to an overloaded server, i.e. to many sites and hence no power left! Would it be correct to assume this?

Could my own old computer (1.2 GHz, 512 Mb Ram) be held responsible for anything of this?

I need some insight and advice on how to proceed and argue tomorrow.

Thank You!

[FWR Media]

looks to point to the server for me.

How are you recording parse time?

Does sek mean seconds?

Basically aside of this it is the "difference" e.g. customer_testimonials best 10 worst 44 that is huge.

A decent server shouldn't vary too much .. it will vary .. but not THAT much.

[theantiquestore]

We had the same issue a few years ago when we were starting out. It was from being on a shared server with a host who really liked to share and didnt care who he shared it with. Any other site with database issues slowed the sql to a crawl during peak traffic times thus everyone on that server ended up suffering too.

We moved to a dedicated server 2 years or so ago and it was the best money we've ever spent. We control who is on it and what they are doing with it. Perhaps this isnt your issue, but I thought I'd offer my 2 cents just in case it is.

[kbking]

Thanks for both of your answers!

In Configuration -> Logging I have set Display The Page Parse Time to True. It prints out to the footer like so: Current Parse Time: 0.132 s with 65 queries.

sek means seconds.

We were very particular when we were to choose webhost a few years ago. We picked the one which had gotten the best reviews in Internet World, a well known magazine here in Sweden. The company was sold a year or so ago for a huge sum I think close a 100 milion SEK. Actually we were ready to go live the last summer, but experienced the same problems. I contacted the support by telephone and was politely told that I was to blame not them. Well I was not sure so in August 2007 I trashed everything and started from scratch.

Now I keep a record of every change I do to the code.

I have also noticed that sometimes, not often but it happens, some of the images are not visible although the page load have finished, why is that?

I have also closely monitored the discussion on an other forum whether one should implement all the new patches that are available to the 2.2 or not. I came to the conclusion that I'm best suited to do the RC1 and RC2 updates; my reasoning for this is that the osc Team won't jeopardize the whole project by issuing untested code. Not being an expert myself, I think this was my only option.

The webhost gave me an other database to connect to. Why did they? A cheap trick? As far as I can see it's not newer nor better, it's the same!

[FWR Media]

It's probably not what you want to hear but I would create a home pc server download the whole site and do your testing on there.

Add Chemos contribution queries_debug-v1.6 so that you can see all the slow queries and page parse times in real time and work out if there is anything slowing it down.

To have page parse times of the size that you have shown must mean either an overloaded server OR there is something fundamentally wrong with your code.

The former is where I would point my finger but if you have tested it locally you would have proof.

[kbking]

I have a clone of the whole site locally on my pc server since the beginning as well as I have Chemos contribution queries debug.

I tried to display Display Database Queries from the new database, but nothing shows (maybe I forgot to do some settings, I don't know). I connected to the old database and that went better, the queries debug prints out the following to the screen:

CODE

QUERY DEBUG:

Array
(
    [QUERIES] => Array
        (
            [0] => select value from sessions where sesskey = '2a0dbcfa519f8171ff8593b292599ad1' and expiry > '1204188545'
            [1] => select c.categories_id, c.parent_id from categories c order by c.parent_id
            [2] => select code, title, image1, image2, symbol_left, symbol_right, decimal_point, thousands_point, decimal_places, value from currencies
            [3] => delete from whos_online where time_last_click < '1204187645'
            [4] => select count(*) as count from whos_online where session_id = '2a0dbcfa519f8171ff8593b292599ad1'
            [5] => update whos_online set customer_id = '0', full_name = 'Guest', ip_address = '81.226.266.205', time_last_click = '1204188545', last_page_url = '/product_info.php?products_id=40' where session_id = '2a0dbcfa519f8171ff8593b292599ad1'
            [6] => select banners_id, date_scheduled from banners where date_scheduled != ''
            [7] => select b.banners_id, b.expires_date, b.expires_impressions, sum(bh.banners_shown) as banners_shown from banners b, banners_history bh where b.status = '1' and b.banners_id = bh.banners_id group by b.banners_id
            [8] => select specials_id from specials where status = '1' and now() >= expires_date and expires_date > 0
            [9] => select p2c.categories_id from products p, products_to_categories p2c where p.products_id = '40' and p.products_status = '1' and p.products_id = p2c.products_id limit 1
            [10] => select parent_id from categories where categories_id = '34'
            [11] => select parent_id from categories where categories_id = '2'
            [12] => select categories_name from categories_description where categories_id = '2' and language_id = '4'
            [13] => select categories_name from categories_description where categories_id = '34' and language_id = '4'
            [14] => select products_model from products where products_id = '40'
            [15] => select count(*) as total from products p, products_description pd where p.products_status = '1' and p.products_id = '40' and pd.products_id = p.products_id and pd.language_id = '4'
            [16] => select languages_id, name, code, image, directory from languages order by sort_order
            [17] => select symbol_left, symbol_right, value from currencies where code = 'SEK' limit 1
            [18] => select p.products_id, pd.products_name, p.products_price, p.products_tax_class_id, p.products_image from products p, products_description pd where p.products_status = '1' and p.products_id = pd.products_id and pd.language_id = '4' and TO_DAYS(NOW()) - TO_DAYS(products_date_added) < '90' order by products_date_added desc limit 25
            [19] => select specials_new_products_price from specials where products_id = '29' and status
            [20] => select sum(tax_rate) as tax_rate from tax_rates tr left join zones_to_geo_zones za on (tr.tax_zone_id = za.geo_zone_id) left join geo_zones tz on (tz.geo_zone_id = tr.tax_zone_id) where (za.zone_country_id is null or za.zone_country_id = '0' or za.zone_country_id = '203') and (za.zone_id is null or za.zone_id = '0' or za.zone_id = '18') and tr.tax_class_id = '2' group by tr.tax_priority
            [21] => select specials_new_products_price from specials where products_id = '40' and status
            [22] => select specials_new_products_price from specials where products_id = '30' and status
            [23] => select specials_new_products_price from specials where products_id = '39' and status
            [24] => select specials_new_products_price from specials where products_id = '38' and status
            [25] => select specials_new_products_price from specials where products_id = '37' and status
            [26] => select specials_new_products_price from specials where products_id = '36' and status
            [27] => select specials_new_products_price from specials where products_id = '35' and status
            [28] => select specials_new_products_price from specials where products_id = '34' and status
            [29] => select specials_new_products_price from specials where products_id = '33' and status
            [30] => select specials_new_products_price from specials where products_id = '32' and status
            [31] => select specials_new_products_price from specials where products_id = '31' and status
            [32] => select specials_new_products_price from specials where products_id = '28' and status
            [33] => select sum(tax_rate) as tax_rate from tax_rates tr left join zones_to_geo_zones za on (tr.tax_zone_id = za.geo_zone_id) left join geo_zones tz on (tz.geo_zone_id = tr.tax_zone_id) where (za.zone_country_id is null or za.zone_country_id = '0' or za.zone_country_id = '203') and (za.zone_id is null or za.zone_id = '0' or za.zone_id = '18') and tr.tax_class_id = '1' group by tr.tax_priority
            [34] => select l.links_id, l.links_url, l.links_image_url, ld.links_title, lf.expires_date from links l, links_description ld, links_featured lf where l.links_id = ld.links_id AND ld.links_id = lf.links_id AND lf.expires_date >= now() order by RAND() limit 10
            [35] => select p.products_id, pd.products_name, pd.products_description, pd.products_spec, pd.products_musthave, pd.products_extraimage, pd.products_manual, pd.products_extra1, pd.products_moreinfo, p.products_model, p.products_quantity, p.products_image, pd.products_url, p.products_price, p.products_tax_class_id, p.products_date_added, p.products_date_available, p.manufacturers_id, p.products_matching from products p, products_description pd where p.products_status = '1' and p.products_id = '40' and pd.products_id = p.products_id and pd.language_id = '4'
            [36] => update products_description set products_viewed = products_viewed+1 where products_id = '40' and language_id = '4'
            [37] => select specials_new_products_price from specials where products_id = '40' and status
            [38] => select categories_description from extra_cat_info left join products_to_categories using (categories_id) where products_to_categories.products_id=40 and extra_cat_info.language_id = '4'
            [39] => SELECT products_extra_image, products_extra_images_id FROM products_extra_images WHERE products_id='40'
            [40] => select count(*) as total from products_options popt, products_attributes patrib where patrib.products_id='40' and patrib.options_id = popt.products_options_id and popt.language_id = '4'
            [41] => select distinct popt.products_options_id, popt.products_options_name from products_options popt, products_attributes patrib where patrib.products_id='40' and patrib.options_id = popt.products_options_id and popt.language_id = '4' order by popt.products_options_name
            [42] => select pov.products_options_values_id, pov.products_options_values_name, pa.options_values_price, pa.price_prefix from products_attributes pa, products_options_values pov where pa.products_id = '40' and pa.options_id = '6' and pa.options_values_id = pov.products_options_values_id and pov.language_id = '4' order by pa.attribute_sort
            [43] => select pov.products_options_values_id, pov.products_options_values_name, pa.options_values_price, pa.price_prefix from products_attributes pa, products_options_values pov where pa.products_id = '40' and pa.options_id = '12' and pa.options_values_id = pov.products_options_values_id and pov.language_id = '4' order by pa.attribute_sort
            [44] => select pov.products_options_values_id, pov.products_options_values_name, pa.options_values_price, pa.price_prefix from products_attributes pa, products_options_values pov where pa.products_id = '40' and pa.options_id = '13' and pa.options_values_id = pov.products_options_values_id and pov.language_id = '4' order by pa.attribute_sort
            [45] => select count(*) as count from reviews where approved = 1 and products_id = '40'
            [46] => select p.products_id from products p, products_to_categories ptc where p.products_status = '1'  and p.products_id = ptc.products_id and ptc.categories_id = 34
            [47] => select categories_name from categories_description where categories_id = 34 AND language_id = 4
            [48] => select products_id, categories_id from products_to_categories where products_id = '40' order by products_id,categories_id
            [49] => select categories_id from categories where parent_id = '34'
            [50] => select distinct p.products_id, pd.products_name, p.products_price, p.products_tax_class_id, p.products_image, s.specials_new_products_price from products p, products_description pd, products_to_categories p2c, categories c, specials s where p.products_status='1' and p.products_id=s.products_id and p.products_id=pd.products_id and pd.language_id='4' and p.products_id = p2c.products_id and p2c.categories_id = c.categories_id and s.status='1' and (p2c.categories_id = '34') order by rand() limit 3
            [51] => select * FROM customer_testimonials WHERE status = 1 ORDER BY rand() LIMIT 1
            [52] => select m.manufacturers_id, m.manufacturers_name, m.manufacturers_image, mi.manufacturers_url from manufacturers m left join manufacturers_info mi on (m.manufacturers_id = mi.manufacturers_id and mi.languages_id = '4'), products p  where p.products_id = '40' and p.manufacturers_id = m.manufacturers_id
            [53] => select products_name from products_description where products_id = '40' and language_id = '4'
            [54] => select r.reviews_id, r.reviews_rating, p.products_id, p.products_image, pd.products_name from reviews r, reviews_description rd, products p, products_description pd where p.products_status = '1' and p.products_id = r.products_id and r.reviews_id = rd.reviews_id and rd.languages_id = '4' and p.products_id = pd.products_id and pd.language_id = '4' and r.approved = '1' and p.products_id = '40' order by r.reviews_id desc limit 10
            [55] => select startdate, counter from counter
            [56] => update counter set counter = '14485'
            [57] => select code from languages where directory = 'swedish'
            [58] => select banners_id, banners_title, banners_image, banners_html_text from banners where status = '1' and banners_group = '468x60'
            [59] => select count(*) as total from sessions where sesskey = '2a0dbcfa519f8171ff8593b292599ad1'
            [60] => update sessions set expiry = '1204189986', value = 'SESSION_IP_ADDRESS|s:14:\"81.226.266.205\";cart|O:12:\"shoppingCart\":5:{s:8:\"contents\";a:0:{}s:5:\"total\";i:0;s:6:\"weight\";i:0;s:6:\"cartID\";N;s:12:\"content_type\";b:0;}language|s:7:\"swedish\";languages_id|s:1:\"4\";your_recent_history|O:14:\"recent_history\":7:{s:12:\"viewed_items\";a:1:{i:0;s:2:\"40\";}s:8:\"searches\";a:0:{}s:11:\"viewed_cats\";a:0:{}s:2:\"on\";b:1;s:4:\"pmax\";i:4;s:4:\"smax\";i:10;s:4:\"cmax\";i:10;}currency|s:3:\"SEK\";navigation|O:17:\"navigationHistory\":2:{s:4:\"path\";a:2:{i:0;a:4:{s:4:\"page\";s:12:\"allprods.php\";s:4:\"mode\";s:6:\"NONSSL\";s:3:\"get\";a:0:{}s:4:\"post\";a:0:{}}i:1;a:4:{s:4:\"page\";s:16:\"product_info.php\";s:4:\"mode\";s:6:\"NONSSL\";s:3:\"get\";a:1:{s:11:\"products_id\";s:2:\"40\";}s:4:\"post\";a:0:{}}}s:8:\"snapshot\";a:0:{}}' where sesskey = '2a0dbcfa519f8171ff8593b292599ad1'
        )

    [TIME] => Array
        (
            [0] => 0.000611
            [1] => 0.000512
            [2] => 0.000573
            [3] => 0.000475
            [4] => 0.000434
            [5] => 0.000851
            [6] => 0.000541
            [7] => 0.000448
            [8] => 0.000417
            [9] => 0.006631
            [10] => 0.000454
            [11] => 0.000429
            [12] => 0.002201
            [13] => 0.000534
            [14] => 0.000439
            [15] => 0.000527
            [16] => 0.000506
            [17] => 0.000408
            [18] => 0.001002
            [19] => 0.000365
            [20] => 0.000410
            [21] => 0.000347
            [22] => 0.000301
            [23] => 0.000368
            [24] => 0.000342
            [25] => 0.000376
            [26] => 0.000373
            [27] => 0.000265
            [28] => 0.000264
            [29] => 0.000268
            [30] => 0.000272
            [31] => 0.000367
            [32] => 0.000265
            [33] => 0.000449
            [34] => 0.000737
            [35] => 0.001043
            [36] => 0.000943
            [37] => 0.000347
            [38] => 0.007091
            [39] => 0.005368
            [40] => 0.003664
            [41] => 0.009843
            [42] => 0.001793
            [43] => 0.003229
            [44] => 0.001013
            [45] => 0.000484
            [46] => 0.000568
            [47] => 0.000454
            [48] => 0.000895
            [49] => 0.000581
            [50] => 0.001245
            [51] => 0.002897
            [52] => 0.002174
            [53] => 0.000534
            [54] => 0.000874
            [55] => 0.000461
            [56] => 0.000773
            [57] => 0.000285
            [58] => 0.000366
            [59] => 0.000919
            [60] => 0.007996
        )

)

SESSION:

Array
(
    [SESSION_IP_ADDRESS] => 81.226.266.205
    [cart] => shoppingCart Object
        (
            [contents] => Array
                (
                )

            [total] => 0
            [weight] => 0
            [cartID] =>
            [content_type] =>
        )

    [language] => swedish
    [languages_id] => 4
    [your_recent_history] => recent_history Object
        (
            [viewed_items] => Array
                (
                    [0] => 40
                )

            [searches] => Array
                (
                )

            [viewed_cats] => Array
                (
                )

            [on] => 1
            [pmax] => 4
            [smax] => 10
            [cmax] => 10
        )

    [currency] => SEK
    [navigation] => navigationHistory Object
        (
            [path] => Array
                (
                    [0] => Array
                        (
                            [page] => allprods.php
                            [mode] => NONSSL
                            [get] => Array
                                (
                                )

                            [post] => Array
                                (
                                )

                        )

                    [1] => Array
                        (
                            [page] => product_info.php
                            [mode] => NONSSL
                            [get] => Array
                                (
                                    [products_id] => 40
                                )

                            [post] => Array
                                (
                                )

                        )

                )

            [snapshot] => Array
                (
                )

        )

)

COOKIE:

Array
(
    [osCsid] => 2a0dbcfa519f8171ff8593b292599ad1
)

POST:

Array
(
)

GET:

Array
(
    [products_id] => 40
)

[kbking]

Also I have checked my error logs locally (don't know how to accesss them at my webhost).

My php error log is empty, that is, no errors found -> indicates completely clean, accurate code all over, I presume.

My MySql error log shows a lot of these, which I believe also are indicating that everything is OK:

080227 22:44:15 InnoDB: Starting shutdown...
080227 22:44:25 InnoDB: Shutdown completed; log sequence number 0 115403109
080227 22:44:25 [Note] c:\wamp\mysql\bin\mysqld-nt.exe: Shutdown complete

080228 6:52:31 InnoDB: Started; log sequence number 0 115403109
080228 6:53:00 [Note] c:\wamp\mysql\bin\mysqld-nt.exe: ready for connections.
Version: '5.0.41-community-nt' socket: '' port: 3306 MySQL Community Edition (GPL)
080228 7:06:34 [Note] c:\wamp\mysql\bin\mysqld-nt.exe: Normal shutdown

080228 7:06:36 InnoDB: Starting shutdown...
080228 7:06:44 InnoDB: Shutdown completed; log sequence number 0 115403109
080228 7:06:44 [Note] c:\wamp\mysql\bin\mysqld-nt.exe: Shutdown complete

[FWR Media]

Some of those queries look too heavy.

Have you run the indexes from the RC2a package?

CODE

alter table banners add index idx_banners_group (banners_group);
alter table banners_history add index idx_banners_history_banners_id (banners_id);
alter table currencies add index idx_currencies_code (code);
alter table customers add index idx_customers_email_address (customers_email_address);
alter table customers_basket add index idx_customers_basket_customers_id (customers_id);
alter table customers_basket_attributes add index idx_customers_basket_att_customers_id (customers_id);
alter table orders add index idx_orders_customers_id (customers_id);
alter table orders_products add index idx_orders_products_orders_id (orders_id);
alter table orders_products add index idx_orders_products_products_id (products_id);
alter table orders_status_history add index idx_orders_status_history_orders_id (orders_id);
alter table orders_products_attributes add index idx_orders_products_att_orders_id (orders_id);
alter table orders_products_download add index idx_orders_products_download_orders_id (orders_id);
alter table products add index idx_products_model (products_model);
alter table products_attributes add index idx_products_attributes_products_id (products_id);
alter table reviews add index idx_reviews_products_id (products_id);
alter table reviews add index idx_reviews_customers_id (customers_id);
alter table specials add index idx_specials_products_id (products_id);
alter table zones add index idx_zones_to_geo_zones_country_id (zone_country_id);

Looking at your queries you could also benefit from the index that Monika kindly donated here: -

CODE

ALTER TABLE `products_to_categories` DROP PRIMARY KEY;
ALTER TABLE `products_to_categories` ADD INDEX `idx_p2c_categories_id` ( `categories_id` );
ALTER TABLE `products_to_categories` ADD INDEX `idx_p2c_products_id` ( `products_id` );

[kbking]

I have not yet run the indexes from the RC2a package. I'm still looking at the upgrade document. Would it be OK to run indexes and then after do the alterations to the .php files?

Monikas donation I've already in place (Thanks Monica!), although I didn't run them in the order she said, I run this first:

ALTER TABLE `specials` ADD UNIQUE `idx_s_products_id` ( `products_id` );

But the order doesn't matter?

The ALTER TABLE `specials` ADD UNIQUE `idx_s_products_id` ( `products_id` ); had the greatest impact and I have to say that I failed to notice any increace in performance as a result of the other two from Monika. But most likely it is imagination, I guess.

As I said before, I can't see things going better with the new database the webhost provided me with. One thing I can't figure out, in configure.php I changed the connection strings to the new ones. Before it was mysql13.mysite.se now it is mysql117.mysite.nu, but when I look in Admin->Tools->Server Info it still says mysql13.mysite.se. I'm confused as to what more I need to change. Or the webhost is pulling my legs here?

[kbking]

One more question.
I have noticed that a page can take several seconds to fully load and when finished it says 0,2 seconds as parse time. Is it correct to say that the 0,2 seconds is the time it took to pull the requested data from the database?

If so, it would be OK to have 0,3 or even 0,6 seconds for that matter, what I mean is, that a visitor could hardly tell the difference between 0,3 and 0,6 seconds. The parse times I experienced yesterday are one of a kind, usually they are below 0.5.

Then the real problem is something else and I guess it would be that there are too many sites on the server making it slow during certain times of the day (and night). I find it hard to believe that there should be something fundamentally wrong with my database. After all it is still very close to a vanilla, the very big differences lies in design and layout.

I have googled the webhost regarding complains about parse times and there are not many, there are a few about slow page loading times which, as I interprets it, refers to the fact that it takes long to render the page itself, graphics and such. Just so we are talking about the same things here.

Sorry, a lengthy post again

[Vger]

Your needs are for an eCommerce web host, and the reason you may not find many complaints about your current Web Host is that they may not have that many eCommerce sites on their servers.

You can try removing or disabling the All Products page.

You can install an image thumbnailer which keeps a permanent cache of the thumbnail images.

Set 'Image Required' to false to see if any of your images are causing the pages to hang when loading.

Go through your images and make sure that their file names are all in lower case and without spaces.

If the site still hangs - it's your hosting.

Vger