Forum OpenACS Development: OpenACS Performance Tests

Collapse
Posted by Eduardo Santos on
Hi everybody,

We have a lot of documentation about OpenACS performance tests, most of them including number of threads X connections X database (PostgreSQL parameters). Right now we are moving our Portal (www.softwarepublico.gov.br) to a new hardware and we are trying to discover a new performance relation. Assuming that most people in the community are interested on that, we are calling everybody to help us in the tests and give some hints, so we can produce some kind of "performance howto" that is going to be in the OpenACS website at the end (maybe we can create a XoWiki page).

<h2>Environment</h2>
Our hardware is an IBM X3550 series like this:

08 Gb Ram
01 hd SAS 176Gb
2 redes Gigabit
Pentium Zion quadcore 1.6GHZ

We have an OpenACS + dotLRN + XoWiki + Subsites application, where most of our public pages are XoWiki, wich I can see consums a lot of database resources. The versions are:

AOLServer 4.5.0 patched for background delivery (cognovis patches)
PostgreSQL 8.2.7
OpenACS 5.3.2
dotLRN 2.3.1
XoTcl Core 0.56.3
XoWiki 0.60

<h2>Metodology</h2>
We are going to use JMeter to simulate Portal navigation. We've chosen JMeter because we can create a navigation sequence, such as start page -> login -> community page. As we don't know the best sequence to evaluate the performance, we hope you an help us on that.

There's also XoTCL Request Monitor installed, so we can see request time average and any other things tha package let us do.

<h2>References</h2>
We have already studied the following documentation before the tests:

http://www.openacs.org/forums/message-view?message_id=1458697
http://www.mail-archive.com/aolserver@listserv.aol.com/msg09542.html
http://www.mail-archive.com/aolserver@listserv.aol.com/msg10976.html
http://www.openacs.org/forums/message-view?message_id=1146218
https://openacs.org/forums/message-view?message_id=340233
http://www.openacs.org/forums/message-view?message_id=392054

Maybe somebody can supply any other links if they have. We also have some PostgreSQL community folks to help us on DB configuration, if it's necessary. We are aware of AOLServer 4.5.0 thread pool change and the file acs-tcl/tcl/pools-init.tcl is present.

The DB and Application are going to be on the same machine, at least for now. If we come to a conclusion that this is not good enough for us, we'll have a separated DB machine.

<h2>Goals</h2>
We have one simple goal to achieve: take as much as we can from the machine: maximum memory usage, maximum processor usage, maximum simultaneos users, less response time for that. Our preliminary tests are done in order to get a good performance with about 100 users navigating (not exactly 100 simultaneous requests), but we want to go to up 1000 users.

We also want to help everybody in the community to diagnose performance problems and have a single document where they can do it.

<h2>Preliminary tests</h2>
The test machine is available on the Internet at the address http://teste2.softwarepublico.gov.br. If somebody want to really join us on that, we can also supply admin access to the machine.

In our first test tries, we have the following config.tcl tuning part:

-- First tuning section --
ns_section ns/threads
    ns_param   mutexmeter         true      ;# measure lock contention
    # The per-thread stack size must be a multiple of 8k for AOLServer to run under MacOS X
    ns_param   stacksize          [expr 1 * 8192 * 256]

-- Second tuning section -- ns_section ns/servers ns_param $server $servername

# # Server parameters # ns_section ns/server/${server} ns_param directoryfile $directoryfile ns_param pageroot $pageroot ns_param maxconnections 250 ;# Max connections to put on queue ns_param maxdropped 0 ns_param maxthreads 100 ;# Tune this to scale your server ns_param minthreads 80 ;# Tune this to scale your server ns_param threadtimeout 120 ;# Idle threads die at this rate ns_param globalstats false ;# Enable built-in statistics ns_param urlstats true ;# 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 other # ns_param directoryproc _ns_dirlist ;# ...but not both! # ns_param directorylisting fancy ;# Can be simple or fancy

-- DB tuning section --

ns_section ns/db/pools ns_param pool1 "Pool 1" ns_param pool2 "Pool 2" ns_param pool3 "Pool 3"

ns_section ns/db/pool/pool1 ns_param maxidle 1000000000 ns_param maxopen 1000000000 ns_param connections 50 ns_param verbose $debug ns_param extendedtableinfo true ns_param logsqlerrors $debug if { $database == "oracle" } { ns_param driver ora8 ns_param datasource {} ns_param user $db_name ns_param password $db_password } else { ns_param driver postgres ns_param datasource ${db_host}:${db_port}:${db_name} ns_param user $db_user ns_param password "" }

ns_section ns/db/pool/pool2 ns_param maxidle 1000000000 ns_param maxopen 1000000000 ns_param connections 10 ns_param verbose $debug ns_param extendedtableinfo true ns_param logsqlerrors $debug if { $database == "oracle" } { ns_param driver ora8 ns_param datasource {} ns_param user $db_name ns_param password $db_password } else { ns_param driver postgres ns_param datasource ${db_host}:${db_port}:${db_name} ns_param user $db_user ns_param password "" }

ns_section ns/db/pool/pool3 ns_param maxidle 1000000000 ns_param maxopen 1000000000 ns_param connections 10 ns_param verbose $debug ns_param extendedtableinfo true ns_param logsqlerrors $debug if { $database == "oracle" } { ns_param driver ora8 ns_param datasource {} ns_param user $db_name ns_param password $db_password } else { ns_param driver postgres ns_param datasource ${db_host}:${db_port}:${db_name} ns_param user $db_user ns_param password "" }

ns_section ns/server/${server}/db ns_param pools "*" ns_param defaultpool pool1

PostgreSQL parameters:

max_connections = 200           # (change requires restart)
#---------------------------------------------------------------------------
# RESOURCE USAGE (except WAL)
#---------------------------------------------------------------------------

# - Memory -

shared_buffers = 1500MB # 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 = 8MB # min 64kB #maintenance_work_mem = 16MB # min 1MB max_stack_depth = 5MB # min 100kB

# - Free Space Map -

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

# - Kernel Resource Usage -

#max_files_per_process = 1000 # min 25 # (change requires restart) #shared_preload_libraries = '' # (change requires restart)

#--------------------------------------------------------------------------- # QUERY TUNING #---------------------------------------------------------------------------

# - Planner Method Configuration -

#enable_bitmapscan = on enable_hashagg = on enable_hashjoin = on enable_indexscan = on enable_mergejoin = on enable_nestloop = on enable_seqscan = on enable_sort = on enable_tidscan = on

So, if you want to have a little bit of fun, be welcome to join us :)

Cheers

Collapse
Posted by Eduardo Santos on
Just some corrections. The hardware has a Dual Xeon Dualcore 1.6 GHZ and the HD is a 146GB SAS.

The first tests with 100 simultaneous connections in the start page using JMeter had a top of 7900ms response time and an average 2500ms. With 1000 simultaneous connections we had 9000ms top and 4000ms average.

Does anybody have a better test case with JMeter?

Collapse
Posted by Dave Bauer on
You said:

The first tests with 100 simultaneous connections in the start page using JMeter had a top of 7900ms response time and an average 2500ms. With 1000 simultaneous connections we had 9000ms top and 4000ms average.

Does that mean average response was 2.5 seconds with 100 connections?

If so the next step is to figure out where the bottleneck is. You should be under 1 second, and 7.9 seconds is totally unacceptable.

When the test is running what is the load like? How much memory is nsd and postgres using, how much cpu etc?

Offhand I am not sure if 50 connections for the main pool is enough for 100 simultaneous connections or not. Depends on how long the queries run, but a standard request does quite a few queries so, the threads might be waiting for open postgres connections.

It looks like you have MORE than enough shared buffers at 1.5G. The work_mem is 8mb. That is probably enough for most queries that would be found on a community home page.

Collapse
Posted by Eduardo Santos on
Hi Dave,

Thank you for the answers. I can say that this average response time is unacceptable. There's something very interesting about response time: when I look at the XoTcl request monitor page, the average response time is about 200ms with 100 simultaneous connections, but JMeter shows me (instantly) tops of 7900ms and average 2500ms (yes, 2.5s). I don't know where this difference comes from. Maybe somebody who knows the package better can tell how it measures the average.

However, even with this response time, I could navigate with no problems. It was a little bit slow, but nothing impossible to use. In the other hand, with 1000 simultaneous connections it was impossible to navigate.

About the db pools, I think we have a problem here. No matter how much I raise this umber, I can only see in htop something between 20 and 23 connections at the DB. Maybe this has something to do with AOLServer 4.5.0 thread pools change. Can somebody confirm that?

When I'm running JMeter, I can see all the processors with 100% (four processors) and I'm using only 4GB RAM on the machine. It seems like I can't make the machine use more memory, and that's why I've increased shared_buffers to 1.5GB.

Maybe I have to find a more clever way to track queries elapsed time. I'm going to install ptop, but I don't know if that's good enough. Does anybody know a better tool?

Collapse
Posted by Gustaf Neumann on
eduardo
when I look at the XoTcl request monitor page, the average response time is about 200ms with 100 simultaneous connections, but JMeter shows me (instantly) tops of 7900ms and average 2500ms (yes, 2.5s).

the xotcl-request-monitor measures the time between request-start and request-end but it does not know the time the request was sitting in the socket or driver queue. There is a bug in the released aolserver 4.5, that i have fixed in the head version of aolserver 4.5 in Oct 2007. If aolserver is swamped with more requests than it can process, these requests can pile up in a queue. This happens easily when running out of resources (e.g. only a few connection threads are defined, or in benchmark situations).

You should try the head version of aolserver 4.5.

From the config-file i see that you have defined maxthreads=100 and in your first pool the connections 50. This value is too small (make it as well 90 or 100), otherwise the connection threads will have to wail for the db-connection.

see below for some other small changes that i would recommend, which will not impact your performance much.

another question: did you compile tcl+aolserver and postgres with 64bit?

what are the queries you are benchmarking?

-gustaf neumann

===========================
...
ns_param maxconnections 250 ;# Max connections to put on queue
ns_param threadtimeout 120 ;# Idle threads die at this rate
--->
ns_param maxconnections 5000 ;# Max connections to put on queue
ns_param threadtimeout 120 ;# Idle threads die at this rate
...

...
ns_param maxidle 1000000000
ns_param maxopen 1000000000
--->
# ns_param maxidle 0
# ns_param maxopen 0
...

Collapse
Posted by Eduardo Santos on
Hi Gustaf,

Thank you very much for your answers. They are being very helpfull, as allways.

We really have a problem in measurement here. I guess JMeter results will be more accurate in response time, because it can track all the time that the request is stucked. Do you think this diference between JMeter and XoTcl Request Monitor could be an I/O problem? I'm sorry if this looks like a silly question, but I'm still learning this thing.

Concerning AOLServer, I've been following the discussions in the mail list and I've realized that it has some performance problems that people are fixing. So I've checked it out from CVS using Cognovis script, like this:


cvs -z3 -d:pserver:mailto:anonymous@aolserver.cvs.sourceforge.net:/cvsroot/aolserver co aolserver

I can say I have the latest version. Do you know how I can check the source code to make sure your patches are there?

About the threads, I can see some kind of problem, maybe even a bug in thread pools definition for AOLServer 4.5.0: no matter how much I increase the number of connections in pool1, I can only see something between 20 and 23 DB connections. This makes me thing the parameter change is not working. Do you know how can I confirm that?

Your last consideration is maybe the most important: I don't know if AOLServer is compiled for 64 bits. I used Cognovis script, so I can assume it's not compiled for 64 bits. Is that right? Do you know where I can find some documentation about how to do it?

PostgreSQL is compiled for 64 bits, I'm sure, because it was installed from backports.org postgresql-8.2 package. I forgot to mention that my OS is Debian Etch.

Last question: what are these parameters maxidle e maxopen for?

Thank you again for your help.

Collapse
Posted by Gustaf Neumann on
The fixes were not only about performance, but as well for stuck servers. By the mentioned cvs command, you should get the head version. The head version does not need the fixes for bgdelivery, since they are already included.

just by guessing i would not be surprised if your are not get more than 10 to 15 connections threads, since most likely, maxthreads is not used. If this is true, you don't need more db-connections.

Add the following script (from Tom Jacksons pool.tcl) to the end of your config file, which takes the old style configuration and uses the 4.5 ns_pools command.

 set cfgsection "ns/server/[ns_info server]"
 set minthreads [ns_config $cfgsection minthreads 0]
 set maxthreads [ns_config $cfgsection maxthreads 10]
 set maxconns [ns_config $cfgsection maxconnections 0]
 set timeout [ns_config $cfgsection threadtimeout 0]
 ns_pools set default -minthreads $minthreads -maxthreads $maxthreads -maxconns $maxconns -timeout $timeout

If you use e.g. 100 connection threads, and you load dotlrn, then you won't be able to run this in 32bit mode (2 GB). In this case, you have to go to 64 bit (necessary for everything, except the postgres server). For compiling e.g. Tcl, you have to configure with "--enable-64bit". I have no idea, what's available in debian etch in 64 bit.

In order to figure out, if a binary (e.g. nsd) or a library (.so, .o) was compiled with 64bit, try the "file" command.

maxidle and maxopen are timeout values, necessary as bugfix for ancient versions of aolserver, obsolete since a few years, but passed from config file to config file.

Collapse
Posted by Eduardo Santos on
Hi everybody,

Now I think we are getting somehwere. We've followed Gustaf's instructions and recompile AOLServer 4.5.0 (HEAD version) to 64 bits. There were some errors in the configure command, but it semms to be Ok (at least the file command shows me 64bit .so files).

We'repeated the tests with the same configuration as before, but the perfomance didn't seem to improve, and I still had the same problem: DB number of connections didn't raise. SO, I've changed the config.tcl to the following parameters:


ns_section ns/server/${server}
ns_param directoryfile $directoryfile
ns_param pageroot $pageroot
ns_param maxconnections 250 ;# Max connections to put on queue
ns_param maxdropped 0
ns_param maxthreads 120 ;# Tune this to scale your server
ns_param minthreads 100 ;# Tune this to scale your server
ns_param threadtimeout 120 ;# Idle threads die at this rate
ns_param globalstats false ;# Enable built-in statistics
ns_param urlstats true ;# Enable URL statistics
ns_param maxurlstats 1000 ;# Max number of URL's to do stats on

ns_section ns/db/pool/pool1
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 80

ns_section ns/db/pool/pool2
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 40

ns_section ns/db/pool/pool3
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 40

The changes in pool2 and pool3 made the connections number in DB jump from 23 to 48 DB connections. It seemed like we did somethig right and we changed the pool numbers to this:


ns_section ns/db/pool/pool1
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 100

ns_section ns/db/pool/pool2
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 80

ns_section ns/db/pool/pool3
ns_param maxidle 1000000000
ns_param maxopen 1000000000
ns_param connections 80

With these changes the DB connections jumped to 160 and the response time is almost good (1200ms average). So, I could understand that the changes in pool1 didn't raise the number of connections in DB, but changes in pool2 and pool3 did changed it.

Knowing that, I've performed another test:

  • Fired JMeter with 100 simultaneous connections 100 times in a row
  • Enabled DB statics in Developer Support
  • Tried to access the / (XoWiki page)
  • Tried to access the /dotlrn
  • Checked DS results

<h2>Results fo / (XoWiki page)</h2>

0 ms gethandle gethandle (returned pool2)
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 = '462' and ppm.party_id = '507' 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 = '4368'

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

select item_id from cr_items where name = 'pt:index' and parent_id = '4368'

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 = '507' 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 = '1553' and ppm.party_id = '507' 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 = '2791' and ppm.party_id = '507' 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 = '3900' and ppm.party_id = '507' and ppm.privilege = 'create' )

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 = '3900' and ppm.party_id = '507' and ppm.privilege = 'admin' )

1 ms select dbqd.lars-blogger.www.blog.categories: select nsdb0

select *
from pinds_blog_categories
where package_id = '3900'

23 ms select dbqd.lars-blogger.www.blog.blog: select nsdb0

select entry_id,
entry_date,
to_char(entry_date, 'YYYY-MM-DD HH24:MI:SS')
as entry_date_ansi,
to_char(current_timestamp,'YYYY-MM-DD HH24:MI:SS')
as sysdate_ansi,
e.title,
e.title_url,
e.category_id,
com.category_id as sw_category_id,
content,
content_format,
draft_p,
p.first_names as poster_first_names,
p.last_name as poster_last_name,
o.creation_user as user_id,
(select count(gc.comment_id)
from general_comments gc,
cr_revisions cr
where gc.object_id = entry_id
and content_item__get_live_revision(gc.comment_id) =
cr.revision_id) as num_comments
from pinds_blog_entries e
join acs_objects o on (o.object_id = e.entry_id)
join persons p on (p.person_id = o.creation_user)
left outer join category_object_map com
on (com.object_id = e.entry_id)

where e.package_id = '3900'

and draft_p = 'f'
and deleted_p = 'f'

order by entry_date desc, entry_id, com.category_id

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 = '4020053' and ppm.party_id = '507' and ppm.privilege = 'write' )

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 = '3965018' and ppm.party_id = '507' and ppm.privilege = 'write' )

27 ms select dbqd.xowiki.www.portlets.noticias-comunidades.blog: select nsdb0

select entry_id,
entry_date,
e.package_id as package_id,
to_char(entry_date, 'YYYY-MM-DD HH24:MI:SS')
as entry_date_ansi,
to_char(current_timestamp,'YYYY-MM-DD HH24:MI:SS')
as sysdate_ansi,
e.title,
e.title_url,
e.category_id,
com.category_id as sw_category_id,
content,
content_format,
draft_p,
p.first_names as poster_first_names,
p.last_name as poster_last_name,
o.creation_user as user_id,
(select count(gc.comment_id)
from general_comments gc,
cr_revisions cr
where gc.object_id = entry_id
and content_item__get_live_revision(gc.comment_id) =
cr.revision_id) as num_comments
from pinds_blog_entries e
join acs_objects o on (o.object_id = e.entry_id)
join persons p on (p.person_id = o.creation_user)
left outer join category_object_map com
on (com.object_id = e.entry_id)
where draft_p = 'f'
and deleted_p = 'f'
and e.package_id in (select package_id from dotlrn_community_applets)
order by entry_date desc
limit '5'

0 ms gethandle gethandle (returned pool3)
20 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '601813'

1 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '3676302'

3 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '3676302'

6 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '601813'

1 ms 0or1row dbqd.xowiki.www.portlets.noticias-comunidades.select_community_id: 0or1row nsdb1

select community_id
from dotlrn_community_applets
where package_id = '4129'

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 = '462' and ppm.party_id = '507' 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 = '4036424' and ppm.party_id = '507' 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 = '4014674' and ppm.party_id = '507' 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 = '4009218' and ppm.party_id = '507' and ppm.privilege = 'write' )

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 = '3985852' and ppm.party_id = '507' 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 = '3940827' and ppm.party_id = '507' and ppm.privilege = 'write' )

16 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=4384 and ci.item_id = page and ci.parent_id = f.folder_id

2 ms select dbqd.general-comments.tcl.general-comments-procs.general_comments_get_comments.get_comments: select nsdb0

select g.comment_id,
r.title,
r.mime_type,
o.creation_user,
acs_object__name(o.creation_user) as author,
o.creation_date

from general_comments g,
cr_revisions r,
acs_objects o
where g.object_id = '4384' and
r.revision_id = content_item__get_live_revision(g.comment_id) and
o.object_id = g.comment_id


order by o.creation_date

6 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 = 4384 and user_id = 507

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 = '4345' and ppm.party_id = '507' 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 = '4345' and ppm.party_id = '507' and ppm.privilege = 'admin' )

7 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 = '4345' and ppm.party_id = '507' and ppm.privilege = 'create' )

57 ms select dbqd.categories.tcl.category-trees-procs.category_tree::get_mapped_trees.get_mapped_trees: select nsdb0

select tree_id, subtree_category_id, assign_single_p,
require_category_p
from category_tree_map
where object_id = '4345'

2 ms select dbqd.::xowiki::portlet::categories-render.get_pages: select nsdb0

select ci.item_id, ci.name, ci.content_type, r.title, category_id , p.page_order from category_object_map c, cr_items ci, cr_revisions r, xowiki_page p where c.object_id = ci.item_id and ci.parent_id = 4368 and ci.content_type not in ('::xowiki::PageTemplate') and category_id in (3888) and r.revision_id = ci.live_revision and p.page_id = r.revision_id and ci.publish_status <> 'production'

2 ms select dbqd.xowiki.www.portlets.portlet-minimo-comunidade.select_comunidade: select nsdb0

select community_id,
pretty_name,
n_members
from dotlrn_community_members_mv
order by random()

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 = '507')

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 = '507')

1 ms select dbqd.theme-zen.tcl.navigation-procs.zen::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

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 = '385' and ppm.party_id = '507' and ppm.privilege = 'admin' )

3 ms 0or1row dbqd.acs-subsite.tcl.subsite-procs.subsite::util::get_portrait_live_revision.get_portrait_info: 0or1row nsdb0

select cr.revision_id
from cr_revisions cr, cr_items ci, acs_rels a
where cr.revision_id = ci.live_revision
and ci.item_id = a.object_id_two
and a.object_id_one = '507'
and a.rel_type = 'user_portrait_rel'
and ci.live_revision is not null

222 Total Duration (ms)

<h2>Results for /dotlrn</h2>

1327 ms gethandle gethandle (returned pool2)
122 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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'read' )

164 ms dml dbqd.acs-tcl.tcl.security-procs.ad_set_client_property.prop_insert_dml: dml nsdb0

insert into sec_session_properties
(session_id, module, property_name, secure_p, last_hit)
select '19981701', 'dotlrn', 'page_num', 'f', '1210872015'
from dual
where not exists (select 1
from sec_session_properties
where session_id = '19981701' and
module = 'dotlrn' and
property_name = 'page_num')

146 ms dml dbqd.acs-tcl.tcl.security-procs.ad_set_client_property.prop_update_dml: dml nsdb0

update sec_session_properties
set property_value = '0',
secure_p = 'f',
last_hit = '1210872015'
where session_id = '19981701' and
module = 'dotlrn' and
property_name = 'page_num'

223 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 = '507')

27 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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'dotlrn_browse' )

26 ms 0or1row dbqd.dotlrn.www.index.get_title: 0or1row nsdb0

select pretty_name
from portal_pages
where portal_id = '2115'
and sort_key = '0'

7 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 = '2115' and ppm.party_id = '507' and ppm.privilege = 'portal_read_portal' )

7 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 = '2115' and ppm.party_id = '507' and ppm.privilege = 'portal_edit_portal' )

88 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::render.portal_select: 0or1row nsdb0

select portals.name,
portals.portal_id,
portals.theme_id,
portal_layouts.layout_id,
portal_layouts.filename as layout_filename,
portal_layouts.resource_dir as layout_resource_dir,
portal_pages.page_id
from portals,
portal_pages,
portal_layouts
where portal_pages.sort_key = '0'
and portal_pages.portal_id = '2115'
and portal_pages.portal_id = portals.portal_id
and portal_pages.layout_id = portal_layouts.layout_id

122 ms select dbqd.new-portal.tcl.portal-procs.portal::render.element_select: select nsdb0

select portal_element_map.element_id,
portal_element_map.region,
portal_element_map.sort_key
from portal_element_map,
portal_pages
where portal_pages.portal_id = '2115'
and portal_element_map.page_id = '2116'
and portal_element_map.page_id = portal_pages.page_id
and portal_element_map.state != 'hidden'
order by portal_element_map.region,
portal_element_map.sort_key

162 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 = '2791' and ppm.party_id = '507' and ppm.privilege = 'admin' )

178 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '3970'
and pem.datasource_id = pd.datasource_id

246 ms select dbqd.survey-portlet.www.survey-portlet.select_surveys: select nsdb0

select s.survey_id, s.name, s.editable_p, s.single_response_p,
s.package_id,
acs_object__name(apm_package__parent_id(s.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = s.package_id) as url,
(select count(*) from survey_responses_latest srl where srl.survey_id=s.survey_id and initial_user_id='507') as response_count
from surveys s
where s.package_id in (3869,5768,4735,93945,51548,31329,520154,840281,601446,561005,22133,387094,1101832,1160554,1161157,1107799,627019,1444619,1664500,1500811,134088,1593736,1534926,3186181,3626690,3632822,3485800,3500450,3695786,3673866,2077568)
and s.enabled_p='t'
order by
parent_name,
upper(s.name)

0 ms gethandle gethandle (returned pool3)
9 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '520154' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

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

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1101832' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

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

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1107799' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

5 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '51548' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

5 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '93945' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

6 ms 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p: 0or1row nsdb1

select 1 from dual
where exists
( select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = '1500811' and ppm.party_id = '507' and ppm.privilege = 'read_private_data' )

21 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4178'
and pem.datasource_id = pd.datasource_id

72 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 = '507' and ppm.party_id = '507' and ppm.privilege = 'admin' )

25 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 = '4129' and ppm.party_id = '507' and ppm.privilege = 'read' )

77 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 = '4129' and ppm.party_id = '507' and ppm.privilege = 'create' )

35 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 = '5840' and ppm.party_id = '507' and ppm.privilege = 'read' )

12 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 = '5840' and ppm.party_id = '507' and ppm.privilege = 'create' )

42 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 = '4811' and ppm.party_id = '507' and ppm.privilege = 'read' )

111 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 = '4811' and ppm.party_id = '507' and ppm.privilege = 'create' )

64 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 = '94115' and ppm.party_id = '507' and ppm.privilege = 'read' )

100 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 = '94115' and ppm.party_id = '507' and ppm.privilege = 'create' )

126 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 = '94701' and ppm.party_id = '507' and ppm.privilege = 'read' )

230 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 = '94701' and ppm.party_id = '507' and ppm.privilege = 'create' )

56 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 = '37528' and ppm.party_id = '507' and ppm.privilege = 'read' )

57 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 = '37528' and ppm.party_id = '507' and ppm.privilege = 'create' )

164 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 = '601813' and ppm.party_id = '507' and ppm.privilege = 'read' )

58 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 = '601813' and ppm.party_id = '507' and ppm.privilege = 'create' )

21 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 = '1124207' and ppm.party_id = '507' and ppm.privilege = 'read' )

84 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 = '1124207' and ppm.party_id = '507' and ppm.privilege = 'create' )

49 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 = '1157455' and ppm.party_id = '507' and ppm.privilege = 'read' )

31 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 = '1157455' and ppm.party_id = '507' and ppm.privilege = 'create' )

25 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 = '1160724' and ppm.party_id = '507' and ppm.privilege = 'read' )

12 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 = '1160724' and ppm.party_id = '507' and ppm.privilege = 'create' )

15 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 = '1161789' and ppm.party_id = '507' and ppm.privilege = 'read' )

26 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 = '1161789' and ppm.party_id = '507' and ppm.privilege = 'create' )

63 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 = '1108048' and ppm.party_id = '507' and ppm.privilege = 'read' )

6 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 = '1108048' and ppm.party_id = '507' and ppm.privilege = 'create' )

15 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 = '631469' and ppm.party_id = '507' and ppm.privilege = 'read' )

14 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 = '631469' and ppm.party_id = '507' and ppm.privilege = 'create' )

22 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 = '1480821' and ppm.party_id = '507' and ppm.privilege = 'read' )

34 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 = '1480821' and ppm.party_id = '507' and ppm.privilege = 'create' )

20 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 = '1664639' and ppm.party_id = '507' and ppm.privilege = 'read' )

20 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 = '1664639' and ppm.party_id = '507' and ppm.privilege = 'create' )

86 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 = '134228' and ppm.party_id = '507' and ppm.privilege = 'read' )

5 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 = '134228' and ppm.party_id = '507' and ppm.privilege = 'create' )

87 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 = '1593842' and ppm.party_id = '507' and ppm.privilege = 'read' )

894 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 = '1593842' and ppm.party_id = '507' and ppm.privilege = 'create' )

235 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 = '2654094' and ppm.party_id = '507' and ppm.privilege = 'read' )

494 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 = '2654094' and ppm.party_id = '507' and ppm.privilege = 'create' )

196 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 = '3199080' and ppm.party_id = '507' and ppm.privilege = 'read' )

144 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 = '3199080' and ppm.party_id = '507' and ppm.privilege = 'create' )

124 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 = '3633817' and ppm.party_id = '507' and ppm.privilege = 'read' )

259 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 = '3633817' and ppm.party_id = '507' and ppm.privilege = 'create' )

229 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 = '3695972' and ppm.party_id = '507' and ppm.privilege = 'read' )

227 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 = '3695972' and ppm.party_id = '507' and ppm.privilege = 'create' )

241 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 = '3676302' and ppm.party_id = '507' and ppm.privilege = 'read' )

158 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 = '3676302' and ppm.party_id = '507' and ppm.privilege = 'create' )

424 ms select dbqd.weblogger-portlet.www.weblogger-portlet.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 (4129, 5840, 4811, 94115, 94701, 37528, 601813, 1124207, 1157455, 1160724, 1161789, 1108048, 631469, 1480821, 1664639, 134228, 1593842, 2654094, 3199080, 3633817, 3695972, 3676302)
and e.draft_p = 'f'
and e.deleted_p = 'f'
order by e.entry_date desc, p.package_id asc
limit 5

227 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4215'
and pem.datasource_id = pd.datasource_id

204 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 = '507' and ppm.party_id = '507' and ppm.privilege = 'chat_room_create' )

193 ms select dbqd.chat-portlet.www.chat-portlet.rooms_list: select nsdb0

select rm.room_id,
rm.pretty_name as pretty_name,
rm.description as description,
rm.moderated_p,
rm.active_p,
rm.archive_p,
acs_permission__permission_p(room_id, '507', 'chat_room_admin') as admin_p,
acs_permission__permission_p(room_id, '507', 'chat_read') as user_p,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = obj.context_id) as base_url
from chat_rooms rm,
acs_objects obj
where rm.room_id = obj.object_id
and obj.context_id IN (4194, 5787, 4772, 94093, 94751, 37420, 565956, 871211, 601791, 567335, 1088764, 1160700, 1261501, 1161758, 1108019, 631445, 1480873, 1664689, 134348, 2654018, 3633903, 3673928, 3696022, 3676260, 2077587)
order by rm.pretty_name

5 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4240'
and pem.datasource_id = pd.datasource_id

10 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 = '507' and ppm.party_id = '507' and ppm.privilege = 'write' )

3396 ms select dbqd.news-aggregator-portlet.www.news-aggregator-portlet.select_items: select nsdb0

select s.source_id,
s.link,
s.description,
s.title,
acs_object__name(apm_package__parent_id(package_id)) as parent_name,
(select site_node__url(site_nodes.node_id) from site_nodes where site_nodes.object_id = package_id) as node_url,
to_char(last_scanned, 'DD-MM-YYYY HH24:MI:SS') as last_scanned,
to_char(creation_date, 'YYYY-MM-DD HH24') as sort_date,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = package_id) as url,
feed_url,
item_id,
i.title as item_title,
i.link as item_link,
i.description as item_description,
package_id
from na_sources s left outer join
na_items i on (s.source_id = i.source_id)
where deleted_p = '0'
and package_id in (4223, 4754, 50130, 94075, 94773, 46633, 601895, 1406991, 1108000, 134329)
order by creation_date desc
limit 10

210 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '199852'
and pem.datasource_id = pd.datasource_id

226 ms select dbqd.wps-portlet.www.wps-portlet.select_presentations: select nsdb0

select o.context_id as package_id, i.item_id as pres_item_id,
acs_object__name(apm_package__parent_id(o.context_id)) as parent_name,
p.pres_title, (select site_node__url(site_nodes.node_id) from site_nodes where site_nodes.object_id = o.context_id) as url
from cr_items i, cr_wp_presentations p , acs_objects o
where o.context_id in ( 199186 )
and p.presentation_id = i.live_revision
and i.item_id = o.object_id
and p.public_p = 't'
order by i.item_id desc, pres_title

153 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '598208'
and pem.datasource_id = pd.datasource_id

287 ms select dbqd.assessment-portlet.www.assessment-portlet.open_asssessments: select nsdb0

select * from (select cr.item_id as assessment_id, cr.title, cr.description, a.password,
a.type,
to_char(a.start_time, 'YYYY-MM-DD HH24:MI:SS') as start_time,
to_char(a.end_time, 'YYYY-MM-DD HH24:MI:SS') as end_time,
to_char(now(), 'YYYY-MM-DD HH24:MI:SS') as cur_time,
cf.package_id, p.instance_name as community_name,
sc.node_id as comm_node_id, sa.node_id as as_node_id, a.anonymous_p,
acs_permission__permission_p(a.assessment_id,'507','admin') as admin_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id
and cr1.item_id=cr.item_id
and s1.subject_id='507'
and completed_datetime is null) as in_progress_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id
and cr1.item_id=cr.item_id
and s1.subject_id='507'
and completed_datetime is not null) as completed_p,
a.number_tries

from as_assessments a, cr_revisions cr, cr_items ci, cr_folders cf,
site_nodes sa, site_nodes sc, apm_packages p,
(select distinct asm.assessment_id
from as_assessment_section_map asm, as_item_section_map ism
where ism.section_id = asm.section_id
and exists (select 1 from acs_object_party_privilege_map ppm
where ppm.object_id = asm.assessment_id
and ppm.privilege = 'read'
and ppm.party_id = '507')) s
where a.assessment_id = cr.revision_id
and cr.revision_id = ci.latest_revision
and ci.parent_id = cf.folder_id
and ci.publish_status = 'live'
and cf.package_id in (594079, 2472808)
and sa.object_id = cf.package_id
and sc.node_id = sa.parent_id
and p.package_id = sc.object_id
and s.assessment_id = a.assessment_id
and ((a.start_time < current_timestamp and a.end_time > current_timestamp) or a.start_time is null)
order by lower(p.instance_name), lower(cr.title)
) q where (q.completed_p < q.number_tries) or (q.number_tries=0 or q.number_tries is null)

45 ms select dbqd.assessment-portlet.www.assessment-portlet.answered_assessments: select nsdb0

select * from (select ass.*, sc.node_id as comm_node_id, sa.node_id as as_node_id, p.instance_name as community_name,
acs_permission__permission_p(ass.assessment_id,'507','admin') as admin_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id and
cr1.item_id=ass.assessment_id
and s1.subject_id='507'
and completed_datetime is null) as in_progress_p,
(select count(*) from as_sessions s1,
cr_revisions cr1 where
s1.assessment_id=cr1.revision_id
and cr1.item_id=ass.assessment_id
and s1.subject_id='507'
and completed_datetime is not null) as completed_p


from
(select cr.item_id as assessment_id, cr.title, cr.description, cf.package_id,
a1.number_tries, a1.end_time
from as_assessments a, cr_revisions cr, cr_items ci, cr_folders cf,
as_assessments a1,
( select distinct s.assessment_id
from as_sessions s
where s.subject_id = '507'
and s.completed_datetime is not null) s
where a.assessment_id = cr.revision_id --
and cf.package_id in (594079, 2472808)
and cr.item_id = ci.item_id
and ci.parent_id = cf.folder_id
and s.assessment_id = a.assessment_id
and a1.assessment_id = ci.latest_revision
) ass,
site_nodes sa, site_nodes sc, apm_packages p
where sa.object_id = ass.package_id
and sc.node_id = sa.parent_id
and p.package_id = sc.object_id
order by lower(p.instance_name), lower(ass.title)
) q
where (q.number_tries is not null and q.number_tries >0 and q.completed_p >= q.number_tries) or (q.end_time is not null and q.end_time < current_timestamp)

23 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '3664907'
and pem.datasource_id = pd.datasource_id

13 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 = '3664369' and ppm.party_id = '507' and ppm.privilege = 'read' )

42 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4030'
and pem.datasource_id = pd.datasource_id

48 ms 0or1row dbqd.static-portlet.www.static-portlet.select_content: 0or1row nsdb0

select body, pretty_name, format
from static_portal_content
where content_id = '4021'

7 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '2127'
and pem.datasource_id = pd.datasource_id

49 ms select dbqd.dotlrn.www.dotlrn-main-portlet.select_communities: select nsdb0

select dotlrn_communities_all.*,
dotlrn_community__url(dotlrn_communities_all.community_id) as url,
(CASE
WHEN
dotlrn_communities_all.community_type = 'dotlrn_community'
THEN 'dotlrn_community'
WHEN dotlrn_communities_all.community_type = 'dotlrn_club'
THEN 'dotlrn_club'
WHEN dotlrn_communities_all.community_type = 'dotlrn_pers_community'
THEN 'dotlrn_pers_community'
ELSE 'dotlrn_class_instance'
END) as simple_community_type,
tree_level(dotlrn_communities_all.tree_sortkey) as tree_level,
coalesce((select tree_level(dotlrn_community_types.tree_sortkey)
from dotlrn_community_types
where dotlrn_community_types.community_type = dotlrn_communities_all.community_type), 0) as community_type_level,
acs_permission__permission_p(dotlrn_communities_all.community_id, '507', 'admin') as admin_p
from dotlrn_communities_all,
dotlrn_member_rels_approved
where dotlrn_communities_all.community_id = dotlrn_member_rels_approved.community_id
and dotlrn_member_rels_approved.user_id = '507'
and archived_p='f'

order by dotlrn_communities_all.tree_sortkey

258 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '2141'
and pem.datasource_id = pd.datasource_id

175 ms select dbqd.forums-portlet.www.forums-portlet.select_forums: select nsdb0

select forums_forums.package_id,
acs_object__name(apm_package__parent_id(forums_forums.package_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = forums_forums.package_id) as url,
forums_forums.forum_id,
forums_forums.name,
case when last_modified > (cast(current_timestamp as date)- 1) then 't' else 'f' end as new_p
from forums_forums_enabled forums_forums,
acs_objects
where acs_objects.object_id = forums_forums.forum_id and
forums_forums.package_id in (0,3779,5678,4645,93855,51458,31239,520062,840191,601355,560915,22043,387004,1101742,1160464,1161067,1107709,626929,1444529,1664410,1500721,133998,1593646,1534836,3186091,3626598,3632732,3485710,3500360,3695694,3673774,2077478)

and exists (
select 1
from acs_object_party_privilege_map ppm
where ppm.object_id = forums_forums.package_id
and ppm.party_id = '507'
and ppm.privilege = 'read_private_data'
)

order by parent_name,
forums_forums.name

352 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '2133'
and pem.datasource_id = pd.datasource_id

245 ms select dbqd.faq-portlet.www.faq-portlet.select_faqs: select nsdb0

select acs_objects.context_id as package_id,
acs_object__name(apm_package__parent_id(acs_objects.context_id)) as parent_name,
(select site_node__url(site_nodes.node_id)
from site_nodes
where site_nodes.object_id = acs_objects.context_id) as url,
faqs.faq_id,
faqs.faq_name
from faqs,
acs_objects
where faqs.faq_id = acs_objects.object_id
and faqs.disabled_p <> 't'
and acs_objects.context_id in (0, 3810, 5709, 4676, 93886, 51489, 31270, 520095, 840222, 601386, 560946, 22074, 387035, 1101773, 1160495, 1161098, 1107740, 626960, 1444560, 1664441, 1500752, 134029, 1593677, 1534867, 3186122, 3626629, 3632763, 3485741, 3500391, 3695727, 3673807, 2077509)
order by lower(faq_name)

181 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4089'
and pem.datasource_id = pd.datasource_id

179 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 = '1553' and ppm.party_id = '507' and ppm.privilege = 'admin' )

225 ms 0or1row dbqd.user-tracking-portlet.www.user-tracking-portlet.get_user_info: 0or1row nsdb0

select first_names , last_name
from persons
where person_id='507';

171 ms 0or1row dbqd.new-portal.tcl.portal-procs.portal::evaluate_element.element_select: 0or1row nsdb0

select pem.element_id,
pem.datasource_id,
pem.state,
pet.filename as filename,
pet.resource_dir as resource_dir,
pem.pretty_name as pretty_name,
pd.name as ds_name
from portal_element_map pem,
portal_element_themes pet,
portal_datasources pd
where pet.theme_id = '3646465'
and pem.element_id = '4186'
and pem.datasource_id = pd.datasource_id

268 ms select dbqd.latest-portlet.www.latest-portlet.communities_all_select: select nsdb0

select dotlrn_communities_all.package_id
from
dotlrn_communities_all, dotlrn_member_rels_approved
where
dotlrn_communities_all.community_id = dotlrn_member_rels_approved.community_id and
dotlrn_member_rels_approved.user_id = '507' and archived_p='f'

272 ms select dbqd.latest.tcl.latest-procs.latest::forums.forums_select: select nsdb0

select o.title, o.object_id, t.pretty_name as object_type, to_char(o.last_modified, 'MM-DD-YYYY') as last_modified
from acs_object_types t, acs_objects o
where t.object_type = o.object_type and
o.object_type in ('forums_forum')
and o.package_id in (37528,37420,31255,31283,31318,31329,37719,31239,796,796,46633,31270,31204,1664426,796,4223,3810,796,623663,625988,796,3869,626054,1664375,2077587,4098,3779,796,1664639,625754,796,1664311,624763,625485,623679,2077522,3795,625450,625924,625437,625789,796,796,623694,796,796,624814,1664489,796,21944,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,2077557,4194,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,3823,2077568,796,2077443,625710,624888,3991,626023,2077609,2077478,624699,625192,796,4073,624798,3744,22059,623742,796,1664441,625102,4129,2077379,796,1664689,623628,3858,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,2077494,22043,22087,625406,623753,2077509,796,601435,601895,601371,601446,601864,601791,601355,601399,796,601320,601386,601813,51458,594079,386905,796,94751,94773,796,51502,1088764,1088811,387083,386969,387048,387035,387020,51423,51489,94701,796,796,387094,51537,387004,51474,51548,94669,1664426,1664375,1664639,1664489,796,1664500,1664604,796,1664410,1664441,1664689,1664454,93934,93945,94165,93855,1521764,93886,94093,93820,93899,94115,796,94075,796,93871,4689,4794,3897870,3991,4610,199186,4811,4676,796,4754,4724,796,4661,4735,4861,4645,4772,796,1088764,387083,386969,387048,387035,387020,796,387094,387004,53783,54470,54181,5840,796,796,53479,796,54115,50130,50392,5768,53415,5694,5787,5809,5678,54498,53593,53834,53849,5722,796,53908,53862,54485,53818,796,53545,5757,53604,54533,54240,53514,796,54194,796,53530,54150,5709,796,54051,54355,796,54544,54419,54454,54166,54229,53719,796,53897,53558,5643,2979629,1534801,3664369,1534926,2610638,1534836,1534915,796,1534880,1534867,796,1534852,1161789,1161146,1161157,1161727,1161067,1161098,1161083,796,796,1161758,1161111,1161032,1160480,1160554,1160669,1160464,1160429,1160724,796,1160543,796,1160495,1160700,1160508,1593662,1593677,796,3673928,2496906,1593690,1593736,1593759,1593646,1593725,796,1593611,1593842,840156,1486799,1831555,871235,1486924,1486865,840207,1486992,840281,1486834,841893,840191,871211,796,1529671,840235,1486913,1486735,1486878,840222,796,840270,796,796,1486850,1107799,1107918,1107709,796,1108000,1108019,1107788,2472808,1107674,1107753,1107740,1107725,1108048,796,560880,560931,560959,561005,1308874,560915,560946,796,796,560994,134088,134014,134197,133963,133998,134228,796,134329,134029,134077,796,134348,134042,1664426,796,623663,625988,796,626054,1664375,1664639,625754,796,1664311,624763,625485,623679,625450,625924,625437,625789,796,623694,796,796,624814,1664489,796,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,796,625710,624888,626023,624699,625192,624798,22059,623742,796,1664441,625102,796,1664689,623628,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,22043,22087,625406,623753,1444560,1444494,1480821,1444619,1626202,1444529,796,1444545,1444608,1480873,1444573,796,2077587,2077522,796,2077557,2077568,2077443,2077609,2077478,796,2077494,2077509,3485726,796,3485741,3485800,3485789,3485754,3485710,3485675,796,2979629,631469,3829959,796,627008,1534801,1941724,1941838,632586,632540,3830018,632715,632496,796,3830108,3829926,796,626960,3664369,1534926,796,627019,632904,2610638,632246,1534836,1534915,626929,796,632397,632814,1534737,626945,796,1534880,796,1534867,632512,632845,632575,632779,796,796,796,3832620,632527,3830007,3829972,3829824,1941849,796,632893,632461,632830,1943332,631445,1941759,796,1534852,1941803,1941660,3829943,626973,632858,3991,3829891,860767,1941790,626894,1941775,3676225,3676677,3673774,796,3673855,3676494,796,3676260,3676613,3687013,796,3686949,3673820,3673791,3673739,796,3676302,3686830,3673807,3687749,3686965,3686897,3676561,3687024,3676642,3688104,3688017,3688069,3686932,3687858,3686978,796,3676629,3676688,796,3687773,3676596,3673866,3500325,3500391,3500404,3500450,3501507,3500360,796,796,3500439,3500376,3186107,3186181,796,3199137,3186122,3186091,3186170,3186056,796,3199080,3186135,520108,796,520095,2684721,2685334,2684631,520154,2684710,970315,520143,520062,2684596,796,2684647,2684662,796,2684675,796,520027,1124207,520078,2684532,565956,3991,3626642,3626690,796,3626598,3626679,3626563,796,3626614,3626629,3632811,3632697,796,3633817,3632748,3632763,3633903,3632776,3632822,796,3633868,3632732,796,3696022,3695775,3695659,3695740,3695727,3695711,3695972,796,3695786,3695937,3695694,1500811,1500752,1548305,1500721,796,1500686,2654094,1500737,1500800,796,2654018,1500765,1160480,1517889,796,1161789,1101773,1160554,1161146,1160669,1500981,1160464,1161157,1160429,1501159,1101821,1160968,1161727,1161067,1501045,1160724,1161098,796,1161083,1501096,1160543,796,796,1501111,1406991,1101707,796,1501170,1501124,796,1157455,796,1501080,1101832,796,1157522,1160495,1160700,1161758,1101742,1101758,1160365,1160508,1161111,1261501,1101786,1161032) order by last_modified desc limit 5

38 ms select dbqd.latest.tcl.latest-procs.latest::fs.fs_select: select nsdb0

select o.title, o.object_id, t.pretty_name as object_type, to_char(o.last_modified, 'MM-DD-YYYY') as last_modified
from acs_object_types t, acs_objects o
where t.object_type = o.object_type and
o.object_type in ('file_storage_object')
and o.package_id in (37528,37420,31255,31283,31318,31329,37719,31239,796,796,46633,31270,31204,1664426,796,4223,3810,796,623663,625988,796,3869,626054,1664375,2077587,4098,3779,796,1664639,625754,796,1664311,624763,625485,623679,2077522,3795,625450,625924,625437,625789,796,796,623694,796,796,624814,1664489,796,21944,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,2077557,4194,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,3823,2077568,796,2077443,625710,624888,3991,626023,2077609,2077478,624699,625192,796,4073,624798,3744,22059,623742,796,1664441,625102,4129,2077379,796,1664689,623628,3858,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,2077494,22043,22087,625406,623753,2077509,796,601435,601895,601371,601446,601864,601791,601355,601399,796,601320,601386,601813,51458,594079,386905,796,94751,94773,796,51502,1088764,1088811,387083,386969,387048,387035,387020,51423,51489,94701,796,796,387094,51537,387004,51474,51548,94669,1664426,1664375,1664639,1664489,796,1664500,1664604,796,1664410,1664441,1664689,1664454,93934,93945,94165,93855,1521764,93886,94093,93820,93899,94115,796,94075,796,93871,4689,4794,3897870,3991,4610,199186,4811,4676,796,4754,4724,796,4661,4735,4861,4645,4772,796,1088764,387083,386969,387048,387035,387020,796,387094,387004,53783,54470,54181,5840,796,796,53479,796,54115,50130,50392,5768,53415,5694,5787,5809,5678,54498,53593,53834,53849,5722,796,53908,53862,54485,53818,796,53545,5757,53604,54533,54240,53514,796,54194,796,53530,54150,5709,796,54051,54355,796,54544,54419,54454,54166,54229,53719,796,53897,53558,5643,2979629,1534801,3664369,1534926,2610638,1534836,1534915,796,1534880,1534867,796,1534852,1161789,1161146,1161157,1161727,1161067,1161098,1161083,796,796,1161758,1161111,1161032,1160480,1160554,1160669,1160464,1160429,1160724,796,1160543,796,1160495,1160700,1160508,1593662,1593677,796,3673928,2496906,1593690,1593736,1593759,1593646,1593725,796,1593611,1593842,840156,1486799,1831555,871235,1486924,1486865,840207,1486992,840281,1486834,841893,840191,871211,796,1529671,840235,1486913,1486735,1486878,840222,796,840270,796,796,1486850,1107799,1107918,1107709,796,1108000,1108019,1107788,2472808,1107674,1107753,1107740,1107725,1108048,796,560880,560931,560959,561005,1308874,560915,560946,796,796,560994,134088,134014,134197,133963,133998,134228,796,134329,134029,134077,796,134348,134042,1664426,796,623663,625988,796,626054,1664375,1664639,625754,796,1664311,624763,625485,623679,625450,625924,625437,625789,796,623694,796,796,624814,1664489,796,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,796,625710,624888,626023,624699,625192,624798,22059,623742,796,1664441,625102,796,1664689,623628,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,22043,22087,625406,623753,1444560,1444494,1480821,1444619,1626202,1444529,796,1444545,1444608,1480873,1444573,796,2077587,2077522,796,2077557,2077568,2077443,2077609,2077478,796,2077494,2077509,3485726,796,3485741,3485800,3485789,3485754,3485710,3485675,796,2979629,631469,3829959,796,627008,1534801,1941724,1941838,632586,632540,3830018,632715,632496,796,3830108,3829926,796,626960,3664369,1534926,796,627019,632904,2610638,632246,1534836,1534915,626929,796,632397,632814,1534737,626945,796,1534880,796,1534867,632512,632845,632575,632779,796,796,796,3832620,632527,3830007,3829972,3829824,1941849,796,632893,632461,632830,1943332,631445,1941759,796,1534852,1941803,1941660,3829943,626973,632858,3991,3829891,860767,1941790,626894,1941775,3676225,3676677,3673774,796,3673855,3676494,796,3676260,3676613,3687013,796,3686949,3673820,3673791,3673739,796,3676302,3686830,3673807,3687749,3686965,3686897,3676561,3687024,3676642,3688104,3688017,3688069,3686932,3687858,3686978,796,3676629,3676688,796,3687773,3676596,3673866,3500325,3500391,3500404,3500450,3501507,3500360,796,796,3500439,3500376,3186107,3186181,796,3199137,3186122,3186091,3186170,3186056,796,3199080,3186135,520108,796,520095,2684721,2685334,2684631,520154,2684710,970315,520143,520062,2684596,796,2684647,2684662,796,2684675,796,520027,1124207,520078,2684532,565956,3991,3626642,3626690,796,3626598,3626679,3626563,796,3626614,3626629,3632811,3632697,796,3633817,3632748,3632763,3633903,3632776,3632822,796,3633868,3632732,796,3696022,3695775,3695659,3695740,3695727,3695711,3695972,796,3695786,3695937,3695694,1500811,1500752,1548305,1500721,796,1500686,2654094,1500737,1500800,796,2654018,1500765,1160480,1517889,796,1161789,1101773,1160554,1161146,1160669,1500981,1160464,1161157,1160429,1501159,1101821,1160968,1161727,1161067,1501045,1160724,1161098,796,1161083,1501096,1160543,796,796,1501111,1406991,1101707,796,1501170,1501124,796,1157455,796,1501080,1101832,796,1157522,1160495,1160700,1161758,1101742,1101758,1160365,1160508,1161111,1261501,1101786,1161032) order by last_modified desc limit 5

3 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2863943'

200 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2857211'

189 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2806819'

148 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2806822'

230 ms 0or1row dbqd.acs-content-repository.tcl.content-revision-procs.content::revision::item_id.item_id: 0or1row nsdb1

select item_id
from cr_revisions
where revision_id = '2788261'

286 ms select dbqd.latest.tcl.latest-procs.latest::asm.answered_assessments: select nsdb0

select cr.item_id as assessment_id, cr.title, a.password,
to_char(a.start_time, 'YYYY-MM-DD HH24:MI:SS') as start_time,
to_char(a.end_time, 'YYYY-MM-DD HH24:MI:SS') as end_time,
to_char(now(), 'YYYY-MM-DD HH24:MI:SS') as cur_time,
to_char(cr.publish_date, 'MM-DD-YYYY') as publish_date,
sc.node_id as comm_node_id, sa.node_id as as_node_id
from as_assessments a, cr_revisions cr, cr_items ci, cr_folders cf,
site_nodes sa, site_nodes sc, apm_packages p
where a.assessment_id = cr.revision_id
and cr.revision_id = ci.latest_revision
and ci.parent_id = cf.folder_id
and sa.object_id = cf.package_id
and sc.node_id = sa.parent_id
and cf.package_id in (37528,37420,31255,31283,31318,31329,37719,31239,796,796,46633,31270,31204,1664426,796,4223,3810,796,623663,625988,796,3869,626054,1664375,2077587,4098,3779,796,1664639,625754,796,1664311,624763,625485,623679,2077522,3795,625450,625924,625437,625789,796,796,623694,796,796,624814,1664489,796,21944,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,2077557,4194,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,3823,2077568,796,2077443,625710,624888,3991,626023,2077609,2077478,624699,625192,796,4073,624798,3744,22059,623742,796,1664441,625102,4129,2077379,796,1664689,623628,3858,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,2077494,22043,22087,625406,623753,2077509,796,601435,601895,601371,601446,601864,601791,601355,601399,796,601320,601386,601813,51458,594079,386905,796,94751,94773,796,51502,1088764,1088811,387083,386969,387048,387035,387020,51423,51489,94701,796,796,387094,51537,387004,51474,51548,94669,1664426,1664375,1664639,1664489,796,1664500,1664604,796,1664410,1664441,1664689,1664454,93934,93945,94165,93855,1521764,93886,94093,93820,93899,94115,796,94075,796,93871,4689,4794,3897870,3991,4610,199186,4811,4676,796,4754,4724,796,4661,4735,4861,4645,4772,796,1088764,387083,386969,387048,387035,387020,796,387094,387004,53783,54470,54181,5840,796,796,53479,796,54115,50130,50392,5768,53415,5694,5787,5809,5678,54498,53593,53834,53849,5722,796,53908,53862,54485,53818,796,53545,5757,53604,54533,54240,53514,796,54194,796,53530,54150,5709,796,54051,54355,796,54544,54419,54454,54166,54229,53719,796,53897,53558,5643,2979629,1534801,3664369,1534926,2610638,1534836,1534915,796,1534880,1534867,796,1534852,1161789,1161146,1161157,1161727,1161067,1161098,1161083,796,796,1161758,1161111,1161032,1160480,1160554,1160669,1160464,1160429,1160724,796,1160543,796,1160495,1160700,1160508,1593662,1593677,796,3673928,2496906,1593690,1593736,1593759,1593646,1593725,796,1593611,1593842,840156,1486799,1831555,871235,1486924,1486865,840207,1486992,840281,1486834,841893,840191,871211,796,1529671,840235,1486913,1486735,1486878,840222,796,840270,796,796,1486850,1107799,1107918,1107709,796,1108000,1108019,1107788,2472808,1107674,1107753,1107740,1107725,1108048,796,560880,560931,560959,561005,1308874,560915,560946,796,796,560994,134088,134014,134197,133963,133998,134228,796,134329,134029,134077,796,134348,134042,1664426,796,623663,625988,796,626054,1664375,1664639,625754,796,1664311,624763,625485,623679,625450,625924,625437,625789,796,623694,796,796,624814,1664489,796,796,625726,625146,624842,22008,625307,625067,625611,625118,796,796,626102,625675,623707,626039,1664500,796,22074,22122,625800,625741,625422,1664604,796,624829,626113,1664410,796,625710,624888,626023,624699,625192,624798,22059,623742,796,1664441,625102,796,1664689,623628,626067,623564,625371,624877,796,22133,625181,567335,625003,1664454,625133,625496,22043,22087,625406,623753,1444560,1444494,1480821,1444619,1626202,1444529,796,1444545,1444608,1480873,1444573,796,2077587,2077522,796,2077557,2077568,2077443,2077609,2077478,796,2077494,2077509,3485726,796,3485741,3485800,3485789,3485754,3485710,3485675,796,2979629,631469,3829959,796,627008,1534801,1941724,1941838,632586,632540,3830018,632715,632496,796,3830108,3829926,796,626960,3664369,1534926,796,627019,632904,2610638,632246,1534836,1534915,626929,796,632397,632814,1534737,626945,796,1534880,796,1534867,632512,632845,632575,632779,796,796,796,3832620,632527,3830007,3829972,3829824,1941849,796,632893,632461,632830,1943332,631445,1941759,796,1534852,1941803,1941660,3829943,626973,632858,3991,3829891,860767,1941790,626894,1941775,3676225,3676677,3673774,796,3673855,3676494,796,3676260,3676613,3687013,796,3686949,3673820,3673791,3673739,796,3676302,3686830,3673807,3687749,3686965,3686897,3676561,3687024,3676642,3688104,3688017,3688069,3686932,3687858,3686978,796,3676629,3676688,796,3687773,3676596,3673866,3500325,3500391,3500404,3500450,3501507,3500360,796,796,3500439,3500376,3186107,3186181,796,3199137,3186122,3186091,3186170,3186056,796,3199080,3186135,520108,796,520095,2684721,2685334,2684631,520154,2684710,970315,520143,520062,2684596,796,2684647,2684662,796,2684675,796,520027,1124207,520078,2684532,565956,3991,3626642,3626690,796,3626598,3626679,3626563,796,3626614,3626629,3632811,3632697,796,3633817,3632748,3632763,3633903,3632776,3632822,796,3633868,3632732,796,3696022,3695775,3695659,3695740,3695727,3695711,3695972,796,3695786,3695937,3695694,1500811,1500752,1548305,1500721,796,1500686,2654094,1500737,1500800,796,2654018,1500765,1160480,1517889,796,1161789,1101773,1160554,1161146,1160669,1500981,1160464,1161157,1160429,1501159,1101821,1160968,1161727,1161067,1501045,1160724,1161098,796,1161083,1501096,1160543,796,796,1501111,1406991,1101707,796,1501170,1501124,796,1157455,796,1501080,1101832,796,1157522,1160495,1160700,1161758,1101742,1101758,1160365,1160508,1161111,1261501,1101786,1161032)
and p.package_id = sc.object_id
and exists (select 1
from as_assessment_section_map asm, as_item_section_map ism
where asm.assessment_id = a.assessment_id
and ism.section_id = asm.section_id)
and acs_permission__permission_p (a.assessment_id, '507', 'read') = 't'
order by publish_date desc limit 5

602 ms 0or1row dbqd.latest-portlet.www.latest-portlet.check_lors: 0or1row nsdb0

select package_key, pretty_name, installed_p from apm_package_version_info where package_key = 'lors'

12 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 = '507' and ppm.privilege = 'admin' )

522 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 = '507')

167 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 = '507')

258 ms select dbqd.theme-zen.tcl.navigation-procs.zen::portal_subnavbar.list_page_nums_select: select nsdb0

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

202 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 = '385' and ppm.party_id = '507' and ppm.privilege = 'admin' )

270 ms 0or1row dbqd.acs-subsite.tcl.subsite-procs.subsite::util::get_portrait_live_revision.get_portrait_info: 0or1row nsdb0

select cr.revision_id
from cr_revisions cr, cr_items ci, acs_rels a
where cr.revision_id = ci.live_revision
and ci.item_id = a.object_id_two
and a.object_id_one = '507'
and a.rel_type = 'user_portrait_rel'
and ci.live_revision is not null

0 ms releasehandle releasehandle nsdb1
1 ms releasehandle releasehandle nsdb0
18,977 Total Duration (ms)

What I can take from these tests is: I'm not using pool1, only pool2 and pool3. I don't know why that happens. Can somebody tell me how it works?

Collapse
Posted by Gustaf Neumann on
Eduardo, 
why are you sticking with the following two lines in your example?

   ns_param maxidle 1000000000
   ns_param maxopen 1000000000

These only add confusion to the discussion.

It is indeed strange that in your configuration, only pool1 is not used. 
This is not, what we observe. Check these two things:

 - what is the result of [db_available_pools ""]
   (e.g. in ds/shell)

 - if the list returned starts with pool1, then something
   in your configuration seems to block pool1. In
   this case, i would recommend to add some trace statements
   with "ns_log notice" to proc do_with_handle in
   00-database-procs to see, who is grabbing pool1

Concerning your results

   Results for / (XoWiki page)
   0 ms gethandle gethandle (returned pool2)
   ...
   222 Total Duration (ms)

   Results for /dotlrn 
   1327 ms gethandle gethandle (returned pool2)
   ...
   18,977 Total Duration (ms)

First of all, i am wondering, from which of the 100 requests this output is from. 
Note the difference in gethandle. In the dotlrn case, you were 
already out of handles (the request had to wait 1.3 seconds for the handle)

Second, if i look at the xowiki request, more than 20% are
from permission checking. 
I would recommend to turn permission caching on (kernel parameter). 

If i take the remaining time, about half of the time of the xowiki test is coming 
from lars-blogger (that you seem to call via your own includelet) and a 
third is coming from categories (xowiki includelet). 

So, these tests say only something about your configuration. Same is 
true with dotlrn values (for example, the time for the home portal page depends very 
much on the number of communities your are member of).


Collapse
Posted by Eduardo Santos on
Hi Gustaf,

I'm still running some other tests, but I've seen some odd thing: the command db_available_pools "" returned this:

pool2 pool3 pool1

It seems like the pool order is reversed, and I have no idea what was causing it. There's also something that is making my test results be a little bit wrong: the repeated query Operation Blocked thing. As the requests are made simultaneously from the same machine, the system is stoping it thinking the same query is being sent. I have to find a way to untoggle this feature so the results can be OK.

I'm still working with your others suggestions and I'll put my results here as soon as I can.

Collapse
Posted by Gustaf Neumann on
A simple approach to fix the wierd order might be to change

  ns_section ns/server/${server}/db
    ns_param   pools              "*"
    ns_param   defaultpool        pool1

to 

  ns_section ns/server/${server}/db
    ns_param   pools              pool1,pool2,pool3
    ns_param   defaultpool        pool1

Concerning request monitor:
to deactivate the repeated operation and blocking stuff, but keeping the measuring, 
simplify the method check (in xotcl-request-monitor/tcl/throttle_mod-procs.tcl) to 

   throttle ad_proc check {} {
    ...
   } {
     my get_context
     return 0
   }

I think, this should help (add this definition simply to the end of the .procs.tcl file, 
you can simple delete it from there, when you are done)

Collapse
Posted by Eduardo Santos on
Hi Gustaf,

Sorry for the late answer, but I was doing some other things and I left the tests a little bit aside. I'm going to have a report really soon about the effects of changing every parameter in the performance.

My question now is much more related to the service itself than the tests environment. I'm facing some performance issue right now that I don't where it comes from. Evry once in a while, about every ten minutes to half hour, I can see a major performance issue. I just can't get no response and the db queries seem to get real slow. Trying o find out what this is about, I"ve found that, in my log, I can see these messages:


[16/Jun/2008:21:58:57][14985.1296435552][-default:720-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1317448032][-default:721-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1401497952][-default:728-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1300638048][-default:736-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1275423072][-default:730-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1174587744][-default:756-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1393092960][-default:705-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1103145312][-default:747-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1334258016][-default:724-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1342663008][-default:726-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1107347808][-default:745-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:57][14985.1292233056][-default:718-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:58][14985.1204005216][-default:744-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:58][14985.1174587744][-thread1174587744-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:58:58][14985.1174587744][-thread1174587744-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 302ms)
[16/Jun/2008:21:58:58][14985.1275423072][-thread1275423072-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:58:59][14985.1191397728][-default:759-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1275423072][-thread1275423072-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 497ms)
[16/Jun/2008:21:58:59][14985.1288030560][-default:733-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1103145312][-thread1103145312-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:58:59][14985.1145170272][-default:713-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1267018080][-default:742-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:58:59][14985.1199802720][-default:702-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:00][14985.1376282976][-default:735-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:00][14985.1103145312][-thread1103145312-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 667ms)
[16/Jun/2008:21:59:02][14985.1325853024][-default:737-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:03][14985.1212410208][-thread1212410208-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:03][14985.1212410208][-thread1212410208-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 233ms)
[16/Jun/2008:21:59:03][14985.1393092960][-thread1393092960-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:04][14985.1393092960][-thread1393092960-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1050ms)
[16/Jun/2008:21:59:05][14985.1321650528][-default:722-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:07][14985.1199802720][-thread1199802720-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:08][14985.1199802720][-thread1199802720-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1202ms)
[16/Jun/2008:21:59:10][14985.1170385248][-default:717-] Warning: db_exec: longdb 5 seconds nsdb0 dml dbqd.acs-tcl.tcl.security-procs.sec_update_user_session_
info.update_last_visit
[16/Jun/2008:21:59:11][14985.1149372768][-default:753-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:11][14985.1166182752][-default:716-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:12][14985.1111550304][-default:746-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:18][14985.1292233056][-thread1292233056-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:18][14985.1334258016][-thread1334258016-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:19][14985.1292233056][-thread1292233056-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 936ms)
[16/Jun/2008:21:59:20][14985.1334258016][-thread1334258016-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2293ms)
[16/Jun/2008:21:59:25][14985.1140967776][-default:731-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:26][14985.1132562784][-default:712-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:29][14985.1254410592][-default:738-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:29][14985.1149372768][-thread1149372768-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:30][14985.1149372768][-thread1149372768-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1293ms)
[16/Jun/2008:21:59:30][14985.1338460512][-default:725-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:31][14985.1182992736][-default:757-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:34][14985.1161980256][-default:696-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:35][14985.1271220576][-default:719-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:35][14985.1098942816][-default:749-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:36][14985.1317448032][-thread1317448032-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:36][14985.1317448032][-thread1317448032-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 327ms)
[16/Jun/2008:21:59:40][14985.1098942816][-thread1098942816-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:40][14985.1178790240][-default:741-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:41][14985.1098942816][-thread1098942816-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1219ms)
[16/Jun/2008:21:59:42][14985.1258613088][-default:708-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:42][14985.1153575264][-thread1153575264-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:44][14985.1304840544][-default:734-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:44][14985.1166182752][-thread1166182752-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:44][14985.1119955296][-default:750-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:44][14985.1153575264][-thread1153575264-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1685ms)
[16/Jun/2008:21:59:46][14985.1208207712][-default:740-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1090537824][-default:727-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1115752800][-default:697-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1136765280][-default:752-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1372080480][-default:698-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1140967776][-thread1140967776-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:46][14985.1262815584][-default:707-] Notice: exiting: timeout waiting for connection
[16/Jun/2008:21:59:46][14985.1166182752][-thread1166182752-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2535ms)
[16/Jun/2008:21:59:46][14985.1145170272][-thread1145170272-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:48][14985.1140967776][-thread1140967776-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2978ms)
[16/Jun/2008:21:59:50][14985.1145170272][-thread1145170272-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4059ms)
[16/Jun/2008:21:59:53][14985.1401497952][-thread1401497952-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:57][14985.1304840544][-thread1304840544-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:21:59:57][14985.1401497952][-thread1401497952-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4555ms)
[16/Jun/2008:22:00:00][14985.1271220576][-thread1271220576-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:01][14985.1304840544][-thread1304840544-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4575ms)
[16/Jun/2008:22:00:02][14985.1288030560][-thread1288030560-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:04][14985.1271220576][-thread1271220576-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4110ms)
[16/Jun/2008:22:00:05][14985.1372080480][-thread1372080480-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:05][14985.1178790240][-thread1178790240-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:08][14985.1288030560][-thread1288030560-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 5566ms)
[16/Jun/2008:22:00:08][14985.1372080480][-thread1372080480-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2902ms)
[16/Jun/2008:22:00:08][14985.1178790240][-thread1178790240-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2884ms)
[16/Jun/2008:22:00:14][14985.1208207712][-thread1208207712-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:17][14985.1262815584][-thread1262815584-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:17][14985.1182992736][-thread1182992736-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:17][14985.1262815584][-thread1262815584-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 624ms)
[16/Jun/2008:22:00:18][14985.1208207712][-thread1208207712-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 3466ms)
[16/Jun/2008:22:00:19][14985.1107347808][-thread1107347808-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:20][14985.1090537824][-thread1090537824-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:24][14985.1107347808][-thread1107347808-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 4952ms)
[16/Jun/2008:22:00:24][14985.1090537824][-thread1090537824-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 3785ms)
[16/Jun/2008:22:00:24][14985.1132562784][-thread1132562784-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:25][14985.1086335328][-sched-] Warning: db_exec: longdb 9 seconds nsdb0 dml dbqd.acs-tcl.tcl.security-procs.sec_sweep_sessions.sessions_sw
eep
[16/Jun/2008:22:00:25][14985.1342663008][-thread1342663008-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:26][14985.1086335328][-sched-] Warning: sched: excessive time taken by proc 4 (11 seconds)
[16/Jun/2008:22:00:28][14985.1132562784][-thread1132562784-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 3387ms)
[16/Jun/2008:22:00:28][14985.1191397728][-thread1191397728-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:29][14985.1300638048][-thread1300638048-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:30][14985.1191397728][-thread1191397728-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 1976ms)
[16/Jun/2008:22:00:32][14985.1342663008][-thread1342663008-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 7163ms)
[16/Jun/2008:22:00:35][14985.1325853024][-thread1325853024-] Notice: destroy called, ::bgdelivery ::xotcl::THREAD->destroy (0ms)
[16/Jun/2008:22:00:37][14985.1300638048][-thread1300638048-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 7627ms)
[16/Jun/2008:22:00:37][14985.1325853024][-thread1325853024-] Notice: destroy called, ::throttle ::xotcl::THREAD->destroy (0ms, 2453ms)

All of a sudden the XoTcl get destroied, and I have no idea where it comes from. Can you give some hint about it?

Collapse
Posted by Gustaf Neumann on
what i can see from your log is that
 - connection threads time out (most likely due to
   your threadtimeout settings), it seems they
   are no fed by new requests.
 - the "destroy called" messages are not serious.
   When a connection thread terminates (the thread is
   destroyed) all the objects it contains are destroyed
   as well. Since the deletion semantics on the C
   level are quite tricky, i left the notice calls
   in. You just see here the messages of the
   thread proxy objects, XOTcl itself is not destroyed.

 - a few db-queries seem to be quite slow:
   
    5 seconds nsdb0 dml dbqd.acs-tcl.tcl.security-
      procs.sec_update_user_session_info.update_last_visit
    9 seconds nsdb0 dml dbqd.acs-tcl.tcl.security-
      procs.sec_sweep_sessions.sessions_sweep
    sched: excessive time taken by proc 4 (11 seconds)

Without more information, it is hard to guess what happens. 
Is the "performance issue" happen during/after the benchmark 
or during normal operations?

To see, what's happening in your database, use e.g.
http://search.cpan.org/dist/pgtop/pgtop
http://www.rot13.org/~dpavlin/sysadm.html

For a deeper understanding of postgres semantics
in particular with checkpoints, see
http://www.westnet.com/~gsmith/content/postgresql/

Collapse
Posted by Eduardo Santos on
Hi Gustaf,

Thank you for your quick answer. I have already installed in my machine ptop and some other tools to monitor PostgreSQL. From the PostgreSQL analysis, it seems like every time I can see these messages in my log, all the DB queries get very slow and ptop shows me that they are waiting to be parsed (they are in waiting state). From this analysis, my first thought is that this destroy objects call is bringing the performance down.

Then, I'm asking myself: why it happens? When I run the benchmark, the system uses all DB connections and threads available. After that, it destroys some of them, what shows me the log messages above. However, when the threads are being destroyed, the system gets so slow that we just can't navigate.

So, there are some thoughts I can get from here:

1 - Is the thread destroy proccess being a performance problem?
2 - Why the DB connections stay in waiting when this destroy is hapenning if I have memory, processor and connections available?

I'll try to take a closer look at the PostgreSQL performance info at this time and try to see something I haven't seem yet. Thank you for your help.

Collapse
Posted by Gustaf Neumann on
The primary question is to figure out, what resources are running out. Candidates
  - cpu
  - amount of memory
  - memory bandwidth
  - i/o

and who is causing it
  - aolserver (e.g. lock-contention)
  - postgres (e.g. checkpoint handling, vacuuming, 
    some complex queries...)

is the whole machine in a bad state (e.g. 
load etc. how does it react on the console)
or just the aolserver or the database?

how many cpus do you have on your system 
(fgrep processor /proc/cpuinfo)?

In respone to your questions:
 - i have never seen thread destroy as a 
   performance problem, but under "normal
   conditions", not all threads end 
   at more or less the same time.
   Normally, the problem with the thread
   destroys is just that they might be
   created quite soon later, thread 
   creation is slow, when the blueprint
   is large (when you have many packages
   installed). However, if one has a large
   blueprint, the thread cleanup has to 
   free all of the contents, which 
   might be a couple of million individual
   free operations. This might entail 
   as well quite a large number of 
   memory locks.

 - there are as well many reasons
   for possible waiting operations.
   Do you see error message concerning
   DEADLOCKS in you database? OpenACS
   5.4 uses less locks (which were introduced
   to overcome some problems in PostgreSQL
   8.0 and 8.1).

-gustaf neumann


Collapse
Posted by Gustaf Neumann on
Eduardo,

the aolserver has the bad behavior, that it is likely that the thread termination parameters (maxconnections, threadtimeout) terminate all connection threads at the same time. This happens, when these threads were started at more or less the same time, which is likely on busy sites or during benchmarks. This mass extinction of threads is performance-wise not a good idea, especially when most of the threads have to be recreated afterwards. Termination and recration of threads are costly operations learning to noticeable delays.

To overcome this problem i have committed a small change to aolserver 4.5 head, that introduces a "spread", a randomization factor for the two mentioned thread termination parameters. The spread will lead to slightly different values for maxconnections and threadtimeout per connection thread (default is +- 20%). When spread is 0 one obtains the original behavior. You might be interested in trying this version.

Collapse
Posted by Tom Jackson on
Gustaf is right here. The AOLserver code does not take into account the size of the queue or the number of requests which could be served by a thread before allowing the thread to exit.

There is a basic logic problem in the code, but it really only shows up under test conditions. Two real world complicating factors are running very few threads (less than 10) and serving long running requests (slow client or huge data).

My experience is that external benchmark programs are less reliable than AOLserver, so it is very difficult to use their results. Most of the slowness in OpenACS will be in database queries, which will be impossible to detect using an external tool.

OTOH, if you expect hundreds of simultaneous visitors to a DB backed site, be happy with your success and look into distributing your site over a number of front end servers.

Collapse
Posted by Eduardo Santos on
Hi Gustaf and Tom,

Thank you very much for your replies. I'm sorry for the time I've taken to post, but I had some personal issue to solve.

With our tests and observations, we are writing some kind of benchmark howto document that should go somewhere in the community, maybe in the XoWiki instance. Our tests had three branches of observation:

1 - AOLServer (OpenACS?) Tunning
2 - PostgreSQL Tunning
3 - SO Tunning

I'm going to try to make a brief description about the specific and generic observations we could find:

<h4> AOLServer (OpenACS? Tunning) </h4>

Our first issue with AOLServer was the 4.5.0 parameters problem that somebody fixed with the file /acs-tcl/tcl/pools-init.tcl as said in this post in Tom's message. With a simple update we where able to solve this issue.

The other problem was with the thread creation process wich, as you just said, is a mixed XoTcl + AOLServer problem. The most important thing we've realized is that the creation and destruction process consumes a lot of I/O operations. To improve the I/O performance we've tried to change the file system, but it had no effect due to the most important thing we've find out: DON'T EVER USE VM's IN PRODUCTION SITES.

Our server was based on Xen VM's and it was impossible to have I/O performance with Virtual Machines. The whole thing about it is that there's no virtualization process able to split the blocks and inodes completely when using virtual machines, so all the I/O is shared between the VM's in the Cluster. It's a little bit different from what happens with logical partitions possible in some hardwares, such as IBM's big servers. In that case the files are completely separated and the partition works with no I/O issues.

Based on this observation, we've switched the production environment to a dedicated server with the specifications described in the first post of this thread, and most of the problems with threads creation and destruction are gone.

The next step was to adjust the configuration file. I guess the biggest challenge to everybody using OpenACS is the best relation between number of users X maxconnections X requests X maxthreads. This is the part where we are stuck right now. According to this Gustaf's Post on AOLServer list:

the question certainly is, what "concurrent users" means (...) note, that when talking about "concurrent users", it might be the case that one user has many requests concurrently running. To simplify things, we should talk about e.g. 10 concurrent requests.

Then you need
- at least 10 threads
- at least 10 connections
The number of database connections is more difficult to estimate, since
this in an application(oacs) matter. In oacs, most dynamic requests need
1 or 2 db connections concurrently.

I know this is not like a cookbook, but using his observation we could think about one thread, one connection and 2 db connections for each request. With these parameters, concerning that the tests are going to perform all the requests we configure at the same time, the results are most likely following this logic. When we set the maxthreads to 150, there's a little bit of degradation in memory trying to serve 100 simultaneous requests. This degradation is over when you set the parameters minthreads to 80 and maxthreads to 120. What we can get from here is that one thread is able to serve one request in the best performance adjustments.

However, when you send these setting to production, there's maybe the most difficult problem: to estimate the number of requests per user. Maybe one patch in xotcl-request-monitor could answer this question, but we are still thinking about the best way to do it. We could also see that the number of connections per user is very different from the relation 1 X 1, and this another thing we are trying to find the best relation.

<h4> PostgreSQL Tunning </h4>

All the tests we are performing until now consider DB and OpenACS in the same box. The goal is to find out the performance limit to this setting, so we can remove PostgreSQL from the machine and measure how it gets better.

There's a lot of material for PostgreSQL in the Internet, and I'm not one specialist myself, but I guess there are some specific observations that could be done.

Everybody says that Internet applications are doing most of the time SELECT operations in the database. This is a myth. If you consider number of operations maybe it can be true, but it's not when you consider execution time and resources usage. The number of TPS (Transactions Per Second) in an application using OpenACS is very large, and that's a good thing. In the old Internet you where creating content to people see. The new paradigm says the opposite: now the users create the content, and that's why I use OpenACS. There's just no better option to build social and collaborative networks in the market.

Concerning this matter, most of PostgreSQL tuning involves transaction improvements. I can't still understand completely the pools mechanism that OpenACS uses for PostgreSQL, and I guess some improvement in this area could make my tests better.

The most important thing to adjust here is the shared memory mechanism. We've seen that, if you put a too big number in PostgreSQL and OS, the memory shared between PostgreSQL and AOLServer can cause the system to crash under stress situations, and that's not a good thing. The I/O becomes a problem with a large number of INSERT and DELETE operations, mostly because the thread creation process is also heavy for the system.

The conclusion is: if you want to have the best performance, you really have to split AOLServer and PostgreSQL in different boxes. The exact point to do it (DB size, number of users) is what we are trying to find out.

<h4> OS Tuning </h4>

Maybe this is the most difficult part to be done, because Linux has a lot of options that can be changed. A better analysis concerning resource usage is necessary so we can have better numbers. I'm going to put here a list of parameters we are changing in a Debian GNU/Linux Etch system:

# echo 2 > /proc/sys/vm/overcommit_memory
# echo 27910635520 > /proc/sys/kernel/shmmax
# echo 32707776 > /proc/sys/kernel/shmall
# echo deadline > /sys/block/sda/queue/scheduler
# echo 250 32000 100 128 > /proc/sys/kernel/sem
# cat /proc/sys/fs/file-max
753884
# echo 16777216 > /proc/sys/net/core/rmem_default
# echo 16777216 > /proc/sys/net/core/wmem_default
# echo 16777216 > /proc/sys/net/core/wmem_max
# echo 16777216 > /proc/sys/net/core/rmem_max

# su - postgres postgres@nodo406:~$ ulimit 753883

There are some other things, such as Kernel changes and TCP/IP configuration we are changing, but I don't think we have the better adjusts yet, so let's wait a little longer.

That's it. Sorry about the long post, but I guess I should give the community some qualified feedback, concerning all the help you guys always give to us.

Collapse
Posted by Gustaf Neumann on
Eduaro, short comments to some of your statements:

- The last change in /acs-tcl/tcl/pools-init.tcl was 15 months ago. You might have been affected by change in the default pool order, http://fisheye.openacs.org/browse/OpenACS/openacs-4/etc/config.tcl?r1=1.47&r2=1.48

- i don't see an kind of "XOTcl problem" in this discussion (maybe i am overly sensible in this question). The only "problem" is see is that the xotcl-core writes a message into the error log, when aolserver threads exit. They would exit as well without XOTcl being involved.

- setting maxthreads to 150 is very high. We use on our production site (more than 2200 concurrent users, up to 120 views per second) maxthreads of 100. by using background delivery, maxthreads can be normally reduced. keep in mind that ever connection thread (or thread for scheduled procs) contains a full blueprint of all used packages, these are 5.000-10.000 procs). In other words, for every thread there is a separate copy of all procs in memory. We are talking about 500.000 to maybe more than one million (!) tcl procs, when 100 threads are configured. This is not lightweight. When all threads go down (as sketched in my earlier posting), all these procs are deleted and maybe recreated immediately in new threads.

- "difficult problem ... estimate the number of requests per user": The request monitor gives you on the start page the actual number of users and the actual number of requests per minute (in the graph), and the actual views/sec and the avg. view time per user. If you have an average view time (AVT) per user of say 62 seconds, then the views per user (VPU) per minute is VPU = 60/AVT = 0.96.
Therefore, 100 users generate U*VPU requests per minute (with the sample values: 96). Getting estimates on Requests per user is just the simple part. More complex is to figure out, how many threads one will need for that. One needs the average processing time, which is unfortunately depending in reality, how many other requests are currently running (all requests share common resources and are therefore not independent).

- Anyhow, the request monitor shows you as well the number of currently running requests, and by observing this value one can estimate the number of required threads. If you have eg. 10 connection threads configured, and you observe that often 8 ore more requests are running, you are already running into limits. Once all connection threads are busy, the newly incoming requests are queued, causing further delays. Even simple requests (like e.g. a logo) can take significant time, since the response time to the user is queuing time + processing time. If the QT is 10 seconds, every request will take at least 10 seconds. If the machine was not able to process the incoming requests quickly enough with the configured threads in the past than it is questionable, when it will be able to catch up. So, queuing requests should be avoided. This is also one place, where the background delivery helps since it frees connection threads much earlier to do other work. On the other hand, if you have e.g. 30 connection threads configured, and you see normally only 2 or three concurrent requests, you are most probably wasting resources.

- i do not agree with the conclusion "for best performance, you really have to split AOLServer and PostgreSQL" to different servers. It depends on the machines. Maybe you are correct with dual or quad-core Intel processors. If the database and aolserver are on the same machine, and you have enough memory and your have enough CPU powers (e.g. 8 cores or more) and your machine has a decent memory-throughput/latency, then local communication between database and aolserver is significantly faster. There are situations, where performance is better, when database and aolserver are on the same machine, even if the server is very busy (as on our learn@wu system). Certainly, it depends on the hardware and the usage patterns.

- concerning running in VMs: i completely agree, for a busy production site, using VMs is not good idea - at least not for beginners (tuning VMs and the hosting environment can help a lot, but there is yet another layer to fiddle around) Usually you have only one cpu visible from inside the VM, so using multiple CPUs (one strength of aolserver + postgres) won't help, so scalability is limited. This is one experience we are going currently through with openacs.org.

have to rush
-gustaf

Collapse
Posted by Gustaf Neumann on
PS: with upcoming processors like POWER7 http://en.wikipedia.org/wiki/POWER7 or Rock http://en.wikipedia.org/wiki/Rock_(processor), we will get 32 simultaneous threads (SMT) per chip! Linux will see this as 32 processors. Cool machines for running OpenACS and PostgreSQL.
Collapse
Posted by Neophytos Demetriou on
True, if the only option (due to the architecture) is to scale up (as opposed to the ability to scale out).
Collapse
Posted by Gustaf Neumann on
i don't see these options as alternatives, but as directions. It is bad if one has multiple cores in a machine is not able to use it. The basic OpenACS infrastructure was built for multiple processing units. The point is simply: the micro-processor designers stopped a few years ago to increase frequencies and to add cores and SMT. These chips arrive now, Aolserver and OpenACS are ready to use them - NOW.

It would be certainly an interesting project to build something like OpenACS based on a P2P-network and DHTs (cassandra, bigtable, ... coral, cfs, oceanstore .... pier), but this will be a different project, since some basic assumption about the data storage are different.

Collapse
Posted by Neophytos Demetriou on
It is also bad if you need an expensive machine to be able to scale (read that as scale linearly). BTW, I would not classify Cassandra as a DHT in the same way that I would not classify PostgreSQL as a file system. The basic assumptions about the programming language and programming style were different for xowiki so I don't see your point about the project talk.
Collapse
Posted by Gustaf Neumann on
The costs of processor per machine went down over the last yeas dramatically. ten years ago, a dual processor machine had the cost of a mainframe (i remember alta-vista vs. google discussions). today, a quadcore processor cost a few hundert dollar. i would expect a similar price for 32 cores in a few years from now.

Sure, DHT is just the basic workhorse, most of the other examples have also quite different properties than e.g. cassandra. What is the problem with the term "project"? xotcl-core and xowiki went out to be compatible with the acs data model. There is nothing wrong in having a project developing an acs package based on p2p technology. Many people will appreciate it. From the scope of the work, it is a project.

Collapse
Posted by Neophytos Demetriou on
Yes, from the scope of the work, it is a project. It's the *different* project part that I did not get the point ;)
Collapse
Posted by Neophytos Demetriou on
Furthermore, different file systems have different properties but that does not make them ACID-compliant databases.

Now, an interesting argument would be the one that makes the case for the use of ACID properties for content-oriented applications and semi-structured data.

Collapse
Posted by Brian Fenton on
Hi everybody,

this is a very interesting discussion.

Gustaf, you said: "by using background delivery, maxthreads can be normally reduced." Can you explain a little bit more how you use background delivery? What's a good case for background delivery, and what isn't? Can you point to any examples?

many thanks
Brian

Collapse
Posted by Neophytos Demetriou on
Hi Brian, if you 've got a lot of long-running threads after a while you can no longer serve any requests. Using background delivery you can delegate the serving of large files to a single thread that manages multiple channels (sockets).

You can do the same thing for resources (css, javascript, images, graphics) using a reverse proxy. The idea is that you should not keep threads loaded with the full blueprint of your installation for these tasks.

The way you use background delivery is similar to ns_returnfile, i.e.

ad_returnfile_background 200 [ns_guesstype ${filename}] ${filename}

Though, you need to make sure that you have tthread installed and the background delivery code that Gustaf wrote.

PS. The NaviServer project went the extra mile of serving requests by loading the procs dynamically --- only those required for a given request. My understanding is that the xorb package does something similar but at a higher level of abstraction.

Collapse
Posted by Gustaf Neumann on
i agree with most of the statements. background delivery is more general than the reverse proxy, since one can do all permission checking etc. as usual in openacs, just the spooling is done via a single thread. This single thread can spool simultaneously several thousands of requests. You can't do that with threads (at least not without modifying the linux kernel). We run into scalability problems with pound (thread based) which were solved by moving to nginx (async delivery).

neophytos, i think, you meant tclthreads and not "tthread" (which sounds close to zoran's ttrace). The c-level code for background delivery is part of naviserver and aolserver 4.5 in the cvs head version. You find patches for aolserver 4.0 and plain 4.5 in the wiki.

xorb is very different from ttrace and is no replacement. ttrace can help to make threads thinner, at the cost of making introspection more complex/wrong. ttrace is not (at least was not) depending on any naviserver code, Zoran wrote it for aolserver. ttrace has XOTcl support and vice versa.

The primary argument in the discussion above: assume you have 10 connection threads configured and you want to server some larger files over some slower lines (600 MB files, delivery might take 2 minutes per request). If 10 people download these files via connection threads at the same time, the server won't be able to serve any requests for these 2 minutes, since tall connection threads are busy; incoming requests will be queued. When you have bgdelivery installed, the connection thread is only used for permission checking and file location on the disk (usually a few milliseconds). This leads to much better scalability.

Collapse
Posted by Neophytos Demetriou on
about nginx: I did that as well but nginx has/had some trouble with the COMET stuff (as opposed to pound that works fine). Still, I'm using nginx.

about tclthreads: The package on TCL's file distribution area (on sf) is called thread-2.6.5 (not sure if that's what you mean). That package also includes ttrace, yes.

about ttrace: NaviServer has that integrated or makes use of it in order to provide tracing as an option. I haven't used that due to some problems that existed between that mechanism and XOTCL back when I tried (as soon as it was released). I remember sending you a message about that but I am not sure what's the current status.

about xorb: yes, I did not mean to imply that it is a replacement but it does serialize/deserialize code from a single thread and it also makes threads thinner, right? (just asking)

Collapse
Posted by Neophytos Demetriou on
The c-level code for background delivery is part of 
naviserver and aolserver 4.5 in the cvs head version. You 
find patches for aolserver 4.0 and plain 4.5 in the wiki.
If you use NaviServer, it's already there.
Collapse
Posted by Neophytos Demetriou on
Please disregard the comment "if you use NaviServer, it's already there". The only way to actually use it is to get the cvs head version :)
Collapse
Posted by Brian Fenton on
Hi Neophytos!
Good to see you on the forums again.

Ok, I got it - it's a drop-in replacement for ns_returnfile. Very useful to know about.

thanks,
Brian

Collapse
Posted by Gustaf Neumann on
Since this thread turns out out be a kind of tutorial, here some completion of the information: ad_returnfile_background is part of xotcl-core and has the following requirements
  1. xotcl-core (sure, if it is defined there)
  2. one needs either a "new" aolserver, or an "old" with the required patches (see discussion above and Boost...), and
  3. one has to have libthread installed (tcl thread library, as described in the request-monitor wiki page)
If you have e.g. only (1), you will have as well a function named ad_returnfile_background, but this will just call ns_returnfile.

Hope this helps -gustaf neumann

Collapse
Posted by Rocael Hernández Rizzardini on
Brian, more info is here: Boost your application performance...
Collapse
Posted by Eduardo Santos on
Hi Gustaf,

Your considerations are very helpful, as they always are. I can have now a more general view about threads X requests behavior. I'll try to make comments based on what you've posted.

- When I said there was a XoTcl problem, I was talking about how the destroy process can be painful depending on the OS + Hardware set. But as you said better, it's not like a XoTcl problem, is more like an AOLServer problem. I guess we agree here.

- I guess I could finally understand what the threads are meant to do. If you have a portion of memory that includes all the procs in the system that can be shared, I can see how 150 is a too large number. Thank you very much for this explanation. I was seeing in production an error that says that maxconnections is exceeded, even with machine resources available. Your explanation shows me that there where a lot of threads in queue waiting for a large download to finish,and background delivery could be a solution for that. I'll think about more testing on that and I'll give everybody a feedback about it.

- About use PostgreSQL and AOLServer in the same box, I've seen in this post here that you run in learn@wu the IBM logical partitions. Is that right? In that case you have no degradation and the system allows you to do everything in the same box without I/O issues. If you consider that a socket connection is quite faster than a TCP/IP one, it's probably a good idea to use the same box. Otherwise, I guess the split is a better option.

That's it. Thank you for the help.

Collapse
Posted by Gustaf Neumann on
Hi Eduardo,

even the mentioned problem (were many thread terminate at the same time) is gone with the actual head version of aolserver.

i am not sure about your question in the last paragraph. Yes, our production server of learn@wu (aolserver + postgres 8.2.*) runs in a single partition of the machine, using 6 of the 8 processors. We have still the same hardware as at the time of my posting with the figures (2005, earlier in the same forum thread), but we are now up to more than 2000 concurrent users, more than 60.000 learning resources, etc. and still below 0.4 seconds per view. The second partition of the server is used for development. The logical partition do not help to make anything faster and are more or less irrelevant in the discussion. We tested configurations with postgres or aolserver on other machines, but these setups were much slower.

As said earlier, if you run out of resources (e.g. cpu power), moving the database to a different (similar) server will certainly help. If one has already enough CPU and memory bandwith, putting the server on a different machine will slow things down.

Collapse
Posted by Eduardo Santos on
Hi Gustaf,

Now I've got what you said. You see: IBM has an OS split mechanism called LPAR or logical partitions, as it's explained here. Using this feature is like if you have a VM, but without the software and hardware limitations that makes it impossible to split completely the I/O between all the machines you have. I thought that was the case for your production system, wich now you say it's not.

If you consider that a socket connection is quite faster than a TCP/IP connection, I can see that having both DB and AOLServer in the same box can be faster if you have enough available resources.

Concerning our tests, however, there's something showing up that can bring more issues to this matter. Linux Kernel has a parameter that sets the maximum amount of shared memory your applications can use in the system, wich is located at /proc/sys/kernel/shmmax. This parameter controls, for example, the amount of memory PostgreSQL can use in the shared buffers. In our test cases, we had the following set of parameters:

## AOLServer parameters
ns_section ns/threads
    ns_param   mutexmeter         true      ;# measure lock contention
    # The per-thread stack size must be a multiple of 8k for AOLServer to run under MacOS X
    ns_param   stacksize          [expr 1 * 8192 * 256]

ns_section ns/server/${server} ns_param maxconnections 1000 ;# Max connections to put on queue ns_param maxdropped 0 ns_param maxthreads 300 ;# Tune this to scale your server ns_param minthreads 200 ;# Tune this to scale your server ns_param threadtimeout 120 ;# Idle threads die at this rate ns_param globalstats false ;# Enable built-in statistics ns_param urlstats true ;# Enable URL statistics ns_param maxurlstats 1000 ;# Max number of URL's to do stats on

ns_section ns/db/pool/pool1 # ns_param maxidle 0 # ns_param maxopen 0 ns_param connections 200 ns_param verbose $debug ns_param extendedtableinfo true ns_param logsqlerrors $debug if { $database == "oracle" } { ns_param driver ora8 ns_param datasource {} ns_param user $db_name ns_param password $db_password } else { ns_param driver postgres ns_param datasource ${db_host}:${db_port}:${db_name} ns_param user $db_user ns_param password "" }

ns_section ns/db/pool/pool2 # ns_param maxidle 0 # ns_param maxopen 0 ns_param connections 150 ns_param verbose $debug ns_param extendedtableinfo true ns_param logsqlerrors $debug if { $database == "oracle" } { ns_param driver ora8 ns_param datasource {} ns_param user $db_name ns_param password $db_password } else { ns_param driver postgres ns_param datasource ${db_host}:${db_port}:${db_name} ns_param user $db_user ns_param password "" }

ns_section ns/db/pool/pool3 # ns_param maxidle 0 # ns_param maxopen 0 ns_param connections 150 ns_param verbose $debug ns_param extendedtableinfo true ns_param logsqlerrors $debug if { $database == "oracle" } { ns_param driver ora8 ns_param datasource {} ns_param user $db_name ns_param password $db_password } else { ns_param driver postgres ns_param datasource ${db_host}:${db_port}:${db_name} ns_param user $db_user ns_param password "" }

## Kernel Parameters: /proc/sys/kernel/shmall 2097152 /proc/sys/kernel/shmmax 2156978176

## PostgreSQL Parameters: max_connections = 1000 # (change requires restart) shared_buffers = 2000MB # min 128kB or max_connections*16kB work_mem = 1MB # min 64kB max_stack_depth = 5MB # min 100kB

With these values, the memory was corrupted and caused the database to crash under the stress test, wich means that PostgreSQL process did shut down all connections and killed the postmaster process, making the server to show a message and don't shut down or come back.

With all the information I have now, I can see this was probably caused by the huge amount of threads I've put. The new threads where trying to get more and more memory, and the OS just couldn't give it. As both AOLServer and PostgreSQL where theoretically using the same memory area, it caused the DB to corrupt and to kill the process. If they where split in different servers maybe this wouldn't happen, and it made us think that different servers are always the best solution. No matter what you do wrong and what happens to the server, the AOLServer crash will not kill the DB process and DB will also not kill AOLServer too. This could be the safer choice for the case.

Collapse
Posted by Gustaf Neumann on

If you consider that a socket connection is quite faster than a TCP/IP connection ...
Well one has to be more precise. One has to distinguish between a local socket (IPC socket, unix domain socket) and a networking socket (e.g. TCP socket). Local communication is faster (at least it should be) than remote communication.

As discussed above, the minthreads/maxthreads values of the configuration are not reasonable (not sure what you were trying to simulate/measure/...). I have certain doubts, that the memory was "corrupted", but i have no problems to believe that several processes crashed on your system when it run out of memory. For running large applications one should become familiar with system monitors that measure resource consumptions. This way one can spot shortages and adjust the parameters in reasonable ways.

Collapse
Posted by Eduardo Santos on
Hi everybody,

I'm bringing back this topic because one of the most discussed things was the background delivery. I'm running some tests and the results are really impressive. The waiting time is dramatically reduced as we have the control thread responsible for the downloads.

I've written a patch based based on oacs-5-3 that puts the background delivery in some more places. I've put it in the bugtracker and you can see it here: http://www.openacs.org/bugtracker/openacs/patch?patch_number=894

However, there's still something missing. When I look at the request-monitor running requests page, I can see a lot of files that are being downloaded for hours wich are still there. It seems like the channel isn't closed if the user doesn't finish the download in the usual way.

Perharps we should have some kind of scheduled procedure to close this kind of channel, or some tool to check if it isn't used anymore, but I don't have a clue on how to do it. Can somebody point me a direction on that?