Forum OpenACS Q&A: cachingmode=none creates a log of ns_log notice entries in error.log

Collapse
1: cachingmode=none creates a log of ns_log notice entries in error.log
Posted by Marty Israelsen on 05/25/22 06:43 PM

We are using cachingmode=none with a cluster and it works great. But we get a lot of the following types of notices in the log. We are wondering if this is a problem or if the notices can just be removed.

It happens on every page refresh

...
[25/May/2022:09:54:19][1.7fa869ffb700][-conn:east_intrastage_test:default:18:566-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.062953
[25/May/2022:09:54:19][1.7fa89d7fa700][-conn:east_intrastage_test:default:12:568-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.063889
[25/May/2022:09:54:19][1.7fa89ffff700][-conn:east_intrastage_test:default:2:567-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.064051
[25/May/2022:09:54:19][1.7fa89ffff700][-conn:east_intrastage_test:default:2:567-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.064051
[25/May/2022:09:54:19][1.7fa89ffff700][-conn:east_intrastage_test:default:2:567-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.064051
[25/May/2022:09:54:19][1.7fa8697fa700][-conn:east_intrastage_test:default:19:569-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.066426
[25/May/2022:09:54:19][1.7fa89d7fa700][-conn:east_intrastage_test:default:12:568-] Notice: ns_cache create entry collision cache util_memoize key 'lang::user::site_wide_locale_not_cached 46788', no timeout
[25/May/2022:09:54:19][1.7fa869ffb700][-conn:east_intrastage_test:default:18:566-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa869ffb700][-conn:east_intrastage_test:default:18:566-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa89d7fa700][-conn:east_intrastage_test:default:12:568-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa89ffff700][-conn:east_intrastage_test:default:2:567-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa89d7fa700][-conn:east_intrastage_test:default:12:568-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa89d7fa700][-conn:east_intrastage_test:default:12:568-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa8697fa700][-conn:east_intrastage_test:default:19:569-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa869ffb700][-conn:east_intrastage_test:default:18:573-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key '1229403', timeout 1653494359.119234
[25/May/2022:09:54:19][1.7fa8697fa700][-conn:east_intrastage_test:default:19:574-] Notice: ns_cache create entry collision cache site_nodes_cache-0 key 'url-1229403', timeout 1653494359.120506
[25/May/2022:09:54:19][1.7fa8697fa700][-conn:east_intrastage_test:default:19:574-] Notice: ns_cache create entry collision cache util_memoize key 'lang::user::site_wide_locale_not_cached 46788', no timeout
[25/May/2022:09:54:19][1.7fa869ffb700][-conn:east_intrastage_test:default:18:573-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
[25/May/2022:09:54:19][1.7fa8697fa700][-conn:east_intrastage_test:default:19:574-] Notice: ns_cache create entry collision cache util_memoize key 'parameter::get_from_package_key -package_key employee-review -parameter UserIdVarName', no timeout
...

Thanks for your expertise, Marty

Collapse
2: Re: cachingmode=none creates a log of ns_log notice entries in error.log (response to 1)
Posted by Gustaf Neumann on 05/29/22 02:30 PM
Dear Marty,

"ns_cache_eval" works as follows:
1) create a temporary cache entry for the key
2) lock the cache-key (to avoid multiple parallel executions)
3) execute the query
4) store the result for the entry on success
5) unlock the cache-key

In nocache mode, it simply skips (4). The cache collision message means that while executing "ns_cache eval SOMECACHE SOMEKEY", a second call for the same cache and key was issued. In normal caching modes, this is desired to avoid computing the same (expensive) call multiple times in parallel. The later call(s) wait for the result of the first execution and return this.

In nocache mode, there is no cached result, and therefore, steps 1..5 can be skipped. I have just now added such a change to NaviServer on Bitbucket, such that multiple queries with the same key can be executed in parallel, without call serialization.

All the best
-gn

Collapse
3: Re: cachingmode=none creates a log of ns_log notice entries in error.log (response to 2)
Posted by Marty Israelsen on 06/02/22 04:48 PM
Thanks for adding this. I will bring down the latest to test it out when I get a free moment.

Sincerely,
Marty