search

FSX / momoko

Wraps (asynchronous) Psycopg2 for Tornado.
http://momoko.61924.nl/
Other
363 stars 73 forks source link

Why is the database insertion so unstable? #93

Closed kamelzcs closed 9 years ago

kamelzcs commented 9 years ago

Python: 2.7.6 Tornado: 4.0.2 Psycopg2: 2.5.4

Changed the SingleQueryHandler in examples

class SingleQueryHandler(BaseHandler):
    @gen.coroutine
    def get(self):
        try:
            cursor = yield momoko.Op(self.db.execute, 'INSERT INTO "member" ("membername", "birthday") VALUES (%s, %s) RETURNING ID', ('123', '2014/12/17'))
            self.write('Query results: %s<br>\n' % cursor.fetchall())
        except Exception as error:
            self.write(str(error))

        self.finish()
CREATE TABLE member
(
  id serial NOT NULL,
  membername character varying(255) NOT NULL,
  birthday date,
  CONSTRAINT member_pkey PRIMARY KEY (id)
)
WITH (
  OIDS=FALSE
);
ALTER TABLE member
  OWNER TO postgres;

This is a successive click on the /query link. It seems the respond time is very unstable, such simple insert query could lead to at most 2445.17ms delay. 

[I 141225 13:50:04 connection:536] Opening new database connection
[I 141225 13:50:08 web:1811] 200 GET / (127.0.0.1) 1.75ms
[I 141225 13:50:10 web:1811] 200 GET /query (127.0.0.1) 17.89ms
[I 141225 13:50:16 web:1811] 200 GET /query (127.0.0.1) 1467.42ms
[I 141225 13:50:41 web:1811] 200 GET /query (127.0.0.1) 1868.55ms
[I 141225 13:50:46 web:1811] 200 GET /query (127.0.0.1) 32.46ms
[I 141225 13:50:49 web:1811] 200 GET /query (127.0.0.1) 13.38ms
[I 141225 13:50:59 web:1811] 200 GET /query (127.0.0.1) 18.88ms
[I 141225 13:51:09 web:1811] 200 GET /query (127.0.0.1) 2445.17ms
[I 141225 13:51:20 web:1811] 200 GET /query (127.0.0.1) 94.91ms
[I 141225 13:51:28 web:1811] 200 GET /query (127.0.0.1) 1574.37ms
[I 141225 13:51:33 web:1811] 200 GET /query (127.0.0.1) 312.02ms

For sync psycopg2, the code is as follows:

import psycopg2
class SingleQueryHandler(BaseHandler):
    @gen.coroutine
    def get(self):
        try:
            cursor = self.db.cursor()
            cursor.execute('INSERT INTO "member" ("membername", "birthday") VALUES (%s, %s) RETURNING ID', ('123', '2014/12/17'))
            self.write('Query results: %s<br>\n' % cursor.fetchall())
        except Exception as error:
            self.write(str(error))

        self.finish()

The result is as follows:

[I 141225 16:08:08 web:1811] 200 GET / (127.0.0.1) 0.48ms
[I 141225 16:08:11 web:1811] 200 GET /query (127.0.0.1) 2.11ms
[I 141225 16:08:18 web:1811] 200 GET /query (127.0.0.1) 1.11ms
[I 141225 16:08:22 web:1811] 200 GET /query (127.0.0.1) 0.96ms
[I 141225 16:08:27 web:1811] 200 GET /query (127.0.0.1) 1.11ms
[I 141225 16:08:30 web:1811] 200 GET /query (127.0.0.1) 0.80ms
[I 141225 16:08:33 web:1811] 200 GET /query (127.0.0.1) 1.30ms
[I 141225 16:08:37 web:1811] 200 GET /query (127.0.0.1) 1.13ms
[I 141225 16:08:45 web:1811] 200 GET /query (127.0.0.1) 0.81ms
[I 141225 16:08:49 web:1811] 200 GET /query (127.0.0.1) 0.82ms
[I 141225 16:08:50 web:1811] 200 GET /query (127.0.0.1) 0.79ms

The difference is very huge.

After the commit is used, the psycopg2 becomes slow as well

class SingleQueryHandler(BaseHandler):
    @gen.coroutine
    def get(self):
        try:
            cursor = self.db.cursor()
            cursor.execute('INSERT INTO "member" ("membername", "birthday") VALUES (%s, %s) RETURNING ID', ('123', '2014/12/17'))
            self.db.commit()
            self.write('Query results: %s<br>\n' % cursor.fetchall())
        except Exception as error:
            self.write(str(error))

        self.finish()

[I 141225 17:18:52 web:1811] 200 GET /query (127.0.0.1) 19.35ms
[I 141225 17:18:53 web:1811] 200 GET /query (127.0.0.1) 16.96ms
[I 141225 17:18:55 web:1811] 200 GET /query (127.0.0.1) 402.65ms
[I 141225 17:18:58 web:1811] 200 GET /query (127.0.0.1) 2317.28ms
[I 141225 17:19:02 web:1811] 200 GET /query (127.0.0.1) 1396.84ms
[I 141225 17:19:03 web:1811] 200 GET /query (127.0.0.1) 33.61ms
[I 141225 17:19:04 web:1811] 200 GET /query (127.0.0.1) 444.74ms
[I 141225 17:19:05 web:1811] 200 GET /query (127.0.0.1) 15.53ms
[I 141225 17:19:06 web:1811] 200 GET /query (127.0.0.1) 18.40ms
[I 141225 17:19:07 web:1811] 200 GET /query (127.0.0.1) 12.16ms
[I 141225 17:19:11 web:1811] 200 GET /query (127.0.0.1) 3081.28ms
haizaar commented 9 years ago

Could you run another test with plain sync psycopg2 (i.e. without momoko) and compare results?

kamelzcs commented 9 years ago

It is sync psycopg2 not async psycopg2?

haizaar commented 9 years ago

Yes, just create regular psycopg2 connection beforehand and use it to query database in your get request. Don't even import momoko.

kamelzcs commented 9 years ago

There should be something wrong. The difference is really huge.

haizaar commented 9 years ago

Can you post the results?, including your test code?

kamelzcs commented 9 years ago

I updated it in the first post

haizaar commented 9 years ago

Yes, the difference is huge indeed. I'll look at this next week.

haizaar commented 9 years ago

Also can you post python, psycopg2 and momoko versions you are using?

kamelzcs commented 9 years ago

After the commit is used, the psycopg2 becomes slow as well

class SingleQueryHandler(BaseHandler):
    @gen.coroutine
    def get(self):
        try:
            cursor = self.db.cursor()
            cursor.execute('INSERT INTO "member" ("membername", "birthday") VALUES (%s, %s) RETURNING ID', ('123', '2014/12/17'))
            self.db.commit()
            self.write('Query results: %s<br>\n' % cursor.fetchall())
        except Exception as error:
            self.write(str(error))

        self.finish()

[I 141225 17:18:52 web:1811] 200 GET /query (127.0.0.1) 19.35ms
[I 141225 17:18:53 web:1811] 200 GET /query (127.0.0.1) 16.96ms
[I 141225 17:18:55 web:1811] 200 GET /query (127.0.0.1) 402.65ms
[I 141225 17:18:58 web:1811] 200 GET /query (127.0.0.1) 2317.28ms
[I 141225 17:19:02 web:1811] 200 GET /query (127.0.0.1) 1396.84ms
[I 141225 17:19:03 web:1811] 200 GET /query (127.0.0.1) 33.61ms
[I 141225 17:19:04 web:1811] 200 GET /query (127.0.0.1) 444.74ms
[I 141225 17:19:05 web:1811] 200 GET /query (127.0.0.1) 15.53ms
[I 141225 17:19:06 web:1811] 200 GET /query (127.0.0.1) 18.40ms
[I 141225 17:19:07 web:1811] 200 GET /query (127.0.0.1) 12.16ms
[I 141225 17:19:11 web:1811] 200 GET /query (127.0.0.1) 3081.28ms
haizaar commented 9 years ago

Nice catch. I guess then its not momoko specific issue. I suggest posting to psycopg mailing list. It also would be nice if you post link to the mail thread here later.

kamelzcs commented 9 years ago

Psycopg link Tornado link

kamelzcs commented 9 years ago

Actually it is the Pgadmin3 log to blame. After I shut it down, everything works on the fly!

Thanks for your time!