[SQL-CVS] [ sqlobject-Support Requests-3366899 ] The speed of SQLObject is slower on the time
SQLObject is a Python ORM.
Brought to you by:
ianbicking,
phd
From: SourceForge.net <no...@so...> - 2011-07-15 17:14:44
|
Support Requests item #3366899, was opened at 2011-07-14 11:40 Message generated for change (Comment added) made by phd You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=540673&aid=3366899&group_id=74338 Please note that this message will contain a full copy of the comment thread, including the initial issue submission, for this request, not just the latest update. Category: None Group: None Status: Open Priority: 5 Private: No Submitted By: Rosa Robles (marobles) Assigned to: Oleg Broytman (phd) Summary: The speed of SQLObject is slower on the time Initial Comment: I had a test of a SQLObject and I had found a strange behaviour of SQLObject. On the time, the respond time is lesser. Here, I put a example of test code : from sqlobject.sqlbuilder import * connection = connectionForURI('postgresql://test:test@localhost/test_sql_object') sqlhub.processConnection = connection class Person(SQLObject): firstName = StringCol() middleInitial = StringCol(length=1, default=None) lastName = StringCol() iteration = 0 while 1: start = datetime.now() person_list = [] for key in range(1000): person = Person.selectBy(firstName='name%s%s' % (iteration,key))[0] person_list.append(person) for person in person_list: person.expire() del person del person_list sqlhub.processConnection.cache.clear() end = datetime.now() print "TIME ",iteration,':' , end - start iteration = iteration + 1 In the result I can check that in each iteration the time is bigger. The first iteration has time of 1.37s, then the time increases and the 19 iteration has time of 5.83 s! TIME 0 : 0:00:01.376392 TIME 1 : 0:00:01.663250 TIME 2 : 0:00:01.978639 TIME 3 : 0:00:02.319939 TIME 4 : 0:00:02.618213 TIME 5 : 0:00:02.723846 TIME 6 : 0:00:02.584007 TIME 7 : 0:00:02.868877 TIME 8 : 0:00:03.051937 TIME 9 : 0:00:03.389757 TIME 10 : 0:00:03.503036 TIME 11 : 0:00:03.563154 TIME 12 : 0:00:04.191539 TIME 13 : 0:00:04.274464 TIME 14 : 0:00:04.813206 TIME 15 : 0:00:04.677002 TIME 16 : 0:00:04.995708 TIME 17 : 0:00:05.126811 TIME 18 : 0:00:05.571279 TIME 19 : 0:00:05.832840 Why is happend this? Thanks in advance for your attention. Cheers Rosa ---------------------------------------------------------------------- >Comment By: Oleg Broytman (phd) Date: 2011-07-15 21:14 Message: Min/max/avg times are almost zero, so it seems the only place the program spends time is calling .expireAll() and cache.clear(), right? ---------------------------------------------------------------------- Comment By: Rosa Robles (marobles) Date: 2011-07-15 10:52 Message: Thanks Oleg. I'm using SQLObject 1.1.1, Python2.6, Postgres 8.4 Ok, I change the code to takes more times. for iteration in range(20): start = datetime.now() acum = timedelta(microseconds=0) times = [] for key in range(1000): time_start = datetime.now() person = Person.selectBy(firstName='name%s%s' % (iteration,key))[0] time_end = datetime.now() times.append(time_end-time_start) acum = acum + (time_end-time_start) end = datetime.now() print "ITERATION ",iteration,"time",end-start print " First Key ->", times[0] print " Last Key ->",times[999] print " Key ->",times.index(max(times)), " Max Time ->", max(times) print " Key ->",times.index(min(times)), " Min Time ->", min(times) print " avg ->",acum/999 Person.sqlmeta.expireAll() for k in connection.cache.caches.keys(): connection.cache.caches[k].expireAll() sqlhub.getConnection().expireAll() connection.cache.clear() gc.collect() And the result is: ITERATION 0 time 0:00:01.302290 First Key -> 0:00:00.001555 Last Key -> 0:00:00.001445 Key -> 11 Max Time -> 0:00:00.003216 Key -> 36 Min Time -> 0:00:00.001115 avg -> 0:00:00.001287 ITERATION 1 time 0:00:01.621580 First Key -> 0:00:00.001879 Last Key -> 0:00:00.001734 Key -> 924 Max Time -> 0:00:00.009572 Key -> 22 Min Time -> 0:00:00.001076 avg -> 0:00:00.001606 ITERATION 2 time 0:00:01.851719 First Key -> 0:00:00.002328 Last Key -> 0:00:00.002064 Key -> 970 Max Time -> 0:00:00.002544 Key -> 22 Min Time -> 0:00:00.001306 avg -> 0:00:00.001836 ITERATION 3 time 0:00:02.040802 First Key -> 0:00:00.002435 Last Key -> 0:00:00.002376 Key -> 557 Max Time -> 0:00:00.009674 Key -> 25 Min Time -> 0:00:00.001538 avg -> 0:00:00.002026 ITERATION 4 time 0:00:02.427911 First Key -> 0:00:00.002906 Last Key -> 0:00:00.002065 Key -> 774 Max Time -> 0:00:00.003263 Key -> 7 Min Time -> 0:00:00.001763 avg -> 0:00:00.002413 ITERATION 5 time 0:00:02.768819 First Key -> 0:00:00.003051 Last Key -> 0:00:00.002319 Key -> 920 Max Time -> 0:00:00.007694 Key -> 11 Min Time -> 0:00:00.002007 avg -> 0:00:00.002753 ITERATION 6 time 0:00:02.537283 First Key -> 0:00:00.002676 Last Key -> 0:00:00.002549 Key -> 2 Max Time -> 0:00:00.003512 Key -> 132 Min Time -> 0:00:00.002318 avg -> 0:00:00.002523 ITERATION 7 time 0:00:02.723405 First Key -> 0:00:00.005272 Last Key -> 0:00:00.002788 Key -> 79 Max Time -> 0:00:00.007543 Key -> 12 Min Time -> 0:00:00.002457 avg -> 0:00:00.002709 ITERATION 8 time 0:00:02.947676 First Key -> 0:00:00.003161 Last Key -> 0:00:00.003028 Key -> 1 Max Time -> 0:00:00.006068 Key -> 31 Min Time -> 0:00:00.002683 avg -> 0:00:00.002933 ITERATION 9 time 0:00:03.781268 First Key -> 0:00:00.004271 Last Key -> 0:00:00.003416 Key -> 930 Max Time -> 0:00:00.011791 Key -> 5 Min Time -> 0:00:00.003029 avg -> 0:00:00.003765 ITERATION 10 time 0:00:03.842353 First Key -> 0:00:00.006544 Last Key -> 0:00:00.003394 Key -> 0 Max Time -> 0:00:00.006544 Key -> 4 Min Time -> 0:00:00.003171 avg -> 0:00:00.003826 ITERATION 11 time 0:00:03.361368 First Key -> 0:00:00.001509 Last Key -> 0:00:00.003626 Key -> 602 Max Time -> 0:00:00.009093 Key -> 9 Min Time -> 0:00:00.001089 avg -> 0:00:00.003346 ITERATION 12 time 0:00:03.581802 First Key -> 0:00:00.001511 Last Key -> 0:00:00.003912 Key -> 474 Max Time -> 0:00:00.009027 Key -> 1 Min Time -> 0:00:00.001117 avg -> 0:00:00.003566 ITERATION 13 time 0:00:03.797965 First Key -> 0:00:00.001833 Last Key -> 0:00:00.004118 Key -> 100 Max Time -> 0:00:00.005115 Key -> 9 Min Time -> 0:00:00.001126 avg -> 0:00:00.003782 ITERATION 14 time 0:00:04.147961 First Key -> 0:00:00.001851 Last Key -> 0:00:00.004362 Key -> 782 Max Time -> 0:00:00.013857 Key -> 16 Min Time -> 0:00:00.001186 avg -> 0:00:00.004132 ITERATION 15 time 0:00:04.251830 First Key -> 0:00:00.001538 Last Key -> 0:00:00.004611 Key -> 518 Max Time -> 0:00:00.009511 Key -> 9 Min Time -> 0:00:00.001114 avg -> 0:00:00.004236 ITERATION 16 time 0:00:04.487687 First Key -> 0:00:00.001541 Last Key -> 0:00:00.004994 Key -> 858 Max Time -> 0:00:00.009368 Key -> 9 Min Time -> 0:00:00.001120 avg -> 0:00:00.004472 ITERATION 17 time 0:00:04.703588 First Key -> 0:00:00.003440 Last Key -> 0:00:00.005104 Key -> 529 Max Time -> 0:00:00.008179 Key -> 8 Min Time -> 0:00:00.001105 avg -> 0:00:00.004688 ITERATION 18 time 0:00:05.300920 First Key -> 0:00:00.001851 Last Key -> 0:00:00.006987 Key -> 854 Max Time -> 0:00:00.007299 Key -> 9 Min Time -> 0:00:00.001181 avg -> 0:00:00.005285 ITERATION 19 time 0:00:06.168681 First Key -> 0:00:00.001880 Last Key -> 0:00:00.005577 Key -> 911 Max Time -> 0:00:00.009503 Key -> 9 Min Time -> 0:00:00.001119 avg -> 0:00:00.006152 ---------------------------------------------------------------------- Comment By: Oleg Broytman (phd) Date: 2011-07-14 20:56 Message: No idea what is going on. Let's investigate a little further. What version of SQLObject are you using? Can you add more prints inside the loop to see what part of the program takes time? ---------------------------------------------------------------------- You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=540673&aid=3366899&group_id=74338 |