Forum OpenACS Development: Re: Strange problem with util_memoize flush

Collapse
Posted by Eduardo Santos on
Hi Gustaf,

Thanks for the reply. I'm using HEAD version of AOLServer 4.5.1

Collapse
Posted by Eduardo Santos on
Oops, forgot the OpenACS version. I'm also using OpenACS 5.5.1 (from tag oacs-5-5 in CVS)
Collapse
Posted by Gustaf Neumann on
can you verify, that you don't load nscache.so from your config.tcl?
Collapse
Posted by Eduardo Santos on
Hi Gustaf,

I remember this problem when I updated the version, and I've taken out from my config.tcl the loading of nscache.so. This is the loading part in my log:


[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Error: pidfile: failed to open pid file '/usr/local/aolserver/log/nspid.ct-gcie': 'Permission deni
ed'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: encoding: loaded: utf-8
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: fastpath[ct-gcie]: mapped GET /
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: fastpath[ct-gcie]: mapped HEAD /
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: fastpath[ct-gcie]: mapped POST /
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: adp[ct-gcie]: mapped GET /*.adp
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: adp[ct-gcie]: mapped HEAD /*.adp
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: adp[ct-gcie]: mapped POST /*.adp
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nssock.so'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nslog.so'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: nslog: opened '/srv/logs/ct-gcie/uxmpog001/ct-gcie.log'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nssha1.so'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nsdb.so'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: modload: loading '/usr/local/aolserver/bin/nspostgres.so'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: PostgreSQL loaded.
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: modload: loading '/usr/local/aolserver/lib/thread2.6.5/libthread2.6.5.so'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: conf: [ns/server/ct-gcie]enabletclpages = 0
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: default thread pool: minthreads 20 maxthreads 30 idle 0 current 0 maxconns 100 queued 0 ti
meout 120 spread 20
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: stats: web stats enabled for '/_stats'
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: XOTcl version 1.6.3 loaded
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: Loading OpenACS, rooted at /var/www/ct-gcie
[13/Jan/2011:03:00:05][15181.18446744071738828512][-main-] Notice: Sourcing /var/www/ct-gcie/packages/acs-bootstrap-installer/bootstrap.tcl

Thanks for the help.

Collapse
Posted by Gustaf Neumann on
My "hope" was that you had some misconfiguration, but so far, i can't see anything obvious. How large is your util_memoize cache? I tried for a while to reproduce the problem with variations of
string length [util_memoize {string repeat abcde 30000}]
in the ds/shell, but could not reproduce the problem. Can you produce a sequence of util_memoize commands like the one above (e.g. loop) to reproduce the problem on your site?
Collapse
Posted by Eduardo Santos on
Hi Gustaf,

My cache is 200000 MB large, and the problem happens clearly when the cache gets full. I can see from AOLServer stats the following info:

Cache Max Current Entries Flushes Hits Misses Hit Rate
xowiki_cache 200000 2026 6 0 110 106 50%
xotcl_object_type_cache 10000 346 37 35809 92407 35846 72%
xotcl_object_cache 400000 19591 16 0 6152 16 99%
util_memoize 200000 199939 2852 7557 1109321 26009 97%
secret_tokens 32768 600 15 0 300 15 95%
nsfp:ct-gcie 5120000 934418 137 0 1557 137 91%
nsfp: 5120000 0 0 0 0 0 0%
ns:dnshost 100 0 0 0 0 0 0%
ns:dnsaddr 100 5 5 0 230 5 97%
ds_page_bits 10000000 0 0 0 0 0 0%
db_cache_pool 200000 20 2 0 7841 2 99%

When the cache gets close to the limit and the system try to reload it, it fails and the reloading proccess lasts forever.

Collapse
Posted by Gustaf Neumann on
The statistics indicate that your util_memoize cache is 200000 bytes, not MB! I do not understand the last sentence. What exactly is "it"?

Yet another attempt to help you:
Run the following script in your ds/shell:

foreach i {1 2 3 4} {util_memoize [list string repeat abcde 3998$i]}
append _ "nearly full: " [ns_cache_size util_memoize] " "
foreach i {4 3 2 1} {util_memoize [list string repeat abcde $i]}
append _ "over full: " [ns_cache_size util_memoize]
The first line fills your cache to the size 199931 bytes. The third line crosses in several steps the 200k border. Does this work on your machine?