Server slow

[Kenneth Lundström]

Hello list,

need some help finding out why my server is so slow.

The server is with a Intel Celeron 2.66 GHz CPU, 4 GB of memory
CentOS 5.5 64-bit, Apache 2.2.3, MySQL 5.0.77, mod_wsgi, Web2py 1.89.5
The server is dedicated to web2py, there is three instances of web2py
running.

I have migrate=False, sessions on disc.

If I try the following code

def testing():
customers = db(db.customer.id > 0).select()
return customers

takes 39 seconds, 5 times in a row, to return 979 rows.

If I put db.customer < 100 it takes 4,5 seconds to return 87 rows.

Is it just me or are this a bit long times?

Kenneth

[Kenneth Lundström]

Of course I forgot something,

python 2.6.5

Kenneth

[mdipierro]

Please tell us more about the setup. Are the three instances behind
running on the same server? why three? What do they do?

This is not normal but I suspect the problem is with database.

Did you set DAL(...,pool_size=10)?


On Dec 2, 5:13 am, Kenneth Lundström <kenneth.t.lundst...@gmail.com>
wrote:

[Kenneth Lundström]

> Please tell us more about the setup. Are the three instances behind
running on the same server?

Yes.

> why three? What do they do?

One is production, one is testing and last one is development. I had two
instances running on a virtual server before and it worked fine.

> This is not normal but I suspect the problem is with database.
> Did you set DAL(...,pool_size=10)?

No, but I tried but no change.

If I try to select more rows:
def testing():
orders = db(db.orders.id > 0).select()
return orders

It takes 80 seconds to return 1608 rows.

If I change the return to return len(troops) it only takes 1,5 seconds.

I have no view defined, just trying out the database.

Kenneth

>
> On Dec 2, 5:13 am, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

[Michele Comitini]

Kenneth,

When you test is that the only active connection to the db?

2010/12/2 Kenneth Lundström <kenneth.t...@gmail.com>:

>> Please tell us more about the setup. Are the three instances behind
>> running on the same server?
>
> Yes.
>
>> why three? What do they do?
>
> One is production, one is testing and last one is development. I had two
> instances running on a virtual server before and it worked fine.
>
>> This is not normal but I suspect the problem is with database.
>> Did you set DAL(...,pool_size=10)?
>
> No, but I tried but no change.
>
> If I try to select more rows:
> def testing():
>    orders = db(db.orders.id > 0).select()
>    return orders
>
> It takes 80 seconds to return 1608 rows.
>
> If I change the return to return len(troops) it only takes 1,5 seconds.
>
> I have no view defined, just trying out the database.
>
>
> Kenneth
>
>
>>

>> On Dec 2, 5:13 am, Kenneth Lundström<kenneth.t.lundst...@gmail.com>

[Kenneth Lundström]

> When you test is that the only active connection to the db?

I tested it on an application running on the test instance. There could
have been lite activity one production site.
But when I tested loading the same function five times in about 10
minutes I allways 39 seconds to load the data.

Kenneth

[mdipierro]

try

import time, logging

def testing():
t0=time.time()
orders = db(db.orders.id > 0).select()
logging.info('time to fetch %s' % (time.time()-t0))
return orders

so you can isolate the problem and see if it is in fetching or
somewhere else (for example session locking).


On Dec 2, 4:21 pm, Kenneth Lundström <kenneth.t.lundst...@gmail.com>
wrote:

>  > When you test is that the only active connection to the db?
>
> I tested it on an application running on the test instance. There could
> have been lite activity one production site.
> But when I tested loading the same function five times in about 10
> minutes I allways 39 seconds to load the data.
>
> Kenneth
>
>
>

> > 2010/12/2 Kenneth Lundström<kenneth.t.lundst...@gmail.com>:

[Kenneth Lundström]

Were is this logged, I could not find anything in any logs?

Kenneth

> try
>
> import time, logging
>
> def testing():
> t0=time.time()
> orders = db(db.orders.id> 0).select()
> logging.info('time to fetch %s' % (time.time()-t0))
> return orders
>
> so you can isolate the problem and see if it is in fetching or
> somewhere else (for example session locking).
>
>

> On Dec 2, 4:21 pm, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

> wrote:
>> > When you test is that the only active connection to the db?
>>
>> I tested it on an application running on the test instance. There could
>> have been lite activity one production site.
>> But when I tested loading the same function five times in about 10
>> minutes I allways 39 seconds to load the data.
>>
>> Kenneth
>>
>>
>>

>>> 2010/12/2 Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>:

>>>>> Please tell us more about the setup. Are the three instances behind
>>>>> running on the same server?
>>>> Yes.
>>>>> why three? What do they do?
>>>> One is production, one is testing and last one is development. I had two
>>>> instances running on a virtual server before and it worked fine.
>>>>> This is not normal but I suspect the problem is with database.
>>>>> Did you set DAL(...,pool_size=10)?
>>>> No, but I tried but no change.
>>>> If I try to select more rows:
>>>> def testing():
>>>> orders = db(db.orders.id> 0).select()
>>>> return orders
>>>> It takes 80 seconds to return 1608 rows.
>>>> If I change the return to return len(troops) it only takes 1,5 seconds.
>>>> I have no view defined, just trying out the database.
>>>> Kenneth

>>>>> On Dec 2, 5:13 am, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

[Kenneth Lundström]

I finally had time to find out a little about loggin.conf.

In my logs/web2py.log I get this line:
2010-12-25 01:42:30,097 - root - INFO - time to fetch 1.81220602989

So it takes under 2 seconds to fetch the data and the rest 37 to show
it? How come?

Kenneth

[mdipierro]

No idea. How much data.
What db? is it local? Probably something is wrong anyway.

On Dec 24, 5:55 pm, Kenneth Lundström <kenneth.t.lundst...@gmail.com>
wrote:

[Kenneth Lundström]

980 rows, 10 columns of data,
38 sec.

MySQL server is on the same server, Apache server is not local, but the
delay is allways 38-39 seconds.

Kenneth

> No idea. How much data.
> What db? is it local? Probably something is wrong anyway.
>

> On Dec 24, 5:55 pm, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

[mdipierro]

Is this reproducible? If so, instead of timing

t0=time.time()
orders = db(db.orders.id > 0).select()
logging.info('time to fetch %s' % (time.time()-t0))

try time

sql = db(db.orders.id > 0)._select()
t0=time.time()
db.executesql(sql)

logging.info('time to fetch %s' % (time.time()-t0))

orders=[]

I do not think this time is spend in web2py. I think - for some reason
- it is spent communication with mysql.

On Dec 25, 4:25 am, Kenneth Lundström <kenneth.t.lundst...@gmail.com>
wrote:

[Kenneth Lundström]

> Is this reproducible?

This happens all the time, if I do it ten times in a row every time it takes 38-39 seconds. Even with lynx on the server itself it takes about 40 seconds.

If I use:

t0=time.time()
orders = db(db.orders.id> 0).select()
logging.info('time to fetch %s' % (time.time()-t0))

The time is 1.75 - 1.90 seconds to fetch the data from database

I change the controller to this

sql = db(db.orders.id> 0)._select()
t0=time.time()
db.executesql(sql)
logging.info('time to fetch %s' % (time.time()-t0))
orders=[]

now I get times like 0.38 - 0.39 seconds

If I instead of db.orders.id< 490) to get half the rows all times drops to half, even 40 seconds is now 20 seconds.

Just testing I tried with:

t0=time.time()
orders = db(db.orders.id> 0).select()

orders1 = db(db.orders.id> 0).select()
orders2 = db(db.orders.id> 0).select()
orders3 = db(db.orders.id> 0).select()
orders4 = db(db.orders.id> 0).select()

logging.info('time to fetch %s' % (time.time()-t0))
return orders

This takes about, 5x1,8s (to fetch data) + 35 seconds = 45 seconds

I tried with a different table that contains about 1250 rows, 6 columns. It takes 1.2-1.3 seconds to fetch the data, but then over 60 seconds to display it.

Kenneth

[mdipierro]

I have never seen this before. Can I see the model?

massimo

On Dec 25, 3:51 pm, Kenneth Lundström <kenneth.t.lundst...@gmail.com>
wrote:

[Kenneth Lundström]

What part of the model would you like to see?

This?

db.define_table('orders',
db.Field('name', 'string', length=40, requires=IS_NOT_EMPTY()),
db.Field('district', db.district, required=True),
db.Field('edited_by', db[user_table], required=True),
db.Field('edited_date', 'datetime', required=True),
db.Field('reward_selected', 'integer', default=0),
db.Field('members', 'integer', default=0),
db.Field('memb_no', 'string', default=0),
db.Field('locked', 'integer', default=False, required=True),
db.Field('cow_id', 'string', default=''),
migrate=settings.migrate)

So far there was no view defined for this controller. If I define a
empty one it takes like 2-3 seconds to show a empty page, controller
changed to dict(orders=orders).

If I define the view to be {{=orders}} it takes again 40 seconds to show.

The strange thing is if I change the view to
{{
for order in orders:
=XML(order)
pass
}}

it only takes about 2-3 seconds to show all orders. Not as nice as
=orders but very strange anyhow.

Kenneth

> I have never seen this before. Can I see the model?
>
> massimo
>

> On Dec 25, 3:51 pm, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

[mdipierro]

Now I understand.

The problem is here:

Field('edited_by', db[user_table], required=True),

When you do {{=orders}} is uses a default representation for
edited_by. The field contains a user id and the default representation
is the user name. So for each record it has to do a database lookup
(980 of them).

If you want to represent users by name, you should either cache them.
Something like this:

db.orders.edited_by.represent = lambda id: cache.ram('user:
%i'%id,lambda:db.auth_user(id).first_name,3600)

or turn your query into a join.

Massimo

On Dec 26, 11:37 pm, Kenneth Lundström <kenneth.t.lundst...@gmail.com>
wrote:

> > On Dec 25, 3:51 pm, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

[Kenneth Lundström]

So it rather fast not slow :=)

But the edited_by column is not showing a name, it shows a number.

But that is not very intresting as I don�t need a list like that, it was
just a test. I�m trying to optimize some reporting functions. I�ll have
to start from an other angle.

Kenneth

> Now I understand.
>
> The problem is here:
>
> Field('edited_by', db[user_table], required=True),
>
> When you do {{=orders}} is uses a default representation for
> edited_by. The field contains a user id and the default representation
> is the user name. So for each record it has to do a database lookup
> (980 of them).
>
> If you want to represent users by name, you should either cache them.
> Something like this:
>
> db.orders.edited_by.represent = lambda id: cache.ram('user:
> %i'%id,lambda:db.auth_user(id).first_name,3600)
>
> or turn your query into a join.
>
> Massimo
>

> On Dec 26, 11:37 pm, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

>>> On Dec 25, 3:51 pm, Kenneth Lundstr�m<kenneth.t.lundst...@gmail.com>

[Kenneth]

Getting back to this discussion.

I have a table containing 31.000 record. Model below.

db.define_table('tracker_person_product',
db.Field('troop', db.troop, required=True),
db.Field('troop_person', db.troop_person, required=True),
db.Field('campaign', db.campaign, required=True),
db.Field('product', db.product, required=True),
db.Field('count_received', 'integer', required=True,
requires=IS_INT_IN_RANGE(0, 1000000)),
db.Field('count_sold', 'integer', required=True,
requires=IS_INT_IN_RANGE(0, 1000000)),
db.Field('count_returned', 'integer', required=True,
requires=IS_INT_IN_RANGE(0, 1000000)),
db.Field('count_paid', 'integer', required=True,
requires=IS_INT_IN_RANGE(0, 1000000)),
db.Field('edited_by', db.auth_user,default=auth.user_id,

required=True),
db.Field('edited_date', 'datetime', required=True),

format='%(count_received)s',
migrate=settings.migrate)

Queryn all records (record=db(db.tracker_person_product).select())
takes 47 seconds. Just executing one row of python code. Not even
showing all records.

Is there something I can do to reduce query time? 31.000 records just
doesn't sound like that much yet.

Kenneth

---------- Forwarded message ----------
From: Kenneth Lundström <kenneth.t.lundst...@gmail.com>
Date: Dec 27 2010, 9:14 am
Subject: Server slow
To: web2py-users

So it rather fast notslow:=)

Kenneth

> Now I understand.

> The problem is here:

> Massimo

>> This?

>> }}

>> Kenneth

>>>> This happens all the time, if I do it ten times in a row every time it takes 38-39 seconds. Even with lynx on theserveritself it takes about 40 seconds.

[Kenneth Lundström]

Sorry, meant this discussion:
http://groups.google.com/group/web2py/browse_thread/thread/c6bc090c04b323ed/b2e8ec8a2d5d0786?lnk=gst&q=server+slow#b2e8ec8a2d5d0786

Database: MySQL, server Apache 2.2.3 on CentOS and web2py version 1.98.1

Kenneth

[pbreit]

Can you run the query directly against the db to compare? Do you have the debug tool displaying at the bottom of the page that shows how long he query took?

[Kenneth Lundström]

> Can you run the query directly against the db to compare? Do you have
the debug tool displaying at the bottom of the page that shows how long
he query took?

t3=time.time()
testar = db(db.tracker_person_product.id).select()

t4=time.time()

logging.info('query time: %s' % (t4-t3))

--> query time: 47,7 seconds

If I run this:
sql = db(db.tracker_person_product.id > 0)._select()

t0=time.time()
db.executesql(sql)
logging.info('time to fetch %s' % (time.time()-t0))

time to fetch: 16.8 seconds

Kenneth

[Anthony]

On Tuesday, August 2, 2011 8:44:52 AM UTC-4, Kenneth wrote:

> Can you run the query directly against the db to compare? Do you have
the debug tool displaying at the bottom of the page that shows how long
he query took?

         t3=time.time()
         testar = db(db.tracker_person_product.id).select()

What happens if you do:

 

testar = db(db.tracker_person_product.id > 0).select()     # Note, added '> 0'

 

[David Marko]

In the first example, web2py converts SQL query results into DAL row objects which takes time for 31K records. Using executesql is always faster ...

[Anthony]

On Tuesday, August 2, 2011 8:54:57 AM UTC-4, David Marko wrote:

In the first example, web2py converts SQL query results into DAL row objects which takes time for 31K records. Using executesql is always faster ...

 

Good point -- executesql isn't returning the same object: http://web2py.com/book/default/chapter/06#executesql

 

Anthony

[Richard Vézina]

To me it seems that it comes from : psycopg2._psycopg

I use Postgres 8.4 under ubuntu 11.04, python 2.6.5, web2py 1.97.1, with the dev http server...

In [3]: import cProfile

In [4]: import pstats

In [5]: cProfile.run('SQLTABLE(db().select(db.test_ph.ALL))')

         650629 function calls (580822 primitive calls) in 14.921 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)

        1    0.000    0.000   14.921   14.921 <string>:1(<module>)

      421    0.004    0.000    0.004    0.000 copy.py:112(_copy_with_constructor)

      421    0.009    0.000    0.016    0.000 copy.py:65(copy)

      677    0.222    0.000    1.243    0.002 dal.py:1046(_select)

      677    0.012    0.000    0.012    0.000 dal.py:1155(select_limitby)

      677    0.044    0.000   13.706    0.020 dal.py:1161(select)

      677    0.017    0.000    4.745    0.007 dal.py:1165(response)

 2136/784    0.078    0.000    0.161    0.000 dal.py:1202(tables)

      677    0.056    0.000    4.687    0.007 dal.py:1243(log_execute)

      677    0.012    0.000    4.699    0.007 dal.py:1250(execute)

      676    0.039    0.000    0.068    0.000 dal.py:1253(represent)

      676    0.004    0.000    0.004    0.000 dal.py:1320(represent_exceptions)

      677    0.007    0.000    0.007    0.000 dal.py:1329(rowslice)

      677    2.285    0.003    7.652    0.011 dal.py:1333(parse)

      677    0.019    0.000    0.045    0.000 dal.py:1458(filter_tenant)

       85    0.007    0.000    0.434    0.005 dal.py:3603(ff)

       85    0.007    0.000    0.723    0.009 dal.py:3649(list_ref_repr)

      170    0.004    0.000    0.455    0.003 dal.py:3653(<genexpr>)

       85    0.008    0.000    0.010    0.000 dal.py:3683(bar_decode_integer)

     9310    0.153    0.000    0.214    0.000 dal.py:3697(__getitem__)

    27725    0.264    0.000    0.264    0.000 dal.py:3706(__setitem__)

       85    0.001    0.000    0.003    0.000 dal.py:3709(__getattr__)

     1522    0.022    0.000    0.035    0.000 dal.py:3712(__setattr__)

    93512    0.803    0.000    0.803    0.000 dal.py:4248(__getitem__)

      677    0.006    0.000    0.006    0.000 dal.py:4251(__setitem__)

    25694    0.389    0.000    0.601    0.000 dal.py:4254(__getattr__)

      677    0.011    0.000    0.017    0.000 dal.py:4257(__setattr__)

      677    0.024    0.000    0.039    0.000 dal.py:4266(__call__)

     1522    0.023    0.000    0.033    0.000 dal.py:4381(__setattr__)

73242/6480    1.729    0.000   12.928    0.002 dal.py:4579(__getitem__)

       85    0.008    0.000    0.406    0.005 dal.py:4594(__call__)

     4989    0.072    0.000    0.255    0.000 dal.py:4647(__getattr__)

     4492    0.066    0.000    0.239    0.000 dal.py:4655(__iter__)

    19439    0.495    0.000    1.167    0.000 dal.py:4950(__eq__)

      676    0.018    0.000    0.039    0.000 dal.py:4953(__ne__)

       85    0.003    0.000    0.005    0.000 dal.py:4971(belongs)

      425    0.024    0.000    0.060    0.000 dal.py:5247(formatter)

     1870    0.013    0.000    0.013    0.000 dal.py:5277(__nonzero__)

     4661    0.039    0.000    0.039    0.000 dal.py:5280(__str__)

    20200    0.226    0.000    0.226    0.000 dal.py:5301(__init__)

    19525    0.155    0.000    0.155    0.000 dal.py:5357(__init__)

      677    0.025    0.000   13.746    0.020 dal.py:5393(select)

      677    0.006    0.000    0.006    0.000 dal.py:5474(__init__)

       86    0.001    0.000    0.002    0.000 dal.py:5518(__nonzero__)

       86    0.001    0.000    0.002    0.000 dal.py:5523(__len__)

      761    0.033    0.000    0.066    0.000 dal.py:5529(__getitem__)

      256    0.005    0.000    0.022    0.000 dal.py:5536(__iter__)

      591    0.010    0.000    0.063    0.000 dal.py:5553(first)

       85    0.003    0.000    0.023    0.000 dal.py:861(BELONGS)

      170    0.002    0.000    0.014    0.000 dal.py:865(<genexpr>)

      591    0.013    0.000    0.120    0.000 dal.py:883(EQ)

6013/4661    0.149    0.000    0.326    0.000 dal.py:932(expand)

       85    0.007    0.000    0.013    0.000 decimal.py:512(__new__)

       86    0.001    0.000    0.080    0.001 html.py:1403(_fixup)

        1    0.000    0.000    0.000    0.000 html.py:1410(_fixup)

        1    0.000    0.000    0.003    0.003 html.py:1418(_fixup)

        1    0.000    0.000    0.000    0.000 html.py:1452(_fixup)

     1981    0.110    0.000    0.326    0.000 html.py:551(__init__)

     1892    0.013    0.000    0.013    0.000 html.py:670(_fixup)

       89    0.043    0.000    0.082    0.001 html.py:679(_wrap_components)

     1981    0.012    0.000    0.012    0.000 html.py:705(_postprocessing)

     3870    0.053    0.000    0.080    0.000 html.py:750(_setnode)

        1    0.182    0.182   14.267   14.267 sqlhtml.py:1305(__init__)

       85    0.004    0.000    4.493    0.053 test.py:1126(<lambda>)

       85    0.003    0.000    1.016    0.012 test.py:1128(<lambda>)

       85    0.003    0.000    1.827    0.021 test.py:1131(<lambda>)

       85    0.003    0.000    1.863    0.022 test.py:1133(<lambda>)

       85    0.003    0.000    1.721    0.020 test.py:1135(<lambda>)

       85    0.003    0.000    1.822    0.021 test.py:1137(<lambda>)

      170    0.003    0.000    0.003    0.000 tz.py:37(__init__)

     3058    0.044    0.000    0.073    0.000 utf_8.py:15(decode)

      506    0.003    0.000    0.003    0.000 validators.py:106(formatter)

     3058    0.029    0.000    0.029    0.000 {_codecs.utf_8_decode}

       85    0.001    0.000    0.001    0.000 {built-in method __new__ of type object at 0x82e5e0}

      340    0.002    0.000    0.002    0.000 {built-in method group}

     7788    0.083    0.000    0.083    0.000 {built-in method match}

     1182    0.016    0.000    0.052    0.000 {hasattr}

   130035    0.925    0.000    0.925    0.000 {isinstance}

4187/4101    0.029    0.000    0.030    0.000 {len}

      677    0.035    0.000    0.188    0.000 {map}

      783    0.005    0.000    0.005    0.000 {method 'add' of 'set' objects}

    10120    0.066    0.000    0.066    0.000 {method 'append' of 'list' objects}

     2956    0.046    0.000    0.117    0.000 {method 'decode' of 'str' objects}

        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

     3052    0.027    0.000    0.027    0.000 {method 'encode' of 'unicode' objects}

      677    4.572    0.007    4.572    0.007 {method 'execute' of 'psycopg2._psycopg.cursor' objects}

      677    0.013    0.000    0.029    0.000 {method 'fetchall' of 'psycopg2._psycopg.cursor' objects}

    15868    0.107    0.000    0.107    0.000 {method 'get' of 'dict' objects}

    73327    0.481    0.000    0.481    0.000 {method 'isdigit' of 'str' objects}

       85    0.001    0.000    0.001    0.000 {method 'items' of 'dict' objects}

2115/1860    0.019    0.000    0.486    0.000 {method 'join' of 'str' objects}

     2199    0.016    0.000    0.016    0.000 {method 'keys' of 'dict' objects}

        1    0.000    0.000    0.000    0.000 {method 'lower' of 'str' objects}

      421    0.007    0.000    0.007    0.000 {method 'reverse' of 'list' objects}

     8550    0.064    0.000    0.064    0.000 {method 'split' of 'str' objects}

    28489    0.197    0.000    0.197    0.000 {method 'startswith' of 'str' objects}

     5086    0.032    0.000    0.032    0.000 {method 'strip' of 'str' objects}

     1352    0.010    0.000    0.010    0.000 {method 'union' of 'set' objects}

     1354    0.018    0.000    0.018    0.000 {time.time}

What do you think?

Richard

[Kenneth Lundström]

No difference.

The model for this table contains four reference to other table, can this affect the speed?


Kenneth