You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@jackrabbit.apache.org by al...@apache.org on 2011/10/13 15:19:38 UTC
svn commit: r1182835 - in
/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java
persistence/bundle/AbstractBundlePersistenceManager.java
Author: alexparvulescu
Date: Thu Oct 13 13:19:38 2011
New Revision: 1182835
URL: http://svn.apache.org/viewvc?rev=1182835&view=rev
Log:
JCR-3098 Add hit miss statistics and logging to caches
- patch by Bart van der Schans, continued
Modified:
jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java
jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java
jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java
Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java
URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java?rev=1182835&r1=1182834&r2=1182835&view=diff
==============================================================================
--- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java (original)
+++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java Thu Oct 13 13:19:38 2011
@@ -114,6 +114,7 @@ public abstract class AbstractCache impl
* interval has passed since the previous listener call.
*/
protected void recordCacheAccess() {
+ totalAccessCount.incrementAndGet();
long count = accessCount.incrementAndGet();
if (count % ACCESS_INTERVAL == 0) {
CacheAccessListener listener = accessListener.get();
@@ -121,7 +122,6 @@ public abstract class AbstractCache impl
listener.cacheAccessed(count);
}
}
- totalAccessCount.incrementAndGet();
}
protected void recordCacheMiss() {
@@ -186,13 +186,13 @@ public abstract class AbstractCache impl
long u = getMemoryUsed() / 1024;
long m = getMaxMemorySize() / 1024;
StringBuilder c = new StringBuilder();
- c.append("Cache name=");
+ c.append("cachename=");
c.append(this.toString());
c.append(", elements=");
c.append(getElementCount());
- c.append(", used memory=");
+ c.append(", usedmemorykb=");
c.append(u);
- c.append(", max memory=");
+ c.append(", maxmemorykb=");
c.append(m);
c.append(", access=");
c.append(getTotalAccessCount());
Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java
URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java?rev=1182835&r1=1182834&r2=1182835&view=diff
==============================================================================
--- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java (original)
+++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java Thu Oct 13 13:19:38 2011
@@ -156,17 +156,18 @@ public class CacheManager implements Cac
* Log info about the caches.
*/
private void logCacheStats() {
- if (log.isDebugEnabled()) {
+ if (log.isInfoEnabled()) {
long now = System.currentTimeMillis();
if (now < nextLogStats) {
return;
}
for (Cache cache : caches.keySet()) {
- log.debug(cache.getCacheInfoAsString());
+ log.info(cache.getCacheInfoAsString());
}
nextLogStats = now + minLogStatsInterval;
}
}
+
/**
* Re-calculate the maximum memory for each cache, and set the new limits.
*/
Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java
URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java?rev=1182835&r1=1182834&r2=1182835&view=diff
==============================================================================
--- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java (original)
+++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java Thu Oct 13 13:19:38 2011
@@ -28,6 +28,8 @@ import javax.jcr.PropertyType;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+import org.apache.jackrabbit.core.cache.Cache;
+import org.apache.jackrabbit.core.cache.CacheAccessListener;
import org.apache.jackrabbit.core.cache.ConcurrentCache;
import org.apache.jackrabbit.core.fs.FileSystemResource;
import org.apache.jackrabbit.core.fs.FileSystem;
@@ -82,7 +84,7 @@ import org.apache.jackrabbit.spi.Name;
* </ul>
*/
public abstract class AbstractBundlePersistenceManager implements
- PersistenceManager, CachingPersistenceManager, IterablePersistenceManager {
+ PersistenceManager, CachingPersistenceManager, IterablePersistenceManager, CacheAccessListener {
/** the default logger */
private static Logger log = LoggerFactory.getLogger(AbstractBundlePersistenceManager.class);
@@ -112,6 +114,18 @@ public abstract class AbstractBundlePers
/** the cache of loaded bundles */
private ConcurrentCache<NodeId, NodePropBundle> bundles;
+ /** The default minimum stats logging interval (in ms). */
+ private static final int DEFAULT_LOG_STATS_INTERVAL = 60 * 1000;
+
+ /** The minimum interval time between stats are logged */
+ private long minLogStatsInterval = Long.getLong(
+ "org.apache.jackrabbit.cacheLogStatsInterval",
+ DEFAULT_LOG_STATS_INTERVAL);
+
+ /** The last time the cache stats were logged. */
+ private volatile long nextLogStats =
+ System.currentTimeMillis() + DEFAULT_LOG_STATS_INTERVAL;
+
/** the persistence manager context */
protected PMContext context;
@@ -379,6 +393,7 @@ public abstract class AbstractBundlePers
// init bundle cache
bundles = new ConcurrentCache<NodeId, NodePropBundle>(context.getHomeDir().getName() + "BundleCache");
bundles.setMaxMemorySize(bundleCacheSize);
+ bundles.setAccessListener(this);
}
/**
@@ -709,4 +724,22 @@ public abstract class AbstractBundlePers
bundles.remove(id);
}
+ public void cacheAccessed(long accessCount) {
+ logCacheStats();
+ }
+
+ private void logCacheStats() {
+ if (log.isInfoEnabled()) {
+ long now = System.currentTimeMillis();
+ if (now < nextLogStats) {
+ return;
+ }
+ log.info(bundles.getCacheInfoAsString());
+ nextLogStats = now + minLogStatsInterval;
+ }
+ }
+
+ public void disposeCache(Cache cache) {
+ // NOOP
+ }
}
Re: svn commit: r1182835 - in /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java persistence/bundle/AbstractBundlePersistenceManager.java
Posted by Stefan Guggisberg <st...@gmail.com>.
On Thu, Oct 13, 2011 at 5:23 PM, Bart van der Schans
<b....@onehippo.com> wrote:
> On Thu, Oct 13, 2011 at 4:51 PM, Stefan Guggisberg
> <st...@gmail.com> wrote:
>> hi bart,
>>
>> On Thu, Oct 13, 2011 at 4:44 PM, Bart van der Schans
>> <b....@onehippo.com> wrote:
>>> Hi Stefan,
>>>
>>> On Thu, Oct 13, 2011 at 4:27 PM, Stefan Guggisberg
>>> <st...@gmail.com> wrote:
>>>>> - if (log.isDebugEnabled()) {
>>>>> + if (log.isInfoEnabled()) {
>>>>
>>>> what's the justification for changing the log level from debug to info?
>>>
>>> This is to make a distinction between the debug logging of the cache
>>> resizing which logs quite a bit of info every second and the logging
>>> of the cache (access/hit/miss) stats which log every minute
>>> (configurable). It's comparable to the logging of the stats of the
>>> bundle cache in 1.x which was also set on info.
>>
>> thanks for the explanation. i'd prefer to stick to the debug log level
>> for this kind of polled, i.e. repeating status information. the info
>> log level is
>> imo fine for logging single status change events (e.g. 'repository started')
>
> In general I agree. In this particular case, how can we log the stats
> on debug without flooding the logs with the debug output from the
> resizeAll() method?
ok, i get your point.
> Can we use TRACE log level for the resizing
> logging?
i guess yes, that's a good idea.
cheers
stefan
> Or is there some configuration trick in the logging (log4j)
> config that I'm missing that can be used to achieve that? I guess this
> "problem" will solve itself once we get the JMX bindings in place.
>
> Regards,
> Bart
>
>>
>> cheers
>> stefan
>>
>>>
>>> Regards,
>>> Bart
>
Re: svn commit: r1182835 - in /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java persistence/bundle/AbstractBundlePersistenceManager.java
Posted by Jukka Zitting <ju...@gmail.com>.
Hi,
On Thu, Oct 13, 2011 at 5:23 PM, Bart van der Schans
<b....@onehippo.com> wrote:
> In general I agree. In this particular case, how can we log the stats
> on debug without flooding the logs with the debug output from the
> resizeAll() method? Can we use TRACE log level for the resizing
> logging? Or is there some configuration trick in the logging (log4j)
> config that I'm missing that can be used to achieve that?
You can override the logging level per-logger.
But yes, as you mention, I logging is not the ideal way to expose
execution statistics like these. The work in JCR-3040 has been
progressing well lately, and should be usable pretty soon.
BR,
Jukka Zitting
Re: svn commit: r1182835 - in /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java persistence/bundle/AbstractBundlePersistenceManager.java
Posted by Bart van der Schans <b....@onehippo.com>.
On Thu, Oct 13, 2011 at 4:51 PM, Stefan Guggisberg
<st...@gmail.com> wrote:
> hi bart,
>
> On Thu, Oct 13, 2011 at 4:44 PM, Bart van der Schans
> <b....@onehippo.com> wrote:
>> Hi Stefan,
>>
>> On Thu, Oct 13, 2011 at 4:27 PM, Stefan Guggisberg
>> <st...@gmail.com> wrote:
>>>> - if (log.isDebugEnabled()) {
>>>> + if (log.isInfoEnabled()) {
>>>
>>> what's the justification for changing the log level from debug to info?
>>
>> This is to make a distinction between the debug logging of the cache
>> resizing which logs quite a bit of info every second and the logging
>> of the cache (access/hit/miss) stats which log every minute
>> (configurable). It's comparable to the logging of the stats of the
>> bundle cache in 1.x which was also set on info.
>
> thanks for the explanation. i'd prefer to stick to the debug log level
> for this kind of polled, i.e. repeating status information. the info
> log level is
> imo fine for logging single status change events (e.g. 'repository started')
In general I agree. In this particular case, how can we log the stats
on debug without flooding the logs with the debug output from the
resizeAll() method? Can we use TRACE log level for the resizing
logging? Or is there some configuration trick in the logging (log4j)
config that I'm missing that can be used to achieve that? I guess this
"problem" will solve itself once we get the JMX bindings in place.
Regards,
Bart
>
> cheers
> stefan
>
>>
>> Regards,
>> Bart
Re: svn commit: r1182835 - in /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java persistence/bundle/AbstractBundlePersistenceManager.java
Posted by Stefan Guggisberg <st...@gmail.com>.
hi bart,
On Thu, Oct 13, 2011 at 4:44 PM, Bart van der Schans
<b....@onehippo.com> wrote:
> Hi Stefan,
>
> On Thu, Oct 13, 2011 at 4:27 PM, Stefan Guggisberg
> <st...@gmail.com> wrote:
>>> - if (log.isDebugEnabled()) {
>>> + if (log.isInfoEnabled()) {
>>
>> what's the justification for changing the log level from debug to info?
>
> This is to make a distinction between the debug logging of the cache
> resizing which logs quite a bit of info every second and the logging
> of the cache (access/hit/miss) stats which log every minute
> (configurable). It's comparable to the logging of the stats of the
> bundle cache in 1.x which was also set on info.
thanks for the explanation. i'd prefer to stick to the debug log level
for this kind of polled, i.e. repeating status information. the info
log level is
imo fine for logging single status change events (e.g. 'repository started')
cheers
stefan
>
> Regards,
> Bart
>
Re: svn commit: r1182835 - in /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java persistence/bundle/AbstractBundlePersistenceManager.java
Posted by Bart van der Schans <b....@onehippo.com>.
Hi Stefan,
On Thu, Oct 13, 2011 at 4:27 PM, Stefan Guggisberg
<st...@gmail.com> wrote:
>> - if (log.isDebugEnabled()) {
>> + if (log.isInfoEnabled()) {
>
> what's the justification for changing the log level from debug to info?
This is to make a distinction between the debug logging of the cache
resizing which logs quite a bit of info every second and the logging
of the cache (access/hit/miss) stats which log every minute
(configurable). It's comparable to the logging of the stats of the
bundle cache in 1.x which was also set on info.
Regards,
Bart
Re: svn commit: r1182835 - in /jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core:
cache/AbstractCache.java cache/CacheManager.java persistence/bundle/AbstractBundlePersistenceManager.java
Posted by Stefan Guggisberg <st...@gmail.com>.
> - if (log.isDebugEnabled()) {
> + if (log.isInfoEnabled()) {
what's the justification for changing the log level from debug to info?
On Thu, Oct 13, 2011 at 3:19 PM, <al...@apache.org> wrote:
> Author: alexparvulescu
> Date: Thu Oct 13 13:19:38 2011
> New Revision: 1182835
>
> URL: http://svn.apache.org/viewvc?rev=1182835&view=rev
> Log:
> JCR-3098 Add hit miss statistics and logging to caches
> - patch by Bart van der Schans, continued
>
> Modified:
> jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java
> jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java
> jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java
>
> Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java
> URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java?rev=1182835&r1=1182834&r2=1182835&view=diff
> ==============================================================================
> --- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java (original)
> +++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/AbstractCache.java Thu Oct 13 13:19:38 2011
> @@ -114,6 +114,7 @@ public abstract class AbstractCache impl
> * interval has passed since the previous listener call.
> */
> protected void recordCacheAccess() {
> + totalAccessCount.incrementAndGet();
> long count = accessCount.incrementAndGet();
> if (count % ACCESS_INTERVAL == 0) {
> CacheAccessListener listener = accessListener.get();
> @@ -121,7 +122,6 @@ public abstract class AbstractCache impl
> listener.cacheAccessed(count);
> }
> }
> - totalAccessCount.incrementAndGet();
> }
>
> protected void recordCacheMiss() {
> @@ -186,13 +186,13 @@ public abstract class AbstractCache impl
> long u = getMemoryUsed() / 1024;
> long m = getMaxMemorySize() / 1024;
> StringBuilder c = new StringBuilder();
> - c.append("Cache name=");
> + c.append("cachename=");
> c.append(this.toString());
> c.append(", elements=");
> c.append(getElementCount());
> - c.append(", used memory=");
> + c.append(", usedmemorykb=");
> c.append(u);
> - c.append(", max memory=");
> + c.append(", maxmemorykb=");
> c.append(m);
> c.append(", access=");
> c.append(getTotalAccessCount());
>
> Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java
> URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java?rev=1182835&r1=1182834&r2=1182835&view=diff
> ==============================================================================
> --- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java (original)
> +++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/cache/CacheManager.java Thu Oct 13 13:19:38 2011
> @@ -156,17 +156,18 @@ public class CacheManager implements Cac
> * Log info about the caches.
> */
> private void logCacheStats() {
> - if (log.isDebugEnabled()) {
> + if (log.isInfoEnabled()) {
> long now = System.currentTimeMillis();
> if (now < nextLogStats) {
> return;
> }
> for (Cache cache : caches.keySet()) {
> - log.debug(cache.getCacheInfoAsString());
> + log.info(cache.getCacheInfoAsString());
> }
> nextLogStats = now + minLogStatsInterval;
> }
> }
> +
> /**
> * Re-calculate the maximum memory for each cache, and set the new limits.
> */
>
> Modified: jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java
> URL: http://svn.apache.org/viewvc/jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java?rev=1182835&r1=1182834&r2=1182835&view=diff
> ==============================================================================
> --- jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java (original)
> +++ jackrabbit/trunk/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/persistence/bundle/AbstractBundlePersistenceManager.java Thu Oct 13 13:19:38 2011
> @@ -28,6 +28,8 @@ import javax.jcr.PropertyType;
>
> import org.slf4j.Logger;
> import org.slf4j.LoggerFactory;
> +import org.apache.jackrabbit.core.cache.Cache;
> +import org.apache.jackrabbit.core.cache.CacheAccessListener;
> import org.apache.jackrabbit.core.cache.ConcurrentCache;
> import org.apache.jackrabbit.core.fs.FileSystemResource;
> import org.apache.jackrabbit.core.fs.FileSystem;
> @@ -82,7 +84,7 @@ import org.apache.jackrabbit.spi.Name;
> * </ul>
> */
> public abstract class AbstractBundlePersistenceManager implements
> - PersistenceManager, CachingPersistenceManager, IterablePersistenceManager {
> + PersistenceManager, CachingPersistenceManager, IterablePersistenceManager, CacheAccessListener {
>
> /** the default logger */
> private static Logger log = LoggerFactory.getLogger(AbstractBundlePersistenceManager.class);
> @@ -112,6 +114,18 @@ public abstract class AbstractBundlePers
> /** the cache of loaded bundles */
> private ConcurrentCache<NodeId, NodePropBundle> bundles;
>
> + /** The default minimum stats logging interval (in ms). */
> + private static final int DEFAULT_LOG_STATS_INTERVAL = 60 * 1000;
> +
> + /** The minimum interval time between stats are logged */
> + private long minLogStatsInterval = Long.getLong(
> + "org.apache.jackrabbit.cacheLogStatsInterval",
> + DEFAULT_LOG_STATS_INTERVAL);
> +
> + /** The last time the cache stats were logged. */
> + private volatile long nextLogStats =
> + System.currentTimeMillis() + DEFAULT_LOG_STATS_INTERVAL;
> +
> /** the persistence manager context */
> protected PMContext context;
>
> @@ -379,6 +393,7 @@ public abstract class AbstractBundlePers
> // init bundle cache
> bundles = new ConcurrentCache<NodeId, NodePropBundle>(context.getHomeDir().getName() + "BundleCache");
> bundles.setMaxMemorySize(bundleCacheSize);
> + bundles.setAccessListener(this);
> }
>
> /**
> @@ -709,4 +724,22 @@ public abstract class AbstractBundlePers
> bundles.remove(id);
> }
>
> + public void cacheAccessed(long accessCount) {
> + logCacheStats();
> + }
> +
> + private void logCacheStats() {
> + if (log.isInfoEnabled()) {
> + long now = System.currentTimeMillis();
> + if (now < nextLogStats) {
> + return;
> + }
> + log.info(bundles.getCacheInfoAsString());
> + nextLogStats = now + minLogStatsInterval;
> + }
> + }
> +
> + public void disposeCache(Cache cache) {
> + // NOOP
> + }
> }
>
>
>