I'm in a bit of a mess and could really do with some help please!

We recently upgraded to OpenACS 5.3.2, dotLRN 2.3.1, with Postgresql 8.2.5, Aolserver 4.0.10, tcl 8.4.13.

Server: Red Hat ES 4
Memory: 4GB
Processor: 2X Dual Core Xeon 2.8GHz

Our site makes use of xowiki heavily but we seems to be having massive performance issues compared to before we upgraded and started using Xowiki so much.

The problem seems to be that when there are a few people logged in (8+) when you try to view a page it can take a few seconds to display and seems to hang halfway through, occasionally there are server hangs of 10 seconds during which time it seems as thoguh the server is not responding at all.

There are quite a few variables in play and I'm struggling to narrow it down but I'll try posting as much info as I can in the hope that someone can help me out.

We have 13,000 accounts on the system but there are usually only 10-15 people online at any 1 time.

Next week we will have 200 people online all of the time so this is a bit of a concern!

When executing Top, total memory can be anything between 50% and 90% of 4GB taken at any given time.

This seems to be the business end of the config file:
server parameters:
#
# Server parameters
#
ns_section ns/server/${server}
ns_param directoryfile $directoryfile
ns_param pageroot $pageroot
ns_param maxconnections 150
ns_param maxdropped 0
ns_param maxthreads 60
ns_param minthreads 20
ns_param threadtimeout 3600
ns_param globalstats false ;# Enable built-in statistics
ns_param urlstats false ;# Enable URL statistics
ns_param maxurlstats 1000 ;# Max number of URL's to do stats on
# ns_param directoryadp $pageroot/dirlist.adp ;# Choose one or the ot
her
# ns_param directoryproc _ns_dirlist ;# ...but not both!
# ns_param directorylisting fancy ;# Can be simple or fancy

An extract from the log file is below. As you can see, it is quite busy and this part in particular seems to be a bit concerning, 1240ms + 478ms + 480ms + 491ms seems to be excessive?

[05/Mar/2008:15:57:39][24412.2533358512][-conn:service0::20] Notice: --i ::3551196 DONE, ::3551196 -> (1240ms, 10
97ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --starting... /ezine/competitions/weblog sum
mary=1&date=1999-02-18, ::3551421 -> (478ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --try weblog -> 0, ::3551421 ::xowiki::Packa
ge->resolve_request (480ms, 1ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --try weblog-portlet -> 0, ::3551421 ::xowik
i::Package->resolve_request (491ms, 10ms)


[05/Mar/2008:15:57:36][24412.2815663024][-conn:service0::3] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/xowiki/www/index.vuh uses deprecated property header_stuff instead of head.
[05/Mar/2008:15:57:36][24412.2815663024][-conn:service0::3] Notice: --i ::3551222 DONE, ::3551222 -> (670ms, 406m
s)
[05/Mar/2008:15:57:38][24412.2533358512][-conn:service0::20] Notice: --starting... /campus/home/ , ::3551196 -> (
48ms)
[05/Mar/2008:15:57:38][24412.2533358512][-conn:service0::20] Notice: --try index -> 0, ::3551196 ::xowiki::Packag
e->resolve_request (51ms, 2ms)
[05/Mar/2008:15:57:38][24412.2533358512][-conn:service0::20] Notice: --after options, ::3553858 ::xowiki::Page->v
iew (143ms, 92ms)
[05/Mar/2008:15:57:39][24412.2533358512][-conn:service0::20] Warning: blank-compat: /var/lib/aolserver/nccedudotl
rn/packages/xowiki/www/index.vuh uses deprecated property title instead of doc(title).
[05/Mar/2008:15:57:39][24412.2533358512][-conn:service0::20] Warning: blank-compat: /var/lib/aolserver/nccedudotl
rn/packages/xowiki/www/index.vuh uses deprecated property header_stuff instead of head.
[05/Mar/2008:15:57:39][24412.2533358512][-conn:service0::20] Notice: --i ::3551196 DONE, ::3551196 -> (1240ms, 10
97ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --starting... /ezine/competitions/weblog sum
mary=1&date=1999-02-18, ::3551421 -> (478ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --try weblog -> 0, ::3551421 ::xowiki::Packa
ge->resolve_request (480ms, 1ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --try weblog-portlet -> 0, ::3551421 ::xowik
i::Package->resolve_request (491ms, 10ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --W starting, ::xotcl::__#m ::xowiki::Weblog
->init (495ms, 4ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Warning: db_qd_get_fullname: there is no documented
proc with name xowiki::init returning dbqd..NULL (declare proc xowiki::init with ad_proc to make it work with the que
ry dispatcher
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --W done, ::xotcl::__#m ::xowiki::Weblog->in
it (582ms, 87ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --try categories-portlet -> 0, ::3551421 ::x
owiki::Package->resolve_request (642ms, 59ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Warning: db_qd_get_fullname: there is no documented
proc with name 3552051::content returning dbqd..NULL (declare proc 3552051::content with ad_proc to make it work with
the query dispatcher
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Notice: --after options, ::3552049 ::xowiki::Page->v
iew (759ms, 117ms)
[05/Mar/2008:15:57:41][24412.2531253168][-conn:service0::22] Warning: blank-compat: /var/lib/aolserver/nccedudotl
rn/packages/xowiki/www/index.vuh uses deprecated property title instead of doc(title).
[05/Mar/2008:15:58:00][24412.2809346992][-conn:service0::9] Notice: --starting... /campus/home/ , ::3551196 -> (7
0ms)
[05/Mar/2008:15:58:00][24412.2809346992][-conn:service0::9] Notice: --try index -> 0, ::3551196 ::xowiki::Package
->resolve_request (72ms, 2ms)
[05/Mar/2008:15:58:00][24412.2809346992][-conn:service0::9] Notice: --after options, ::3553858 ::xowiki::Page->vi
ew (162ms, 89ms)
[05/Mar/2008:15:58:00][24412.2809346992][-conn:service0::9] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/xowiki/www/index.vuh uses deprecated property title instead of doc(title).
[05/Mar/2008:15:58:00][24412.2809346992][-conn:service0::9] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/xowiki/www/index.vuh uses deprecated property header_stuff instead of head.
[05/Mar/2008:15:58:01][24412.2809346992][-conn:service0::9] Notice: --i ::3551196 DONE, ::3551196 -> (1589ms, 142
7ms)
[05/Mar/2008:15:58:08][24412.2817768368][-conn:service0::1] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/acs-subsite/www/pvt/home.adp uses deprecated property title instead of doc(title).
[05/Mar/2008:15:58:08][24412.2817768368][-conn:service0::1] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/acs-subsite/www/pvt/home.adp uses deprecated property header_stuff instead of head.
[05/Mar/2008:15:58:08][24412.2817768368][-conn:service0::1] Warning: blank-compat: property focus is deprecated i
n blank-master - focus should be handled in site-master.
[05/Mar/2008:15:58:24][24412.2532305840][-conn:service0::21] Warning: blank-
compat: /var/lib/aolserver/service0/packages/acs-subsite/www/user/password-update.adp uses deprecated property ti
tle instead of doc(title).
[05/Mar/2008:15:58:24][24412.2532305840][-conn:service0::21] Warning: blank-compat: /var/lib/aolserver/nccedudotl
rn/packages/acs-subsite/www/user/password-update.adp uses deprecated property header_stuff instead of head.
[05/Mar/2008:15:58:24][24412.2532305840][-conn:service0::21] Warning: blank-compat: property focus is deprecated
in blank-master - focus should be handled in site-master.
[05/Mar/2008:15:58:29][24412.2814610352][-conn:service0::4] Notice: --starting... /campus/facultyzone/ , ::355111
8 -> (27ms)
[05/Mar/2008:15:58:29][24412.2814610352][-conn:service0::4] Notice: --try index -> 0, ::3551118 ::xowiki::Package
->resolve_request (29ms, 2ms)
[05/Mar/2008:15:58:30][24412.2814610352][-conn:service0::4] Notice: --after options, ::3551878 ::xowiki::Page->vi
ew (269ms, 239ms)
[05/Mar/2008:15:58:30][24412.2814610352][-conn:service0::4] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/xowiki/www/index.vuh uses deprecated property title instead of doc(title).
[05/Mar/2008:15:58:30][24412.2814610352][-conn:service0::4] Warning: blank-compat: /var/lib/aolserver/service0
n/packages/xowiki/www/index.vuh uses deprecated property header_stuff instead of head.
[05/Mar/2008:15:58:30][24412.2814610352][-conn:service0::4] Notice: --i ::3551118 DONE, ::3551118 -> (517ms, 248m
s)
[05/Mar/2008:15:58:40][24412.2817768368][-conn:service0::1] Warning: blank-compat: /var/lib/aolserver/service0

Let me know if you need any more info please!

Thanks in advance,
Matthew

The CPU is barely getting above 5-20% use.

It's almost as if when one person makes a request everyone else has to wait for their request before anything else happens.

From Postgresql conf
max_connections = 100
#---------------------------------------------------------------------------
# RESOURCE USAGE (except WAL)
#---------------------------------------------------------------------------

# - Memory -

shared_buffers = 32MB # min 128kB or max_connections*16kB
# (change requires restart)
#temp_buffers = 8MB # min 800kB
#max_prepared_transactions = 5 # can be 0 or more
# (change requires restart)
# Note: increasing max_prepared_transactions costs ~600 bytes of shared memory
# per transaction slot, plus lock space (see max_locks_per_transaction).
#work_mem = 1MB # min 64kB
#maintenance_work_mem = 16MB # min 1MB
#max_stack_depth = 2MB # min 100kB

# - Free Space Map -

max_fsm_pages = 204800 # min max_fsm_relations*16, 6 bytes each
# (change requires restart)
#max_fsm_relations = 1000 # min 100, ~70 bytes each
# (change requires restart)
.
.
.



These seem to take an age considering the CPU is so idle?

[05/Mar/2008:16:22:27][24412.2803030960][-conn:service0::15] Notice: --i ::3551196 DONE, ::3551196 -> (4774ms, 38
5ms)
[05/Mar/2008:16:22:36][24412.2806188976][-conn:service0::12] Notice: --starting... /campus/myprogramme/ , ::35512
22 -> (2806ms)
[05/Mar/2008:16:22:36][24412.2806188976][-conn:service0::12] Notice: --try index -> 0, ::3551222 ::xowiki::Packag
e->resolve_request (2809ms, 2ms)
[05/Mar/2008:16:22:36][24412.2806188976][-conn:service0::12] Notice: --after options, ::3551914 ::xowiki::Page->v
iew (3022ms, 213ms)

You should also check if max connections in each pool is too low, we had that problem and requests had to be queued making the user wait until one connection was available

Also if you have developer support instaled check what is consuming more time in the page load.

From: http://openacs.org/xowiki/postgresql-admin

I take it we need to increase this value too?
What would you recommend?

#Change the kernel parameter for maximum shared memory segment size to 128Mb: DAVEB: How current is this? Do modern 2.4 or 2.6 kernels have such low settings? This is highly dependent also on the amount of RAM on your server, most realy servers have gigabytes of RAM so adjust accordingly.

[root root]# echo 134217728 >/proc/sys/kernel/shmmax
[root root]#

Make that change permanent by editing /etc/sysctl.conf to add these lines at the end:

# increase shared memory limit for postgres
kernel.shmmax = 134217728

What value would you recommend for that if I'm going for 128MB in the shared buffers?

This is the correct setting

# increase shared memory limit for postgres
kernel.shmmax = 134217728

for 128mb.

connections is way to low, I'd try with at least 20 in each pool and if it starts getting very slow with more users raise it at once.

Also keep in mind you have it 100 connections configured in postgres, so if you raise it over 33 you'll have to change the value in postgres also

We started off with the Zen theme and added some extra stuff, not too much but possibly some bad code!

What you explain about the wait before it becomes active is exactly how it feels, you click on a link and then it takes a few seconds before you get any sort of response from the system. It's very strange.

From developer support these are the database queries that run on our master template. Some of them seem to take an excessive amount of time...

0 ms gethandle gethandle (returned pool2)
389 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'read' )


1 ms 0or1row dbqd.-lookup.entry_exists_select: 0or1row nsdb0

select item_id from cr_items where name = 'index' and parent_id = '3551907'

1 ms 0or1row dbqd.-lookup.entry_exists_select: 0or1row nsdb0

select item_id from cr_items where name = 'en:index' and parent_id = '3551907'

17 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '-4' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


1 ms select dbqd.::xowiki::portlet::my-references-render.get_references: select nsdb0

SELECT page,ci.name,f.package_id from xowiki_references,cr_items ci,cr_folders f where reference=3553858 and ci.item_id = page and ci.parent_id = f.folder_id

1 ms getrow getrow nsdb0

1 ms select dbqd.categories.tcl.categories-procs.category::get_mapped_categories.get_mapped_categories: select nsdb0


select category_id
from category_object_map
where object_id = '3553858'



0 ms getrow getrow nsdb0

2 ms dml dbqd.::xowiki::Page-record_last_visited.update_last_visisted: dml nsdb0

update xowiki_last_visited set time = current_timestamp, count = count + 1 where page_id = 3553858 and user_id = 14554

1 ms 0or1row dbqd.views.tcl.views-procs.views::record_view.record_view: 0or1row nsdb0

select views__record_view('3553858', '14554')

1 ms 0or1row dbqd.views.tcl.views-procs.views::get.views: 0or1row nsdb0

SELECT views, unique_views, to_char(last_viewed,'YYYY-MM-DD HH24:MI:SS') as last_viewed
FROM view_aggregates
WHERE object_id = '3553858'


170 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'write' )


18 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


23 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'create' )


17 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '109968' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


2 ms 0or1row dbqd.dotlrn.tcl.community-procs.dotlrn_community::member_p.select_count_membership: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_member_rels_approved
where community_id = '3225'
and user_id = '14554')


3 ms 0or1row dbqd.dotlrn.tcl.dotlrn-security-procs.dotlrn::user_p.select_count: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_users
where user_id = '14554')


3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1303' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


3 ms 0or1row dbqd.dotlrn.tcl.dotlrn-security-procs.dotlrn::user_p.select_count: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_users
where user_id = '14554')


1 ms select dbqd.theme-campus.tcl.navigation-procs.campus::portal_subnavbar.list_page_nums_select: select nsdb0

select pretty_name, accesskey, sort_key
from portal_pages
where portal_id = null and hidden_p = 'f'
order by sort_key


0 ms getrow getrow nsdb0

18 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '344' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


18 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '14554' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


412 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551056' and ppm.party_id = '14554' and ppm.privilege = 'read' )


23 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551056' and ppm.party_id = '14554' and ppm.privilege = 'create' )


10 ms select dbqd.weblogger-portlet.www.weblogger-portlet-front-page.entries: select nsdb0

select e.entry_id,
acs_object__name(apm_package__parent_id(e.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = e.package_id) as base_url,
e.title,
e.content,
u.first_names as poster_first_names,
u.last_name as poster_last_name,
to_char(e.entry_date , 'HH24:MI') as posted_time_pretty,
p.package_id
from apm_packages p left outer join
pinds_blog_entries e on (e.package_id = p.package_id) join
acs_objects o on (o.object_id = e.entry_id) join
acs_users_all u on (u.user_id = o.creation_user)
where p.package_id in (3551056)

and e.draft_p = 'f'
and e.deleted_p = 'f'
order by p.package_id asc, e.entry_date desc, e.entry_date desc


0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

0 ms getrow getrow nsdb0

1,136 Total Duration (ms)

I have kernel.shmmax set to 134217728 but then when I try to set shared_buffers to 128MB in the PostgreSQL config it won't start the postgresql service again?

How can I find out more information about what query this is? 408ms is a loooong time for every page impression.


408 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'read' )

=# \d acs_permissions
Table "public.acs_permissions"
Column | Type | Modifiers
------------+------------------------+-----------
object_id | integer | not null
grantee_id | integer | not null
privilege | character varying(100) | not null
Indexes:
"acs_permissions_pk" PRIMARY KEY, btree (object_id, grantee_id, privilege)
"acs_permissions_grantee_idx" btree (grantee_id)
"acs_permissions_object_id_idx" btree (object_id)
"acs_permissions_privilege_idx" btree (privilege)
Foreign-key constraints:
"acs_permissions_grantee_id_fk" FOREIGN KEY (grantee_id) REFERENCES parties(party_id)
"acs_permissions_on_what_id_fk" FOREIGN KEY (object_id) REFERENCES acs_objects(object_id)
"acs_permissions_priv_fk" FOREIGN KEY (privilege) REFERENCES acs_privileges(privilege)


=# select count(*) from acs_permissions;
count
--------
193374
(1 row)

=# \d acs_object_context_index
Table "public.acs_object_context_index"
Column | Type | Modifiers
---------------+---------+-----------
object_id | integer | not null
ancestor_id | integer | not null
n_generations | integer | not null
Indexes:
"acs_object_context_index_pk" PRIMARY KEY, btree (object_id, ancestor_id)
"acs_obj_ctx_idx_ancestor_idx" btree (ancestor_id)
Check constraints:
"acs_obj_context_idx_n_gen_ck" CHECK (n_generations >= 0)
Foreign-key constraints:
"acs_obj_context_idx_anc_id_fk" FOREIGN KEY (ancestor_id) REFERENCES acs_objects(object_id)
"acs_obj_context_idx_obj_id_fk" FOREIGN KEY (object_id) REFERENCES acs_objects(object_id)


n=# select count(*) from acs_object_context_index;
count
--------
859795
(1 row)


=# \d acs_privilege_descendant_map
Table "public.acs_privilege_descendant_map"
Column | Type | Modifiers
------------+------------------------+-----------
privilege | character varying(100) | not null
descendant | character varying(100) | not null
Indexes:
"acs_priv_desc_map_idx" btree (descendant)
Foreign-key constraints:
"acs_priv_hier_child_priv_fk" FOREIGN KEY (descendant) REFERENCES acs_privileges(privilege)
"acs_priv_hier_priv_fk" FOREIGN KEY (privilege) REFERENCES acs_privileges(privilege)


=# select count(*) from acs_privilege_descendant_map;
count
-------
309
(1 row)

zen is no performance bottleneck, it won't affect the speed of permissions at all.

we have on our learn system more than 10 times the number of entries in the permission tables, and much better speed (most time below 1ms, with up to 2000 concurrently active users; but we have also a different hardware).

The indices you have are correct, these are the indices of the standard openacs installation.

We have on our productive environment two indices more:
Try to add these:

create index acs_privilege_descendant_map_privilege_idx on acs_privilege_descendant_map (privilege);

create index acs_object_context_index_object_id_idx on acs_object_context_index (object_id);

after creating the indices, do a "VACUUM " on both tables.

measure again. It is a while, since i have added these indices. They might be an artefact of our local modifications. if they don't not help, remove the indices again.

Matthew if the shhmax is set try using less than 128mb shared buffers to see if that works.
ie: try 64mb or 96mb.

I changed shared buffers to 96MB and check this out:

Total query time for db transactions:
58 Total Duration (ms)

Before it was:
1,136 Total Duration (ms)

0 ms gethandle gethandle (returned pool2)
4 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'read' )


1 ms 0or1row dbqd.-lookup.entry_exists_select: 0or1row nsdb0

select item_id from cr_items where name = 'index' and parent_id = '3551907'

1 ms 0or1row dbqd.-lookup.entry_exists_select: 0or1row nsdb0

select item_id from cr_items where name = 'en:index' and parent_id = '3551907'

2 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '-4' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


1 ms select dbqd.::xowiki::portlet::my-references-render.get_references: select nsdb0

SELECT page,ci.name,f.package_id from xowiki_references,cr_items ci,cr_folders f where reference=3553858 and ci.item_id = page and ci.parent_id = f.folder_id

0 ms select dbqd.categories.tcl.categories-procs.category::get_mapped_categories.get_mapped_categories: select nsdb0


select category_id
from category_object_map
where object_id = '3553858'



3 ms dml dbqd.::xowiki::Page-record_last_visited.update_last_visisted: dml nsdb0

update xowiki_last_visited set time = current_timestamp, count = count + 1 where page_id = 3553858 and user_id = 14554

1 ms 0or1row dbqd.views.tcl.views-procs.views::record_view.record_view: 0or1row nsdb0

select views__record_view('3553858', '14554')

1 ms 0or1row dbqd.views.tcl.views-procs.views::get.views: 0or1row nsdb0

SELECT views, unique_views, to_char(last_viewed,'YYYY-MM-DD HH24:MI:SS') as last_viewed
FROM view_aggregates
WHERE object_id = '3553858'


2 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'write' )


2 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551196' and ppm.party_id = '14554' and ppm.privilege = 'create' )


3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '109968' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


2 ms 0or1row dbqd.dotlrn.tcl.community-procs.dotlrn_community::member_p.select_count_membership: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_member_rels_approved
where community_id = '3225'
and user_id = '14554')


6 ms 0or1row dbqd.dotlrn.tcl.dotlrn-security-procs.dotlrn::user_p.select_count: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_users
where user_id = '14554')


3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1303' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


2 ms 0or1row dbqd.dotlrn.tcl.dotlrn-security-procs.dotlrn::user_p.select_count: 0or1row nsdb0

select count(*)
from dual
where exists (select 1
from dotlrn_users
where user_id = '14554')


1 ms select dbqd.theme-campus.tcl.navigation-procs.campus::portal_subnavbar.list_page_nums_select: select nsdb0

select pretty_name, accesskey, sort_key
from portal_pages
where portal_id = null and hidden_p = 'f'
order by sort_key


3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '344' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


2 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '14554' and ppm.party_id = '14554' and ppm.privilege = 'admin' )


2 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551056' and ppm.party_id = '14554' and ppm.privilege = 'read' )


3 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb0

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '3551056' and ppm.party_id = '14554' and ppm.privilege = 'create' )


10 ms select dbqd.weblogger-portlet.www.weblogger-portlet-front-page.entries: select nsdb0

select e.entry_id,
acs_object__name(apm_package__parent_id(e.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = e.package_id) as base_url,
e.title,
e.content,
u.first_names as poster_first_names,
u.last_name as poster_last_name,
to_char(e.entry_date , 'HH24:MI') as posted_time_pretty,
p.package_id
from apm_packages p left outer join
pinds_blog_entries e on (e.package_id = p.package_id) join
acs_objects o on (o.object_id = e.entry_id) join
acs_users_all u on (u.user_id = o.creation_user)
where p.package_id in (3551056)

and e.draft_p = 'f'
and e.deleted_p = 'f'
order by p.package_id asc, e.entry_date desc, e.entry_date desc


58 Total Duration (ms)

Yes, I'm feeling a bit better about it now!

I'm going to play around with the values next week and try to optimise the performance even further. We're upping to 10GB of RAM in the server next week so I should be able to increase it even more.

SHMMAX was the only problem still outstanding. I'm going to try doubling that figure and then increase the Shared Buffers accordingly.

There are so many variables to consider when upgrading it's almost like starting all over again!

I'll try the ipcs-m and ipcs-ml commands when I get back to the office and report back. hopefully this thread will be useful for others wanting to optimise postgres performance.

Thank you so much for all of the replies to this post. Without you all putting in the time this project wouldn't be so successful.

Matthew

Is more related to your applications and how many nested queries (api-db-calls) you run.

Gustaf, when you mention "i would as well recommend to set maxidle and maxopen to 0, but this does not have to do with your performace problems"; can you elaborate why?

Many thanks Gustaf. That makes sense. Thanks for taking the time to respond.

Brian