Forum OpenACS Development: Re: Strange problem with util

3: Re: Strange problem with util_memoize flush (response to 2)

Posted by Eduardo Santos on 01/13/11 05:32 PM

Hi Gustaf,

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

4: Re: Strange problem with util_memoize flush (response to 3)

Posted by Eduardo Santos on 01/13/11 05:33 PM

Oops, forgot the OpenACS version. I'm also using OpenACS 5.5.1 (from tag oacs-5-5 in CVS)

5: Re: Strange problem with util_memoize flush (response to 3)

Posted by Gustaf Neumann on 01/13/11 07:17 PM

can you verify, that you don't load nscache.so from your config.tcl?

6: Re: Strange problem with util_memoize flush (response to 5)

Posted by Eduardo Santos on 01/13/11 07:29 PM

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.

7: Re: Strange problem with util_memoize flush (response to 6)

Posted by Gustaf Neumann on 01/20/11 01:36 PM

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?

8: Re: Strange problem with util_memoize flush (response to 7)

Posted by Eduardo Santos on 01/20/11 03:17 PM

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.

9: Re: Strange problem with util_memoize flush (response to 8)

Posted by Gustaf Neumann on 01/20/11 08:43 PM

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?

Forum OpenACS Development: Re: Strange problem with util_memoize flush