automat_svet-ZKwmMI9HCDA@public.gmane.org
2005-Sep-15 01:20 UTC
poor performance - need advice
I''m moving a web site on production and after a few days of tuning
still my site is so slow...
ok maybe I need to change something in the code to increase speed and
still cache is not active.. but why my site in production and with
fcgi is way slower than my development machine (an old powerbook)?
this is my site on dreamhost shared:
home page:
Completed in 0.90276 (1 reqs/sec) | Rendering: 0.29059 (32%) | DB:
0.59966 (66%) [http://www.rialtosantambrogio.org/calendario]
a second page:
Completed in 0.72307 (1 reqs/sec) | Rendering: 0.26568 (36%) | DB:
0.45221 (62%) [http://www.rialtosantambrogio.org/evento/29]
and this is my powerbook:
home page:
Completed in 0.44669 (2 reqs/sec) | Rendering: 0.39703 (88%) | DB:
0.02935 (6%) [http://localhost/calendario]
second page:
Completed in 0.14423 (6 reqs/sec) | Rendering: 0.06235 (43%) | DB:
0.06047 (41%) [http://localhost/evento/29]
db response on dreamhost seems really slow and 1req/sec is so scary...
Any thoughts would be greatly appreciated.
Thanks
Ettore
..this is my development.log
home page:
Processing CalendarioController#index (for 127.0.0.1 at Thu Sep 15
03:00:32 CEST 2005)
Parameters: {"action"=>"index",
"controller"=>"calendario"}
[4;33mArticle Load (0.015544) [1;37mSELECT * FROM articles
WHERE data_inizio >= now() ORDER BY data_inizio asc
Rendering within layouts/calendario
Rendering calendario/index (200 OK)
[4;35mArticle Columns (0.003769) [0;37mSHOW FIELDS FROM
articles
[4;33mCollaboration Load (0.006126) [1;37mSELECT * FROM
collaborations ORDER BY position LIMIT 4
[4;35mCollaboration Columns (0.007681) [0;37mSHOW FIELDS
FROM collaborations
Completed in 0.44669 (2 reqs/sec) | Rendering: 0.39703 (88%) | DB:
0.02935 (6%) [http://localhost/calendario]
second page:
Processing CalendarioController#evento (for 127.0.0.1 at Thu Sep 15
02:58:25 CEST 2005)
Parameters: {"action"=>"evento",
"id"=>"29",
"controller"=>"calendario"}
[4;33mArticle Load (0.006832) [1;37mSELECT * FROM articles
WHERE articles.id = ''29'' LIMIT 1
[4;35mArticle Columns (0.019223) [0;37mSHOW FIELDS FROM
articles
[4;33mTag Load (0.002817) [1;37mSELECT t.*, j.* FROM
tags_articles j, tags t WHERE t.id = j.tag_id AND j.article_id = 29
[4;35mTag Columns (0.002892) [0;37mSHOW FIELDS FROM tags
Rendering within layouts/calendario
Rendering calendario/mostra (200 OK)
[4;33mCollaboration Load (0.024587) [1;37mSELECT * FROM
collaborations ORDER BY position LIMIT 4
[4;35mCollaboration Columns (0.004118) [0;37mSHOW FIELDS
FROM collaborations
Completed in 0.14423 (6 reqs/sec) | Rendering: 0.06235 (43%) | DB:
0.06047 (41%) [http://localhost/evento/29]
On 15.9.2005, at 4.20, automat_svet-ZKwmMI9HCDA@public.gmane.org wrote:> > > Any thoughts would be greatly appreciated.Can you get to your logs on Dreamspace? It would be of immense help to see which queries are taking the time. //jarkko> > Thanks > > Ettore > > > ..this is my development.log > > home page: > > Processing CalendarioController#index (for 127.0.0.1 at Thu Sep 15 > 03:00:32 CEST 2005) > Parameters: {"action"=>"index", "controller"=>"calendario"} > [4;33mArticle Load (0.015544) [1;37mSELECT * FROM articles > WHERE data_inizio >= now() ORDER BY data_inizio asc > Rendering within layouts/calendario > Rendering calendario/index (200 OK) > [4;35mArticle Columns (0.003769) [0;37mSHOW FIELDS FROM > articles > [4;33mCollaboration Load (0.006126) [1;37mSELECT * FROM > collaborations ORDER BY position LIMIT 4 > [4;35mCollaboration Columns (0.007681) [0;37mSHOW FIELDS > FROM collaborations > Completed in 0.44669 (2 reqs/sec) | Rendering: 0.39703 (88%) | DB: > 0.02935 (6%) [http://localhost/calendario] > > second page: > > Processing CalendarioController#evento (for 127.0.0.1 at Thu Sep 15 > 02:58:25 CEST 2005) > Parameters: {"action"=>"evento", "id"=>"29", > "controller"=>"calendario"} > [4;33mArticle Load (0.006832) [1;37mSELECT * FROM articles > WHERE articles.id = ''29'' LIMIT 1 > [4;35mArticle Columns (0.019223) [0;37mSHOW FIELDS FROM > articles > [4;33mTag Load (0.002817) [1;37mSELECT t.*, j.* FROM > tags_articles j, tags t WHERE t.id = j.tag_id AND j.article_id = > 29 > [4;35mTag Columns (0.002892) [0;37mSHOW FIELDS FROM tags > Rendering within layouts/calendario > Rendering calendario/mostra (200 OK) > [4;33mCollaboration Load (0.024587) [1;37mSELECT * FROM > collaborations ORDER BY position LIMIT 4 > [4;35mCollaboration Columns (0.004118) [0;37mSHOW FIELDS > FROM collaborations > Completed in 0.14423 (6 reqs/sec) | Rendering: 0.06235 (43%) | DB: > 0.06047 (41%) [http://localhost/evento/29] > > _______________________________________________ > Rails mailing list > Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org > http://lists.rubyonrails.org/mailman/listinfo/rails > >_______________________________________________ Rails mailing list Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org http://lists.rubyonrails.org/mailman/listinfo/rails
automat_svet-ZKwmMI9HCDA@public.gmane.org
2005-Sep-15 14:22 UTC
Re: poor performance - need advice
Jarkko,
thanks for replying, i''ve set up my production log to debug just to
check my queries..
this is my index page:
Processing CalendarioController#index (for 213.155.200.27 at Thu Sep
15 07:04:12 PDT 2005)
Parameters: {"action"=>"index",
"controller"=>"calendario"}
Article Load (0.006220) SELECT * FROM articles WHERE data_inizio
>= now() ORDER BY data_inizio asc
Rendering within layouts/calendario
Rendering calendario/index (200 OK)
Collaboration Load (0.011495) SELECT * FROM collaborations ORDER
BY position LIMIT 4
Completed in 0.48530 (2 reqs/sec) | Rendering: 0.46444 (95%) | DB:
0.01771 (3%) [http://www.rialtosantambrogio.org/calendario]
and this is a second page:
Processing CalendarioController#evento (for 213.155.200.27 at Thu Sep
15 07:16:41 PDT 2005)
Parameters: {"action"=>"evento",
"id"=>"29",
"controller"=>"calendario"}
Article Load (0.005076) SELECT * FROM articles WHERE articles.id
= ''29'' LIMIT 1
Tag Load (0.003298) SELECT t.*, j.* FROM tags_articles j, tags t
WHERE t.id = j.tag_id AND j.article_id = 29
Rendering within layouts/calendario
Rendering calendario/mostra (200 OK)
Collaboration Load (0.009098) SELECT * FROM collaborations ORDER
BY position LIMIT 4
Completed in 0.29913 (3 reqs/sec) | Rendering: 0.27787 (92%) | DB:
0.01747 (5%) [http://www.rialtosantambrogio.org/evento/29]
So, you can see my db time access time is is decreased from the past
days (yesterday i got Completed in 0.90276 (1 reqs/sec) | Rendering:
0.29059 (32%) | DB: 0.59966 (66%)) and infact today my site is
sensibly faster..
Maybe it''s something with Dreamhost, I don''t think
i''m asking too
much to the db, my home page shows 10 records, plus something from
the sidebar.. of a total of less than 50 records... so...
But still I don''t understand the average 2/5 req per sec, should not
much more?
thanks for help
Ettore
Il giorno 15/set/05, alle ore 09:32, Jarkko Laine ha scritto:
>
> On 15.9.2005, at 4.20, automat_svet-ZKwmMI9HCDA@public.gmane.org wrote:
>
>>
>>
>> Any thoughts would be greatly appreciated.
>>
>
> Can you get to your logs on Dreamspace? It would be of immense help
> to see which queries are taking the time.
>
> //jarkko
>
>
>>
>> Thanks
>>
>> Ettore
>>
>>
>> ..this is my development.log
>>
>> home page:
>>
>> Processing CalendarioController#index (for 127.0.0.1 at Thu Sep 15
>> 03:00:32 CEST 2005)
>> Parameters: {"action"=>"index",
"controller"=>"calendario"}
>> [4;33mArticle Load (0.015544) [1;37mSELECT * FROM
>> articles WHERE data_inizio >= now() ORDER BY data_inizio asc
>> Rendering within layouts/calendario
>> Rendering calendario/index (200 OK)
>> [4;35mArticle Columns (0.003769) [0;37mSHOW FIELDS FROM
>> articles
>> [4;33mCollaboration Load (0.006126) [1;37mSELECT * FROM
>> collaborations ORDER BY position LIMIT 4
>> [4;35mCollaboration Columns (0.007681) [0;37mSHOW FIELDS
>> FROM collaborations
>> Completed in 0.44669 (2 reqs/sec) | Rendering: 0.39703 (88%) | DB:
>> 0.02935 (6%) [http://localhost/calendario]
>>
>> second page:
>>
>> Processing CalendarioController#evento (for 127.0.0.1 at Thu Sep
>> 15 02:58:25 CEST 2005)
>> Parameters: {"action"=>"evento",
"id"=>"29",
>> "controller"=>"calendario"}
>> [4;33mArticle Load (0.006832) [1;37mSELECT * FROM
>> articles WHERE articles.id = ''29'' LIMIT 1
>> [4;35mArticle Columns (0.019223) [0;37mSHOW FIELDS FROM
>> articles
>> [4;33mTag Load (0.002817) [1;37mSELECT t.*, j.* FROM
>> tags_articles j, tags t WHERE t.id = j.tag_id AND j.article_id =
>> 29
>> [4;35mTag Columns (0.002892) [0;37mSHOW FIELDS FROM tags
>> Rendering within layouts/calendario
>> Rendering calendario/mostra (200 OK)
>> [4;33mCollaboration Load (0.024587) [1;37mSELECT * FROM
>> collaborations ORDER BY position LIMIT 4
>> [4;35mCollaboration Columns (0.004118) [0;37mSHOW FIELDS
>> FROM collaborations
>> Completed in 0.14423 (6 reqs/sec) | Rendering: 0.06235 (43%) | DB:
>> 0.06047 (41%) [http://localhost/evento/29]
>>
>> _______________________________________________
>> Rails mailing list
>> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
>> http://lists.rubyonrails.org/mailman/listinfo/rails
>>
>>
>>
>
> _______________________________________________
> Rails mailing list
> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
> http://lists.rubyonrails.org/mailman/listinfo/rails
>
On 15.9.2005, at 17.22, automat_svet-ZKwmMI9HCDA@public.gmane.org wrote:> Jarkko, > thanks for replying, i''ve set up my production log to debug just to > check my queries.. > this is my index page: > > Processing CalendarioController#index (for 213.155.200.27 at Thu > Sep 15 07:04:12 PDT 2005) > Parameters: {"action"=>"index", "controller"=>"calendario"} > Article Load (0.006220) SELECT * FROM articles WHERE > data_inizio >= now() ORDER BY data_inizio asc > Rendering within layouts/calendario > Rendering calendario/index (200 OK) > Collaboration Load (0.011495) SELECT * FROM collaborations > ORDER BY position LIMIT 4 > Completed in 0.48530 (2 reqs/sec) | Rendering: 0.46444 (95%) | DB: > 0.01771 (3%) [http://www.rialtosantambrogio.org/calendario] > > and this is a second page: > > Processing CalendarioController#evento (for 213.155.200.27 at Thu > Sep 15 07:16:41 PDT 2005) > Parameters: {"action"=>"evento", "id"=>"29", > "controller"=>"calendario"} > Article Load (0.005076) SELECT * FROM articles WHERE > articles.id = ''29'' LIMIT 1 > Tag Load (0.003298) SELECT t.*, j.* FROM tags_articles j, tags > t WHERE t.id = j.tag_id AND j.article_id = 29 > Rendering within layouts/calendario > Rendering calendario/mostra (200 OK) > Collaboration Load (0.009098) SELECT * FROM collaborations > ORDER BY position LIMIT 4 > Completed in 0.29913 (3 reqs/sec) | Rendering: 0.27787 (92%) | DB: > 0.01747 (5%) [http://www.rialtosantambrogio.org/evento/29] > > > So, you can see my db time access time is is decreased from the > past days (yesterday i got Completed in 0.90276 (1 reqs/sec) | > Rendering: 0.29059 (32%) | DB: 0.59966 (66%)) and infact today my > site is sensibly faster.. > > Maybe it''s something with Dreamhost, I don''t think i''m asking too > much to the db, my home page shows 10 records, plus something from > the sidebar.. of a total of less than 50 records... so... > > But still I don''t understand the average 2/5 req per sec, should > not much more?OK, so db is not the problem. Now you have to take a look at what''s taking the time. When you talk about production log, are you really talking about production.log, i.e. are you sure you''re running in production mode? If yes, I don''t know any other way than try some benchmarking/ profiling [2] to find out what is taking the time. Perhaps you do something very expensive when creating the calendar. You might also want to take a look at caching [2]. //jarkko [1] http://wiki.rubyonrails.com/rails/show/BenchmarkingRails [2] http://rails.rubyonrails.com/classes/ActionController/Caching.html> > thanks for help > > Ettore > > > Il giorno 15/set/05, alle ore 09:32, Jarkko Laine ha scritto: > > >> >> On 15.9.2005, at 4.20, automat_svet-ZKwmMI9HCDA@public.gmane.org wrote: >> >> >>> >>> >>> Any thoughts would be greatly appreciated. >>> >>> >> >> Can you get to your logs on Dreamspace? It would be of immense >> help to see which queries are taking the time. >> >> //jarkko >> >> >> >>> >>> Thanks >>> >>> Ettore >>> >>> >>> ..this is my development.log >>> >>> home page: >>> >>> Processing CalendarioController#index (for 127.0.0.1 at Thu Sep >>> 15 03:00:32 CEST 2005) >>> Parameters: {"action"=>"index", "controller"=>"calendario"} >>> [4;33mArticle Load (0.015544) [1;37mSELECT * FROM >>> articles WHERE data_inizio >= now() ORDER BY data_inizio asc >>> Rendering within layouts/calendario >>> Rendering calendario/index (200 OK) >>> [4;35mArticle Columns (0.003769) [0;37mSHOW FIELDS FROM >>> articles >>> [4;33mCollaboration Load (0.006126) [1;37mSELECT * FROM >>> collaborations ORDER BY position LIMIT 4 >>> [4;35mCollaboration Columns (0.007681) [0;37mSHOW FIELDS >>> FROM collaborations >>> Completed in 0.44669 (2 reqs/sec) | Rendering: 0.39703 (88%) | >>> DB: 0.02935 (6%) [http://localhost/calendario] >>> >>> second page: >>> >>> Processing CalendarioController#evento (for 127.0.0.1 at Thu Sep >>> 15 02:58:25 CEST 2005) >>> Parameters: {"action"=>"evento", "id"=>"29", >>> "controller"=>"calendario"} >>> [4;33mArticle Load (0.006832) [1;37mSELECT * FROM >>> articles WHERE articles.id = ''29'' LIMIT 1 >>> [4;35mArticle Columns (0.019223) [0;37mSHOW FIELDS FROM >>> articles >>> [4;33mTag Load (0.002817) [1;37mSELECT t.*, j.* FROM >>> tags_articles j, tags t WHERE t.id = j.tag_id AND j.article_id = >>> 29 >>> [4;35mTag Columns (0.002892) [0;37mSHOW FIELDS FROM tags >>> Rendering within layouts/calendario >>> Rendering calendario/mostra (200 OK) >>> [4;33mCollaboration Load (0.024587) [1;37mSELECT * FROM >>> collaborations ORDER BY position LIMIT 4 >>> [4;35mCollaboration Columns (0.004118) [0;37mSHOW FIELDS >>> FROM collaborations >>> Completed in 0.14423 (6 reqs/sec) | Rendering: 0.06235 (43%) | >>> DB: 0.06047 (41%) [http://localhost/evento/29] >>> >>> _______________________________________________ >>> Rails mailing list >>> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org >>> http://lists.rubyonrails.org/mailman/listinfo/rails >>> >>> >>> >>> >> >> _______________________________________________ >> Rails mailing list >> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org >> http://lists.rubyonrails.org/mailman/listinfo/rails >> >> > > _______________________________________________ > Rails mailing list > Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org > http://lists.rubyonrails.org/mailman/listinfo/rails > >_______________________________________________ Rails mailing list Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org http://lists.rubyonrails.org/mailman/listinfo/rails