Forum OpenACS Development: acs_object__new slowness...

I think I have tracked down the slow object create problem on postgres. The problem is that creating the tree_sortkey is quite slow for things with lots of siblings...

Here is the code which generates the tree_sortkey:

create function acs_objects_insert_tr () returns opaque as '
declare
        v_parent_sk     varbit default null;
        v_max_value     integer;
begin
        if new.context_id is null then 
            select max(tree_leaf_key_to_int(tree_sortkey)) into v_max_value 
              from acs_objects 
             where context_id is null;
        else 
            select max(tree_leaf_key_to_int(tree_sortkey)) into v_max_value 
              from acs_objects 
             where context_id = new.context_id;

            select tree_sortkey into v_parent_sk 
              from acs_objects 
             where object_id = new.context_id;
        end if;

        new.tree_sortkey := tree_next_key(v_parent_sk, v_max_value);

        return new;
end;' language 'plpgsql';

I created a site with about 90k users (and not much content) and adding users was taking about 4 seconds per user. and the majority of that time was spent generating the tree_sortkey for the user and the users membership_rel for the site. The user has context_id null and the membership_rel has context_id -2 and here are the query plans for these two circumstances:

clean=# explain analyze select max(tree_leaf_key_to_int(tree_sortkey)) from acs_objects where context_id = - 2;
                                                      QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=4994.24..4994.24 rows=1 width=12) (actual time=2244.36..2244.36 rows=1 loops=1)
   ->  Seq Scan on acs_objects  (cost=0.00..4763.93 rows=92126 width=12) (actual time=0.16..294.26 rows=90053 loops=1)
         Filter: (context_id = -2)
 Total runtime: 2244.40 msec
(4 rows)

clean=# explain analyze select max(tree_leaf_key_to_int(tree_sortkey)) from acs_objects where context_id is null;
                                                      QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=4532.39..4532.39 rows=1 width=12) (actual time=1892.85..1892.85 rows=1 loops=1)
   ->  Seq Scan on acs_objects  (cost=0.00..4305.74 rows=90660 width=12) (actual time=0.03..263.70 rows=92624 loops=1)
         Filter: (context_id IS NULL)
 Total runtime: 1892.90 msec
(4 rows)

I created functional indexes for tree_leaf_key_to_int(tree_sortkey):

create index tmp_ts_idx on acs_objects(tree_leaf_key_to_int(tree_sortkey));
create index tmp_ts_null_idx on acs_objects(tree_leaf_key_to_int(tree_sortkey)) where context_id is null;
create index tmp_ts_reguser_idx on acs_objects(tree_leaf_key_to_int(tree_sortkey)) where context_id = -2;

but none of them were used unless I did "set enable_seqscan to off;" and in that case they were typically just as slow as the table scans (not unsurprisingly since they are both ~50% of the table).

clean=# explain analyze select max(tree_leaf_key_to_int(tree_sortkey)) from acs_objects where context_id is null;
                                                                   QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=242645.75..242645.75 rows=1 width=12) (actual time=1847.50..1847.50 rows=1 loops=1)
   ->  Index Scan using tmp_ts_null_idx on acs_objects  (cost=0.00..242414.19 rows=92624 width=12) (actual time=0.13..306.28 rows=92624 loops=1)
         Filter: (context_id IS NULL)
 Total runtime: 1847.56 msec

The fundamental problem is that walking through an objects siblings to find the max(tree_leaf_key) is very slow. we can mitigate the problem somewhat by making sure things have a context_id that limits the number of siblings but for users the registered_users context will always have a lot of siblings and so user create will remain slow.

On openacs.org here are the contexts with lots of children:

openacs.org=# select *, acs_object__name(context_id) 
  from (select count(*), context_id from acs_objects group by context_id having count(*) > 100) a;

 count | context_id |               acs_object__name
-------+------------+-----------------------------------------------
   111 |       -400 | Trash
   105 |       -100 | Pages
  7024 |         -2 | Registered Users
 27304 |      14013 | OpenACS Q&A
  9725 |      14014 | OpenACS Development
   307 |      14015 | OpenACS CMS
  1292 |      14016 | OpenACS Testing
  2725 |      14017 | .LRN Q&A
  5090 |      46408 | CVS Commits
  1479 |      56106 | OpenACS Bugs
   260 |      73798 | #OpenACS IRC Log
   180 |      98190 |  Bookmarks Root Folder of shermira@wanadoo.es
   329 |     115570 | OpenACS Improvement Proposals (TIPs)
   125 |     137862 | doc/openacs-HEAD/
 25391 |            |
(15 rows)

One reason forums is still somewhat slow is that all messages have the context of the forum and so a post has to walk through the 1000s of rows to determine the max sibling. Another problem is the apm_package__new slowness, this happens because parameter_values are objects and have context_id null; Each parameter takes a while to create as it has to traverse the items which also have context_id null.

Again on openacs.org here are the objects created with no context_id:

openacs.org=# select object_type, count(*) from acs_objects where context_id is\
 null  group by object_type having count(*) > 10;
      object_type      | count
-----------------------+-------
 acs_sc_implementation |    22
 acs_sc_msg_type       |    46
 acs_sc_operation      |    19
 apm_package_version   |    50
 apm_parameter         |   176
 apm_parameter_value   |   800
 content_extlink       |   167
 content_revision      |   142
 etp_page_revision     |   767
 notification          |   215
 notification_request  | 14067
 site_node             |   118
 url                   |  1644
 user                  |  7024
 user_portrait_rel     |    82
(15 rows)

Notifications and Users here are the standouts but on a dotlrn site I think you can end up with a pretty large number of parameter_value entries as well (because there are a lot of params and a lot of site nodes).

Jeff ... good call on the parameters.

You've correctly identified the bottleneck as being the creation of tree_sortkey.  The general fix is to add an additional integer column called (say) "max_leaf" to each node , which can be used directly, avoiding the need to traverse all the children of a node when adding a new child.

This needs to be done for all types which carry tree_sortkeys, and should be done for 5.0.

There are still concurrency issues which AFAIK are unsolvable in today's PG because locking within PL/pgSQL doesn't work right (which I define as "the way Oracle does it" in this case).  Locking has to be done at the application level to work the way one expects and this is impractical for a system like OpenACS.  Fortunately in practice it's not clear anyone's actually run into the concurrency bug ...

<blockquote> The general fix is to add an additional integer column
called (say) "max_leaf" to each node , which can be
used directly, avoiding the need to traverse all the
children of a node when adding a new child.
</blockquote>

But wouldn't it require additional time to update it (albeit this may still be better than current state)?

Maybe Oracle-like CONNECT BY for Pg should be given a try?

Don, I like using the object_id but the problem is updates on an existing site where the heirarchy was created with the old style key mechanism

Node  ObjID   Context SortKey
A     1       null    1
  B   2       1       1.1
C     3       null    2

If you wanted to update B's context_id to null you couldn't assume it's object_id was available since it had been used by C for its sortkey.

Of course on insert it should be ok (although it's conceivable that if a site juggled it's context_ids around enough the tree_sortkey could have walked past the object_id sequence but I don't think that it has ever or would ever happen). To be certain and safe though you would need to bump the object_id past the max tree_sortkey if it had, and when updating context_id to null you would need to take a nextval(object_id) although use it just for the sortkey rather than as the actual object_id.

Andrew, No, it has not been fixed yet and it (and thanks for pointing out Patrick's solution). I think there is still a locking problem with Patrick's code (not based on anything but hearsay though) but the more commonly encountered problem, besides the performance one that got me looking into it, is the duped tree_sortkeys. There are some places where code like Patricks has been implemented (forums, dotlrn_communities_all, dotlrn_community_types all maintain a max_child_sortkey in the parent) but it's not in: sp_folders, bm_bookmarks, acs_messages, cr_keywords, cr_items, site_nodes, acs_privilege_hierarchy_index, acs_objects, and acs_object_types.

Yes, most of the oracle datamodel uses connect by for this rather than tree_sortkey but they are roughly equivalent. The tree_sortkey stuff has been implemented in oracle is used in dotlrn (for the dotlrn_communities_all and dotlrn_community_types tables). My gut tells me tree_sortkey is a better answer for heirarchies that are mostly static but I am not aware of anyone having benchmarked things.

Actually I was thinking of changing *all* first-level keys to use the object's object_id, though that's not what I said :)  Changing to this scheme would fix the null context_id problem automatically, that's what I'm thinking.

So your A,B,C nodes would all have their object_id as their first-level sortkey ...

Now doing the update may still be difficult because update's in PG aren't (logically) atomic so you can have unique constraint errors generated mid-update so any update script has to be very careful, I don't think you can just do one big UPDATE statement.

But this is the most attractive solution I've been able to think of ...

When I ran my experiments I went all the way up to "LOCK TABLE".

However, now that I think about it ... doing a "SELECT FOR UPDATE" in two separate parallel calls to a function may actually work correctly IN THIS CASE, because we know the key exists at the beginning of each transaction that fires the trigger.  Thus both see (and lock) the same tuple.  Good news - I think :)

When I found the locking problem I was looking at another problem - the denormalized party members table I added in 4.6 that helped speed up permissions checking so much.

Check out the Oracle and Postgres implementations - you'll see that in Oracle I keep one party/membership pair and count the number of times a row's generated through group membership (multiple instances are a natural result of the groups datamodel and implementation).

In Postgres I don't count, I add the duplicate rows, adding to the space burden that results from this denormalization (but not materially slowing down permissions checking).

The reason is that in PG you can't solve the following problem entirely within PL/pgSQL:

If a tuple with key "k" exists in table "t", UPDATE its counter; otherwise INSERT a new tuple with key "k" and counter set to zero.

Logically you can do this (no exception handling in PG, remember):

LOCK t;
UPDATE t SET counter = counter + 1 WHERE key = 'k';
IF (no rows updated) THEN
  INSERT INTO t VALUES ('k', 0);
END;
UNLOCK t;

(in practice you only need a write lock of course)

Buried in PL/pgSQL this code will generate duplicate rows in "t" with key "k".  Done at PSQL it will not (of course!).

The problem is that a statement like "SELECT foo()" is executed atomically - statements inside PL/pgSQL don't change tuple visibility in other transactions because they're not considered "real commands".

So two calls to the above snippet can result in the following (call the two threads "A" and "B"):

A. locks t
B. waits for t because A has locked it
A. tries update, no tuples modified (row doesn't exist)
A. inserts row with key 'k'
A. unlocks table
B. resumes execution
B. tries update - NO TUPLES ARE MODIFIED because it doesn't
see the row inserted by A above!  Because the tuple set visible to the function is computed when its parent "SELECT foo()" begins execution, changes by other transactions aren't visible anywhere within the statement.

F**K!

Of course from PSQL each statement bumps the command counter (counts as a "real command") and doing the above from two PSQL sessions results in B "seeing" the tuple inserted by A, once A releases its lock and B resumes execution.

Oracle, on the other hand, makes tuples from other transactions visible within PL/SQL in such cases, in triggers and procs at least (maybe not functions - see below).

Now one can argue that PG is doing the correct - though damned inconvenient - thing here because a SELECT statement is *supposed* to operate atomically on a set of tuples.  We don't have procedures in PG, just functions, and we don't have triggers distinct from functions (in other words, PG triggers call functions rather than contain their on block of code).

One could argue that functions shouldn't have side effects that bring up issues like tuple visibility (since functions with side effects are "unclean" in theory anyway) but since PG procs don't exist and PG triggers don't have their own block of code we're *forced* to write "unclean" functions where we very, very much want side effects to break the atomic nature of the calling SELECT statement ...

Now at the application level we could call LOCK before such function calls but it is impractical to tell developers LOCK all tables used by all functions called directly or indirectly by triggers that are modified in ways that could cause race conditions within that code.  Right? :)

I haven't raised this issue with the PG crowd because, as I've said, from one point of view the behavior's correct and because we have, well, philosophical differences in some areas and I've gotten tired of trying to explain language implementation issues to them in a way that they can understand.  They tend to be inconsistent and unpredictable.

Ok, select for update it is. I will do some concurrency testing as well and see if I can break it.

If by level 0 you mean null, then I think there is a good reason for things with context_id null to have a non-null tree sortkey.

Say you want all the parents of e given a heirarchy

  
Node   level0    level1
a      Null      1
  b    1         1.1
c      Null      2
  d    1         2.1
    e  1.1       2.1.1

if a and c are level 0 then as you walk up you have no way of picking out a or c as the parent of e, whereas in the case of all tree_sortkeys starting at level1 it's just the same as the other parents...

I also think given how many are null (~20% for realistic data sets -- a problem in itself really) the optimizer would have better statistics if there are no null tree_sortkeys. although I guess with postgres partial indexes can make that much less of a problem.

I tracked down the last bottleneck with creating users (and it ends up not being a problem with acs_objects). The problem is with the rel_constraint__violation check in membership_rels_in_tr. The second query in that function is very fast but the first gets much slower as users are added to the system. Here it is:

 for constraint_violated in
     select constraint_id, constraint_name
       from rel_constraints_violated_one
       where rel_id = violation__rel_id
       LIMIT 1 
    LOOP

This is checking for violated rel_constraints with rel_side = 'one' and takes about 2 seconds on my system even though rel_constraints only has one entry (and that with rel_side 'two'):

 constraint_id |               constraint_name               | rel_segment | rel_side | required_rel_segment 
---------------+---------------------------------------------+-------------+----------+----------------------
        924494 | Members of foo must be members of Main Site |      924493 | two      |                  432

In fact I can't find anywhere in the code that anything with rel_side one ever gets created nor does openacs.org or any other site I checked have rel_side 'one' entries.

In any case, the query plan for that seemingly innocuous query is entertainingly horrible:

                                                                                        QUERY PLAN                                                                                        
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Merge Join  (cost=2.04..16701.25 rows=1 width=262) (actual time=1208.71..1208.71 rows=0 loops=1)
   Merge Cond: ("outer".container_id = "inner".element_id)
   Join Filter: ("inner".segment_id = "outer".required_rel_segment)
   Filter: ("inner".element_id IS NULL)
   ->  Nested Loop  (cost=1.02..16310.71 rows=1 width=159) (actual time=1208.71..1208.71 rows=0 loops=1)
         Join Filter: (("inner".object_type = "outer".rel_type) AND ("inner".tree_sortkey >= "outer".tree_sortkey) AND ("inner".tree_sortkey <= tree_right("outer".tree_sortkey)))
         ->  Nested Loop  (cost=1.02..16307.39 rows=1 width=132) (actual time=1208.70..1208.70 rows=0 loops=1)
               Join Filter: ("inner".object_type = "outer".rel_type)
               ->  Nested Loop  (cost=1.02..16304.40 rows=1 width=105) (actual time=1208.70..1208.70 rows=0 loops=1)
                     Join Filter: ("outer".group_id = "inner".group_id)
                     ->  Index Scan using group_elem_idx_container_idx on group_element_index  (cost=0.00..16301.51 rows=2 width=26) (actual time=1067.93..1201.84 rows=2 loops=1)
                           Filter: (rel_id = 129804)
                     ->  Materialize  (cost=2.06..2.06 rows=1 width=79) (actual time=3.43..3.43 rows=0 loops=2)
                           ->  Hash Join  (cost=1.02..2.06 rows=1 width=79) (actual time=6.85..6.85 rows=0 loops=1)
                                 Hash Cond: ("outer".segment_id = "inner".rel_segment)
                                 ->  Seq Scan on rel_segments rs  (cost=0.00..1.02 rows=2 width=23) (actual time=0.03..0.04 rows=6 loops=1)
                                 ->  Hash  (cost=1.01..1.01 rows=1 width=56) (actual time=6.69..6.69 rows=0 loops=1)
                                       ->  Index Scan using jcd_rel_constraint_relside on rel_constraints rel  (cost=0.00..1.01 rows=1 width=56) (actual time=6.68..6.68 rows=0 loops=1)
                                             Index Cond: (rel_side = 'one'::bpchar)
               ->  Seq Scan on acs_object_types o2  (cost=0.00..2.44 rows=44 width=27) (never executed)
         ->  Seq Scan on acs_object_types o1  (cost=0.00..2.44 rows=44 width=27) (never executed)
   ->  Materialize  (cost=3742888.01..3742888.01 rows=67268 width=103) (never executed)
         ->  Nested Loop  (cost=1.02..3742888.01 rows=67268 width=103) (never executed)
               Join Filter: (("outer".tree_sortkey >= "inner".tree_sortkey) AND ("outer".tree_sortkey <= tree_right("inner".tree_sortkey)) AND ("outer".group_id = "inner".group_id))
               ->  Nested Loop  (cost=0.00..1804822.87 rows=598630 width=53) (never executed)
                     Join Filter: ("inner".object_type = "outer".rel_type)
                     ->  Index Scan using group_elem_idx_element_idx on group_element_index  (cost=0.00..14919.17 rows=598630 width=26) (never executed)
                     ->  Seq Scan on acs_object_types o1  (cost=0.00..2.44 rows=44 width=27) (never executed)
               ->  Materialize  (cost=3.71..3.71 rows=2 width=50) (never executed)
                     ->  Hash Join  (cost=1.02..3.71 rows=2 width=50) (never executed)
                           Hash Cond: ("outer".object_type = "inner".rel_type)
                           ->  Seq Scan on acs_object_types o2  (cost=0.00..2.44 rows=44 width=27) (never executed)
                           ->  Hash  (cost=1.02..1.02 rows=2 width=23) (never executed)
                                 ->  Seq Scan on rel_segments rs  (cost=0.00..1.02 rows=2 width=23) (never executed)
 Total runtime: 1209.02 msec
(35 rows)

Maybe someone who actually understands rel_segments (hint Don :) ) can look into why this is so awful. Given how bad the query is it might be worth adding something that checks that any rel_side 'one' constraints exist before running it.

Well, it's easy to see why it's slow ... it's that three-deep nested loop that does an index scan on group_element_index.  That scan's being executed a shitpile of times if it accumulates over a second execution time over the life of the query ...

I'll dig deeper tomorrow, we're dealing with a complex set of nested selects on views.

The second half of the query doesn't suck quite so bad, only a two-deep nested loop ("only?") that in this case isn't executed at all so it runs fast.

In Oracle the biggest caveat with UNIONs is that they have an implicit sort attached: to weed out duplicates Oracle needs to sort the result at some point.

E.g. in permissons where you only want to know that there is a row, not how many, you would use a UNION ALL (which returns duplicates, so it doesn't need to sort)

The same holds true probably for Oracle.

Yes, actually, Jeff and I switched a lot of UNION to UNION ALL  clauses for 4.6.? for this very reason, when it was clear that there was no possibility of duplicate rows.

Thanks for the Oracle reference - Oracle's ability to optimize in the face of UNION is rather limited, indeed.

I created 500k users, but only 6 rel_segments (for main site and 2 subsites), and 2 rel_constraints (one for each subsites). My daughter contributed to the experiment by turning my computer off so yeah, everything has been restarted after a vacuumdb -f -z.

I have a second db (on the same server) with 100k users, 20 rel_segs, and 3 rel_constraints and the query takes .5ms (rather than the 1-2 seconds with the dataset which is 5x larger). Same

I dropped the group_elem_idx_container_idx and on the 500k user db the query dropped to under 1ms and had this plan:

explain analyze select constraint_id, constraint_name from rel_constraints_violated_one where rel_id = 20938;
                                                                                QUERY PLAN                                                                                 
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=26.42..34855.94 rows=1 width=262) (actual time=0.07..0.07 rows=0 loops=1)
   Join Filter: (("inner".segment_id = "outer".required_rel_segment) AND ("inner".element_id = "outer".container_id))
   Filter: ("inner".element_id IS NULL)
   ->  Merge Join  (cost=3.05..10.36 rows=1 width=159) (actual time=0.07..0.07 rows=0 loops=1)
         Merge Cond: ("outer".group_id = "inner".group_id)
         Join Filter: ("outer".object_type = "inner".rel_type)
         ->  Nested Loop  (cost=0.00..17.74 rows=5 width=133) (actual time=0.07..0.07 rows=0 loops=1)
               Join Filter: (("inner".tree_sortkey >= "outer".tree_sortkey) AND ("inner".tree_sortkey <= tree_right("outer".tree_sortkey)))
               ->  Nested Loop  (cost=0.00..14.53 rows=1 width=106) (actual time=0.07..0.07 rows=0 loops=1)
                     Join Filter: ("inner".object_type = "outer".rel_type)
                     ->  Nested Loop  (cost=0.00..11.54 rows=1 width=79) (actual time=0.07..0.07 rows=0 loops=1)
                           Join Filter: ("inner".rel_segment = "outer".segment_id)
                           ->  Index Scan using rel_segments_grp_rel_type_uq on rel_segments rs  (cost=0.00..5.32 rows=6 width=23) (actual time=0.02..0.03 rows=6 loops=1)
                           ->  Seq Scan on rel_constraints rel  (cost=0.00..1.02 rows=1 width=56) (actual time=0.00..0.00 rows=0 loops=6)
                                 Filter: (rel_side = 'one'::bpchar)
                     ->  Seq Scan on acs_object_types o2  (cost=0.00..2.44 rows=44 width=27) (never executed)
               ->  Seq Scan on acs_object_types o1  (cost=0.00..2.44 rows=44 width=27) (never executed)
         ->  Sort  (cost=3.05..3.06 rows=3 width=26) (never executed)
               Sort Key: public.group_element_index.group_id
               ->  Index Scan using group_elem_idx_rel_id_idx on group_element_index  (cost=0.00..3.04 rows=3 width=26) (never executed)
                     Index Cond: (rel_id = 20938)
   ->  Materialize  (cost=33280.71..33280.71 rows=104324 width=103) (never executed)
         ->  Hash Join  (cost=23.36..33280.71 rows=104324 width=103) (never executed)
               Hash Cond: ("outer".rel_type = "inner".object_type)
               Join Filter: ("outer".group_id = "inner".group_id)
               ->  Seq Scan on group_element_index  (cost=0.00..19349.74 rows=927174 width=26) (never executed)
               ->  Hash  (cost=23.29..23.29 rows=29 width=77) (never executed)
                     ->  Nested Loop  (cost=1.07..23.29 rows=29 width=77) (never executed)
                           Join Filter: (("inner".tree_sortkey >= "outer".tree_sortkey) AND ("inner".tree_sortkey <= tree_right("outer".tree_sortkey)))
                           ->  Hash Join  (cost=1.07..4.03 rows=6 width=50) (never executed)
                                 Hash Cond: ("outer".object_type = "inner".rel_type)
                                 ->  Seq Scan on acs_object_types o2  (cost=0.00..2.44 rows=44 width=27) (never executed)
                                 ->  Hash  (cost=1.06..1.06 rows=6 width=23) (never executed)
                                       ->  Seq Scan on rel_segments rs  (cost=0.00..1.06 rows=6 width=23) (never executed)
                           ->  Seq Scan on acs_object_types o1  (cost=0.00..2.44 rows=44 width=27) (never executed)
 Total runtime: 0.29 msec
(36 rows)

It could be thrashing I suppose. I have shared_buffers and 8192 (64MB) which is not as large as it could be (although I intentionally set it a little low since I want to catch performance problems where the db does not fit in memory). I will bump it up and see if it makes a difference.

Maybe we should drop the container_id index since I don't think it ever has particularly a particularly good key distribution and so is hardly ever better than a table scan (it's got 2 distinct values on openacs.org).

Even on sloanspace the two big container_id's make up 35% of the rows in group_element_index.

Do we ever really query on container_id w/o also having a group_id?

Sounds good ... sounds like a brain-fart on the part of the optimizer, sheesh.