| 00:00.15 | *** join/#storm wallflower (n=wallflow@ip-205-246-113-216.pool.grokthis.net) |
| 01:56.59 | *** join/#storm bigdo3 (n=scmikes@72-197-8-8-arpa.cust.cinci.current.net) |
| 02:26.35 | *** part/#storm marianom (n=marianom@ubuntu/member/marianom) |
| 02:47.16 | *** join/#storm marianom (n=marianom@ubuntu/member/marianom) |
| 04:08.35 | *** join/#storm bigdo2 (n=scmikes@72-197-8-8-arpa.cust.cinci.current.net) |
| 05:46.00 | *** join/#storm jukart (n=jukart@lsfw01.lovelysystems.com) |
| 06:31.19 | *** join/#storm mcella (n=mcella@ip-177-236.sn2.eutelia.it) |
| 09:21.50 | *** join/#storm harnak (n=harnak@ip-118-90-4-161.xdsl.xnet.co.nz) |
| 11:05.47 | *** join/#storm niemeyer (n=niemeyer@201-14-56-193.ctame705.dsl.brasiltelecom.net.br) |
| 11:32.44 | *** join/#storm dobee (n=dobee@lsfw01.lovelysystems.com) |
| 12:56.40 | *** join/#storm goschtl (n=goschtl@p5B0BC022.dip.t-dialin.net) |
| 15:40.27 | *** part/#storm goschtl (n=goschtl@p5B0BC022.dip.t-dialin.net) |
| 16:28.00 | *** join/#storm marianom (n=marianom@ubuntu/member/marianom) |
| 16:38.00 | *** join/#storm dobee (n=dobee@62-47-240-199.adsl.highway.telekom.at) |
| 17:01.58 | *** join/#storm dobee_ (n=dobee@62-47-240-199.adsl.highway.telekom.at) |
| 17:05.47 | *** join/#storm ghtdak (n=tarbox@dsl081-170-177.sea1.dsl.speakeasy.net) |
| 17:08.14 | ghtdak | pg8000 - pure python interface to postgres how might this change twistorm? http://pybrary.net/pg8000/ |
| 17:22.33 | radix | ghtdak: I doubt it will change anything |
| 17:23.05 | radix | even if it has an asynchronous API, which I can't see |
| 17:24.46 | radix | it could certainly become an option for a storm backend, if there's some reason to do that |
| 17:26.35 | ghtdak | radix: it just seemed less opaque potentially lending itself to something more twisted esque... |
| 17:26.53 | radix | ghtdak: well, perhaps it'll be better than psycopg (some day?) |
| 17:27.01 | radix | ghtdak: but I don't see anything about it that makes it interesting in the context of Twisted |
| 17:28.53 | ghtdak | radix: haven't read through the code myself... and I'm sure its not async... just that the protocol parsing is likely there and perhaps ripping out the IO would allow us to get rid of the deferToThread... although I'm not entirely sure how much that buys us... |
| 17:30.20 | radix | ghtdak: that would be neat, and would probably be nice for something adbapi-level |
| 17:30.37 | radix | ghtdak: but the problem with that and storm is that we would have to rewrite *all* of storm to deal with asynchronous backends |
| 17:30.48 | radix | (well, not "all", but "a very significant portion") |
| 17:31.45 | ghtdak | yea, but I've been playing with twistorm and the pieces it does are great for my needs. again, my argument about getting rid of defertothread gets weaker... not to mention that whole database agnosticism thing :-) |
| 17:55.25 | *** join/#storm dobee (n=dobee@85-124-200-100.static.xdsl-line.inode.at) |
| 18:00.10 | *** part/#storm ghtdak (n=tarbox@dsl081-170-177.sea1.dsl.speakeasy.net) |
| 18:11.42 | *** join/#storm mcella_ (n=mcella@ip-177-242.sn2.eutelia.it) |
| 18:46.03 | *** join/#storm jam (n=jam@adsl-75-51-62-134.dsl.chcgil.sbcglobal.net) |
| 18:47.14 | jam | good afternoon/good morning, I'm having a performance anomaly with storm, and I was wondering if anyone might help me work through either a workaround, or maybe a fix to Storm itself. |
| 18:47.29 | radix | jam: sure |
| 18:47.37 | jam | thanks radix |
| 18:47.43 | jam | So a basic summary of what I'm doing |
| 18:47.53 | jam | I'm parsing a file, where each line has a "source, destination" pair |
| 18:48.10 | jam | "source" is a 3-tuple entity, as is destination |
| 18:48.29 | jam | In my schema, I want to have a table for each entry, and have it reference an entity table |
| 18:48.40 | jam | so for each line, I parse out the source and destination |
| 18:48.45 | jam | then check to see if they exist in the entity table |
| 18:48.53 | jam | if they do, I use the entity.id |
| 18:48.59 | jam | if they don't, I create an entry and use it |
| 18:49.12 | jam | Fairly straightforward, IMO, but it is dog-slow |
| 18:49.19 | jam | what happens is that each "find()" does a flush() |
| 18:49.28 | jam | which calls obj_info.event.emit('flush') |
| 18:49.31 | jam | on all "live objects" |
| 18:49.37 | jam | in this case, when I'm inserting 2000 rows |
| 18:49.47 | jam | it ends up calling emit('flush'), 1M+ times |
| 18:49.48 | radix | so you've already determined that the slowness is in Python, not in database operations? |
| 18:50.00 | jam | radix: well --lsprof points to emit('flush') |
| 18:50.04 | radix | i.e., all of your queries are using indexes? |
| 18:50.10 | jam | though the find() operation is the specific issue |
| 18:50.26 | jam | radix: I added a unique(a, b, c) constraint on the entity table |
| 18:50.30 | radix | I see, ok |
| 18:50.30 | jam | so it should be using indices |
| 18:52.45 | radix | jam: also, what are your transaction boundaries? |
| 18:52.56 | radix | (I'm just going through the basics first) |
| 18:52.57 | jam | radix: I'm holding a single transaction for all 2k lines |
| 18:53.19 | jam | I'd like to parse a whole file, though that is something like 200k lines |
| 18:53.34 | jam | I can probably add some store.commit() in there, but I'd rather not if I don't have to |
| 18:53.40 | radix | jam: so, I'm wondering if it'll be improved if you batch the items into smaller transactions and make sure you don't maintain references to unnecessary objects for too long |
| 18:54.09 | jam | radix: well, my first workaround was to just create my own dictionary mapping (a,b, c) => db_id |
| 18:54.12 | radix | jam: even with raw SQL, it can be really increase performance to batch transactions to some particular size |
| 18:54.16 | jam | and that made it noticably faster |
| 18:54.36 | radix | jam: hmmm |
| 18:54.46 | radix | jam: actually, what kind of find() are you doing? |
| 18:54.52 | radix | jam: just getting an object by its primary key? |
| 18:55.03 | jam | radix: by the alternate unique key |
| 18:55.11 | jam | the primary key is a simple DB integer |
| 18:55.17 | radix | jam: oh, hm, ok |
| 18:55.17 | jam | the table is |
| 18:55.21 | jam | id, info, about, this |
| 18:55.26 | jam | where 'info, about, this' is unique |
| 18:55.35 | jam | and I'm using a table to collapse those long strings into a simple integer |
| 18:55.43 | radix | ok |
| 18:55.45 | jam | rather than replicating all of that in my other rows |
| 18:56.01 | radix | I was about to suggest .get(), which is a way to look up an object by its primary key without hitting the database if it's not necessary, but that won't help :) |
| 18:56.31 | jam | As an aside, I have 227,000 lines, and 1,179 unique entities |
| 18:56.39 | jam | if that gives you an idea about the hit rates, etc. |
| 18:57.54 | radix | jam: a cache of query results does sound fairly reasonable, when you may be making the same query many times |
| 18:58.20 | jam | radix: to give you a comparison, it is 12s to load 2000 lines, if I create a python dict, it goes down to 2.6s |
| 18:58.39 | jam | radix: my concern is mostly about "Storm" and the overhead of all of the emit('flush') calls |
| 18:58.49 | jam | it seems to be... quadratic? or some other very poor performance |
| 18:58.50 | radix | jam: well, avoiding the queries avoids the flushes :) |
| 18:59.08 | radix | jam: wait, quadratic? maybe I missed something |
| 18:59.09 | jam | radix: certainly |
| 18:59.22 | radix | jam: it should just do that once for each live object |
| 18:59.35 | jam | radix: well for each line, there are 2 entities to lookup |
| 18:59.38 | jam | for 2000 lines |
| 18:59.45 | jam | I see 1 million calls to emit('flush') |
| 18:59.56 | jam | there are only 64 unique entities in my 2000 lines |
| 19:00.18 | jam | so 2000 * 2000 = 4 million |
| 19:00.23 | jam | so if you say that it starts at 1 live object |
| 19:00.30 | jam | but has 2000 live objects at the end |
| 19:00.37 | jam | you get to around 1 million calls |
| 19:00.40 | radix | I see |
| 19:00.47 | jam | 2000 doesn't sound like a lot of objects to me |
| 19:01.27 | radix | jam: still, my suspicion is that the query itself would be more expensive than any one of those flushes |
| 19:01.39 | radix | there may still be room for optimization there, though |
| 19:02.00 | radix | jam: 2000 is kind of a lot of objects to be manipulating all at once in one transaction |
| 19:02.21 | jam | well, considering I have 200,000 of them, 2000 is pretty small |
| 19:02.32 | jam | I've certainly done bulk imports before in raw SQL and it wasn't a big deal |
| 19:02.39 | jam | I can show you the --lsprof outputs if you want |
| 19:02.43 | radix | jam: yes, and I would certainly recommend you do _not_ manipulate all 200,000 of those objects in one transaction :) |
| 19:03.03 | radix | even if you're doing raw import with SQL statements, batching the transactions will make it much faster |
| 19:03.03 | jam | radix: I've often done that in the past, just not using an ORM |
| 19:04.31 | radix | jam: anyway, for your application, I would suggest doing the caching of queries |
| 19:04.48 | jam | radix: I'm still a little concerned about the find() performance |
| 19:05.05 | jam | Dropping the batch size to 100 would be possible, I guess |
| 19:05.18 | radix | jam: we may be able to do something about flush performance |
| 19:05.31 | jam | what I'm seeing *with* the cache is 61 calls to 'find()' |
| 19:05.32 | radix | like, maybe we can avoid emitting the flush event for objects which haven't been dirtied |
| 19:05.43 | jam | taking 3s (under --lsprof) |
| 19:05.56 | jam | of which 3s is spent in flush() |
| 19:06.17 | jam | radix: what is the call to look for, which would be the actually DB query? |
| 19:06.30 | jam | radix: also, this is lp:storm (trunk) btw |
| 19:06.32 | radix | jam: execute probably |
| 19:06.45 | radix | I assume you're measuring wallclock time? |
| 19:07.07 | jam | I see 1000 calls to _fill_missing_values which calls execute |
| 19:07.18 | jam | _fill_missing takes 1.1s, execute takes 0.77 of that |
| 19:07.29 | radix | jam: that's not the primary execution. which DB are you using, btw? |
| 19:07.30 | jam | so the flush() overhead is still 3x that of the actual DB query |
| 19:07.36 | jam | radix: this is using sqlite |
| 19:07.42 | jam | I'm also planning on using postgres |
| 19:08.03 | radix | fill_missing_values gets called after insertions |
| 19:08.19 | radix | jam: what about all calls to raw_execute? |
| 19:08.57 | jam | radix: I also see 34,099 calls to emit() taking 0.8749 sec (it is the #1 entry in --lsprof) |
| 19:09.20 | radix | this is wallclock time? |
| 19:09.24 | jam | 2064 calls to raw_execute, taking 0.5979 s |
| 19:09.32 | jam | radix: I believe it is wall-clock |
| 19:09.42 | jam | so hitting the db is only what, 0.6s ? |
| 19:09.46 | jam | versus 3s in flush()? |
| 19:10.00 | radix | jam: Ok, then that's bad :) |
| 19:10.02 | jam | radix: that is *with* my cache |
| 19:10.09 | radix | jam: can you verify that it's wallclock time and not CPU time? |
| 19:10.25 | jam | radix: well, if you put a 'pdb' statement in, the number goes way up |
| 19:10.29 | jam | but I'll try a sleep just to make sure |
| 19:10.30 | radix | I see, ok |
| 19:11.42 | jam | <PROTECTED> |
| 19:11.47 | jam | radix: so yeah, wall-clock time |
| 19:11.48 | radix | ok |
| 19:13.20 | radix | I guess I can think of a few possibilities |
| 19:13.28 | radix | but I'm not sure if they'll break compatibility or features in bad ways |
| 19:14.11 | radix | we could offer a more explicit event registration API so that we avoid firing events when nobody will be listening to them, or we could try to figure out a way to only emit the event for "dirty" objects |
| 19:17.35 | jam | radix: so just to give you the lsprof overview. I see 1998 calls to 'insert_one' which takes 10s |
| 19:17.45 | jam | 1.5s is spent in "properties.__set__' |
| 19:17.54 | jam | 8s is spent in _get_or_create_entity_id |
| 19:18.01 | jam | with 3996 calls (2 per line) |
| 19:18.15 | jam | of the 8s, 7.3s is spent in store.find() |
| 19:18.33 | jam | of the 7.3736s, 7.37 of it is spent in flush() |
| 19:19.00 | niemeyer | jam: Are these cumulative times? |
| 19:20.07 | niemeyer | Hmm.. from your description it looks like so |
| 19:20.12 | jam | niemeyer: yes |
| 19:20.48 | niemeyer | jam: So what's spending most of the non-cumulative time in your case? |
| 19:20.53 | jam | of 8.0 total seconds spent in flush(), 0.3s is spent in emit(), and 7.17s are spent in _flush_one() |
| 19:21.27 | jam | niemeyer: with the entity.id cache, _check_disconnect spends 1.0s non cumulative |
| 19:21.33 | niemeyer | jam: Yeah, it's expected that the bulk of Storm's operation will be under flush |
| 19:21.40 | jam | event.emit() spends 0.7885s |
| 19:22.16 | jam | under _flush_one() at 7.17s, 2.6s is _fill_missing_values, and 3.25 is in database.execute |
| 19:22.44 | jam | and a total time of 1.74s in raw_execute |
| 19:23.01 | niemeyer | jam: But that's cumulative, right? |
| 19:23.05 | jam | niemeyer: correct |
| 19:23.25 | jam | _check_disconnect doesn't have anything underneath it |
| 19:23.29 | niemeyer | jam: It's hard to spot the bottleneck with cumulative times |
| 19:23.49 | jam | niemeyer: well, pointing out that flush() is spending 7x longer than execute... (cumulative) |
| 19:23.52 | niemeyer | jam: At least at that level |
| 19:24.16 | jam | so the top non-cumulative are |
| 19:24.20 | jam | _check_disconnect at 1s |
| 19:24.25 | jam | emit at 0.7885 |
| 19:24.30 | jam | _compile_single at 0.6911 |
| 19:24.44 | jam | expr.py.__call__ at 0.6327 |
| 19:25.00 | jam | method get of dict objects a t0.6237 (with 256,470 calls) |
| 19:25.01 | niemeyer | jam: I definitely expect the ORM to be the heavier part of an operation of a few thousand inserts |
| 19:25.11 | jam | variables:180(set) at 0.5389 s |
| 19:25.32 | jam | niemeyer: if you want real pain, I can take out my object cache |
| 19:25.57 | niemeyer | jam: Can you describe in a high level what's being done? |
| 19:26.04 | jam | niemeyer: do you have the traceback? |
| 19:26.10 | jam | I'm parsing a file with XX lines |
| 19:26.13 | niemeyer | jam: Note that _check_disconnect() is a simple pass-through |
| 19:26.15 | jam | each line has a source and destination |
| 19:26.29 | jam | These are reused throughout the file |
| 19:26.34 | jam | so I check to see if it exists, if not I create it |
| 19:26.44 | jam | so that is 2 lookups per line |
| 19:26.50 | jam | with most of them already existing |
| 19:26.51 | niemeyer | It's curious that most of the non-cumulative time is there |
| 19:27.05 | jam | (out of 2000 lines, there are only 64 unique entities) |
| 19:27.19 | jam | so my local cache hits something like 90% of the time |
| 19:27.20 | niemeyer | jam: How do you check for existence? |
| 19:27.36 | jam | niemeyer: by the unique(col1, col2) constraint on the table |
| 19:27.48 | jam | find(entity, entity.col1 == X, entity.col2 == Y) |
| 19:27.50 | niemeyer | jam: Sorry, I mean, how is it done int he Storm level |
| 19:27.57 | niemeyer | jam: And then? |
| 19:28.05 | jam | result = find() |
| 19:28.09 | jam | obj = result.one() |
| 19:28.12 | jam | if obj is None: |
| 19:28.25 | niemeyer | jam: Ok, that's one bit worth optimizing |
| 19:28.55 | niemeyer | jam: There's no need to kick in the ORM mechanism for this query |
| 19:29.03 | jam | In raw SQL, I could certainly do "SELECT entity.id FOR entity.col1 == ? AND entity.col2 == ?" |
| 19:29.21 | jam | niemeyer: well, I was hoping to be able to use the ORM since, that is what it is for |
| 19:29.25 | jam | I certainly can do raw SQL if I wanted |
| 19:29.31 | niemeyer | jam: You can do that in Storm too, but it's even easier to do result.count() != 0 |
| 19:29.43 | jam | niemeyer: but I need the object id to reference it |
| 19:29.57 | jam | The db table is |
| 19:30.01 | jam | id, col1, col2 |
| 19:30.01 | niemeyer | jam: Then you can do |
| 19:30.06 | jam | unique(col1, col2) |
| 19:30.10 | niemeyer | jam: result.values(MyClass.id) |
| 19:30.39 | niemeyer | jam: Are these columns the primary key? |
| 19:30.51 | niemeyer | Well, certainly not |
| 19:30.57 | niemeyer | Otherwise you wouldn't need the object |
| 19:31.12 | niemeyer | jam: So yeah, that's an improvement |
| 19:31.57 | jam | niemeyer: well, they are a unique() key, but I'm using the row.id as the primary key |
| 19:32.10 | jam | as col1, col2 are long strings |
| 19:32.22 | jam | and I'd rather use a simple 32-bit int in future lookups |
| 19:32.34 | niemeyer | jam: I definitely agree that the ORM should be used whenever it makes sense to use it, but I won't pretend that it's not a heavy operation. Using the whole ORM mechanism is a lot more expensive than the raw SQL |
| 19:32.53 | niemeyer | jam: That's the price for the convenience of having something like this written in Python |
| 19:33.12 | radix | niemeyer: still, there may be some optimizations possible |
| 19:33.13 | jam | niemeyer: sure, though I think the overhead is a bit more than *I* would have expected |
| 19:33.16 | niemeyer | jam: Right, understood.. makes sense |
| 19:33.20 | jam | especially because of the O(N^2) problem |
| 19:33.21 | niemeyer | radix: Oh yeah, agreed |
| 19:33.28 | jam | when processing N lines, it calls flush on N objects |
| 19:33.41 | jam | (N times) |
| 19:33.44 | jam | well, N*2 in my case |
| 19:34.08 | jam | if I get rid of the N^2 portion, it still takes 7x to do all the flushes |
| 19:34.15 | jam | but anyway, I can redo that portion in raw SQL |
| 19:34.25 | jam | what is the *right* way to get it to not conflict with the ORM? |
| 19:34.29 | jam | just flush() after the insert? |
| 19:34.38 | jam | store.add(new_entity), store.flush()? |
| 19:34.44 | jam | so that an SQL query will find it? |
| 19:35.18 | niemeyer | emit |
| 19:35.24 | niemeyer | Sorry.. wrong window |
| 19:35.39 | niemeyer | Hmmm |
| 19:36.04 | jam | niemeyer: so the result.values(MyClass.id) is so that I get back just the Entity.id value, rather than a whole object, right? |
| 19:36.07 | niemeyer | jam: Conflict in which sense? |
| 19:36.15 | jam | niemeyer: get out of sync |
| 19:36.16 | niemeyer | jam: Right |
| 19:36.21 | jam | where the raw SQL doesn't think the same thing as the ORM |
| 19:36.37 | niemeyer | jam: I see |
| 19:36.51 | niemeyer | jam: You can run store.invalidate() to make Storm invalidate all cached objects |
| 19:37.20 | niemeyer | jam: So if you plan to update a large number of objects, that might be the easiest |
| 19:37.32 | niemeyer | jam: If you're just inserting objects, there's nothing to worry (for now) |
| 19:37.34 | jam | niemeyer: I don't often do that |
| 19:37.40 | jam | but yeah, thanks for the heads up |
| 19:37.42 | niemeyer | jam: We don't have negative caches *yet* |
| 19:37.46 | jam | mostly I'm just inserting right now |
| 19:37.58 | jam | niemeyer: so is the correct thing something along the lines of: |
| 19:38.03 | jam | >>> result = store.execute(Select(Person.name, Person.id == 1) |
| 19:38.08 | jam | result.get_one() |
| 19:38.11 | jam | (from the tutorial) |
| 19:38.27 | niemeyer | jam: Nope, you can use find() in these cases too |
| 19:38.30 | niemeyer | jam: E.g. |
| 19:38.44 | jam | niemeyer: well find() calls flush(), and I'm trying to avoid that if I can |
| 19:38.56 | jam | since I called flush() manually the last time I added something to this table |
| 19:39.13 | niemeyer | jam: Oh, I see |
| 19:39.29 | jam | I insert about 64/4000 of the time |
| 19:39.34 | niemeyer | jam: There's no way to call execute a query in the Store without going through the flush() procedure |
| 19:39.37 | jam | so it is much more efficient to only flush when I insert |
| 19:39.39 | niemeyer | s/call/ |
| 19:39.43 | jam | rather than everytime I lookup |
| 19:40.06 | jam | niemeyer: well, I can do c = store._raw_connection.get_cursor(), c.execute() or whatever |
| 19:40.12 | jam | though I'm sure that isn't an "officially supported" api |
| 19:40.21 | niemeyer | jam: On the other hand, if you don't have 200 thousand objects in memory, it's less likely to be a performance bottleneck |
| 19:40.46 | jam | niemeyer: well, I create an Entity(Storm) to insert |
| 19:40.54 | niemeyer | jam: That's definitely not supported.. anything underlined isn't |
| 19:40.57 | jam | will that go away if I only query for the result.values(Entity.id) ? |
| 19:41.17 | niemeyer | jam: It will get garbage collected after a while, if you don't save a reference to it |
| 19:41.55 | jam | niemeyer: if I save a reference to "my_entity.id" is that self-referential? |
| 19:42.00 | jam | or is that just a simple integer in my dict? |
| 19:42.13 | jam | I don't know how much magic you have in some of your objects |
| 19:42.43 | niemeyer | jam: Just a simple integer |
| 19:43.16 | niemeyer | jam: If you're feeling brave, you might want to try out the C-based extensions |
| 19:43.19 | jam | niemeyer: also, what about Store.block_implicit_flushes() around this? |
| 19:43.39 | jam | specifically around the find() |
| 19:43.56 | niemeyer | jam: Hmm, but I guess it's not working in trunk.. |
| 19:44.14 | jam | niemeyer: well, the logic looks right in my copy of trunk |
| 19:44.15 | niemeyer | jam: Oh yeah, that might work |
| 19:44.33 | niemeyer | jam: I forgot about that new API jamesh implemented |
| 19:44.56 | niemeyer | jam: Sorry, I was referring to the C extensions on that "not working" bit |
| 19:45.37 | niemeyer | We need to somehow enable testing on them so that they don't go behind |
| 19:46.05 | niemeyer | I mean, they must be explicitly compiled right now for tests to run with it |
| 19:46.17 | niemeyer | So we either run the whole test suite in one way or the other |
| 19:46.39 | *** join/#storm dobee (n=dobee@85-124-200-100.static.xdsl-line.inode.at) |
| 19:48.40 | jam | niemeyer: we used an interesting method with bzr, which you might consider |
| 19:48.50 | jam | basically, we have explicit tests for the functions which are "replaced" |
| 19:48.58 | jam | and then we call one foo_c and one foo_py |
| 19:49.08 | jam | and we can run the explicit tests across both of them |
| 19:49.26 | jam | assuming that you are testing the interface sufficiently |
| 19:49.27 | niemeyer | jam: We thought about something like this, but it's slightly more tricky in that specific case |
| 19:49.33 | jam | and then the higher level just uses whatever is available |
| 19:49.41 | jam | niemeyer: you can also set "make check" to do |
| 19:49.44 | jam | run test |
| 19:49.47 | jam | build .c |
| 19:49.49 | jam | run test |
| 19:49.57 | niemeyer | jam: Some of the C replacements are used as bases for subclasses that are then implemented in Python |
| 19:50.01 | jam | we do python -O test; LANG=C python -O test |
| 19:50.18 | niemeyer | jam: and that spreads quite a bit of code |
| 19:50.40 | niemeyer | jam: I think your approach sounds like a good one nevertheless.. we'll just have to reorganize things somehow to make that possible |
| 19:51.30 | jam | niemeyer: well, with using a block()/unblock() call, I'm seeing 59,000 calls to emit() which is taking 0.7s non-cumulative (1.7 cumulative) |
| 19:51.32 | niemeyer | jam: Yeah, that second suggestion sounds easy to do |
| 19:52.13 | niemeyer | jam: Interesting indeed |
| 19:52.29 | jam | niemeyer: I might add some gc.collect calls |
| 19:52.33 | niemeyer | refreshes his memory about emit |
| 19:53.07 | niemeyer | jam: Out of curiosity, would you mind to compile the C version? |
| 19:53.15 | niemeyer | jam: and try it out to see the timing difference |
| 19:53.40 | niemeyer | jam: cevent.c is likely up-to-date, but I think I missed an update on the other modules in the current trunk |
| 19:54.06 | niemeyer | jam: Oh, crap.. it's a single C module.. it'll be tricky. |
| 19:54.50 | niemeyer | will have to review the diff between 0.12 and trunk to bring them up-to-date |
| 19:54.52 | jam | well, without doing result.values() I see 78,421 calls to emit() |
| 19:55.00 | jam | so result.values() *does* seem to improve it |
| 19:55.04 | jam | but not as much as I would expect |
| 19:55.35 | jam | niemeyer: is there a way to keep the compiled query? |
| 19:55.36 | niemeyer | jam: emit() is the basic building block of many of the features, so I'm not too surprised |
| 19:55.43 | jam | I see a decent amount of time spent in _compile_single |
| 19:55.47 | jam | even though that query doesn't change form |
| 19:56.17 | niemeyer | jam: It's one thing worth considering for sure |
| 19:57.07 | niemeyer | jam: What are the cumulative/non-cumulative times on it, out of curiosity? |
| 19:57.15 | jam | niemeyer: so is there a way to call a direct SQL string? |
| 19:57.24 | jam | (with parameter substitution, of course) |
| 19:57.44 | jam | niemeyer: 63,218 calls, 59,028 recursive, 3.5s cumulative, 0.6493 non-cumulative |
| 19:58.04 | niemeyer | jam: Yes, just store.execute("SQL STRING", (param, ...)) |
| 19:58.19 | jam | compile_column is 1.497, 0.3079, and compile_sql_token is 0.746, 0.2211 |
| 19:58.57 | niemeyer | Interesting.. that's an easy win with the cextension |
| 19:59.11 | niemeyer | Not compile_column, though |
| 19:59.24 | niemeyer | Well, maybe that one too.. |
| 19:59.53 | jam | niemeyer: so I should use "?" for the parameters, right? |
| 19:59.54 | niemeyer | Functions specialized on backends would still be slower, but there would already be a win there |
| 19:59.57 | jam | not the named ones, or anything like that |
| 19:59.58 | niemeyer | jam: Right |
| 20:08.14 | *** join/#storm mcella (n=mcella@ip-179-232.sn2.eutelia.it) |
| 20:15.55 | jam | niemeyer: well, using a raw sql query (without the cache) is 4s, with the cache is 2.4s |
| 20:16.15 | jam | versus 2.6s with the cache and store.find() |
| 20:16.23 | jam | and 12s without the cache and store.find() |
| 20:19.31 | niemeyer | jam: For 200k rows? |
| 20:20.05 | jam | niemeyer: 2k rowsw |
| 20:20.07 | jam | rows |
| 20:20.17 | jam | it was 19min last night for 200k rows |
| 20:20.31 | jam | still pretty long versus the time to just parse it into python tuples |
| 20:20.45 | jam | --lsprof is pointing a bit at 60915 calls to _compile_single |
| 20:20.58 | jam | from 38872 calls to Expr.__call__ |
| 20:22.22 | niemeyer | jam: Well, yeah, I don't think we'll get close to the raw timing unfortunately :( |
| 20:22.53 | jam | under lsprof, 6.5s is in 2063 calls to _flush_one, 2.3 of that in _fill_missing, and 3.1 in execute() |
| 20:23.19 | niemeyer | jam: Storm is usually pretty fast for a Python ORM, but the overhead in such large operations become noticeable |
| 20:24.17 | niemeyer | jam: If that script may be shown, I'd be interested in having a look at it at some point |
| 20:24.36 | niemeyer | jam: 19 minutes is unexpectedly high |
| 20:24.59 | *** join/#storm dobee (n=dobee@85-124-200-100.static.xdsl-line.inode.at) |
| 20:27.46 | jam | niemeyer: that might have been before my Id cache, but I don't think so |
| 20:28.11 | jam | I usually count the insertions per second in at least the hundreds range |
| 20:28.35 | jam | if it was 200/s that would be 1ks or 16 min |
| 20:29.00 | jam | niemeyer: does the ORM retain handles to objects if you don't Store.commit() them? |
| 20:29.13 | jam | I'm just wondering if committing every 100-1000 would make a large difference |
| 20:29.35 | jam | niemeyer: otherwise, I don't seem to be holding my own reference to any of these things |
| 20:29.42 | jam | it is meant to just be the "bulk import" portion of the code |
| 20:30.04 | jam | niemeyer: also, does Storm support any of the "COPY" syntax from postgres? |
| 20:30.08 | jam | speaking of bulk imports |
| 20:30.47 | niemeyer | jam: It retains strong references to dirty objects only (and to the N last fetched objects in a cache) |
| 20:31.08 | niemeyer | jam: It doesn't implement anything on top of it, but you can definitely use it |
| 21:02.19 | *** join/#storm mcella_ (n=mcella@ip-176-246.sn2.eutelia.it) |
| 21:12.12 | jam | niemeyer: define "dirty" is that uncommitted, or unflushed ? |
| 21:13.31 | niemeyer | jam: "dirty" = object has changes that must be sent to the database (with INSERT, UPDATE, DELETE) |
| 21:13.51 | jam | so a flush() will remove the "dirty" flag? |
| 21:14.21 | niemeyer | jam: So unflushed.. could be uncommitted *and* unflushed, of course |
| 21:14.24 | niemeyer | jam: It will |
| 21:15.00 | jam | niemeyer: well, if I change it to commit every 200 lines, it actually slows down to 3.4s, versus 2.4 |
| 21:15.08 | jam | If I commit every 1000, it is around 2.4s still |
| 21:15.16 | jam | though I'm testing only 2000 lines right now |
| 21:52.13 | *** join/#storm dobee (n=dobee@85-124-200-100.static.xdsl-line.inode.at) |