Why is the database insertion so unstable?
Closed this issue · 12 comments
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
Could you run another test with plain sync psycopg2 (i.e. without momoko) and compare results?
It is sync psycopg2 not async psycopg2?
Yes, just create regular psycopg2 connection beforehand and use it to query database in your get request. Don't even import momoko.
There should be something wrong.
The difference is really huge.
Can you post the results?, including your test code?
I updated it in the first post
Yes, the difference is huge indeed. I'll look at this next week.
Also can you post python, psycopg2 and momoko versions you are using?
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
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.
Actually it is the Pgadmin3 log to blame. After I shut it down, everything works on the fly!
Thanks for your time!