From e654db6bfe73d5813b448af2e265e3d61ebca766 Mon Sep 17 00:00:00 2001 From: Brett Porter Date: Mon, 6 Dec 2010 15:56:35 +0000 Subject: [PATCH] [MRM-1442] track time spent in each consumer during a scan, to help diagnose poor scanning performance git-svn-id: https://svn.apache.org/repos/asf/archiva/branches/archiva-1.3.x@1042689 13f79535-47bb-0310-9956-ffa450edef68 --- .../scanner/RepositoryScanStatistics.java | 37 ++++++++++++++++++ .../scanner/RepositoryScannerInstance.java | 38 ++++++++++++++++--- .../functors/ConsumerProcessFileClosure.java | 36 +++++++++++++++++- .../webapp/WEB-INF/jsp/admin/systemStatus.jsp | 35 +++++++++++++---- 4 files changed, 131 insertions(+), 15 deletions(-) diff --git a/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScanStatistics.java b/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScanStatistics.java index 5d4fd3f06..4f18ff283 100644 --- a/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScanStatistics.java +++ b/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScanStatistics.java @@ -25,6 +25,7 @@ import org.apache.maven.archiva.model.RepositoryContentStatistics; import java.text.SimpleDateFormat; import java.util.List; +import java.util.Map; /** * RepositoryScanStatistics - extension to the RepositoryContentStatistics model. @@ -42,6 +43,10 @@ public class RepositoryScanStatistics private SimpleDateFormat df = new SimpleDateFormat(); + private Map consumerCounts; + + private Map consumerTimings; + public void triggerStart() { startTimestamp = System.currentTimeMillis(); @@ -94,6 +99,17 @@ public class RepositoryScanStatistics for ( String id : knownConsumers ) { buf.append( "\n " ).append( id ); + if ( consumerTimings.containsKey( id ) ) + { + long time = consumerTimings.get( id ); + buf.append( " (Total: " ).append( time ).append( "ms" ); + if ( consumerCounts.containsKey( id ) ) + { + long total = consumerCounts.get( id ); + buf.append( "; Avg.: " + ( time / total ) + "; Count: " + total ); + } + buf.append( ")" ); + } } } else @@ -108,6 +124,17 @@ public class RepositoryScanStatistics for ( String id : invalidConsumers ) { buf.append( "\n " ).append( id ); + if ( consumerTimings.containsKey( id ) ) + { + long time = consumerTimings.get( id ); + buf.append( " (Total: " ).append( time ).append( "ms" ); + if ( consumerCounts.containsKey( id ) ) + { + long total = consumerCounts.get( id ); + buf.append( "; Avg.: " + ( time / total ) + "ms; Count: " + total ); + } + buf.append( ")" ); + } } } else @@ -142,4 +169,14 @@ public class RepositoryScanStatistics return buf.toString(); } + + public void setConsumerCounts( Map consumerCounts ) + { + this.consumerCounts = consumerCounts; + } + + public void setConsumerTimings( Map consumerTimings ) + { + this.consumerTimings = consumerTimings; + } } diff --git a/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScannerInstance.java b/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScannerInstance.java index cd25dc396..f9de67fa6 100644 --- a/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScannerInstance.java +++ b/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/RepositoryScannerInstance.java @@ -21,7 +21,9 @@ package org.apache.maven.archiva.repository.scanner; import java.io.File; import java.util.Date; +import java.util.HashMap; import java.util.List; +import java.util.Map; import org.apache.archiva.repository.scanner.functors.TriggerScanCompletedClosure; import org.apache.commons.collections.Closure; @@ -32,6 +34,7 @@ import org.apache.maven.archiva.common.utils.BaseFile; import org.apache.maven.archiva.configuration.ManagedRepositoryConfiguration; import org.apache.maven.archiva.consumers.InvalidRepositoryContentConsumer; import org.apache.maven.archiva.consumers.KnownRepositoryContentConsumer; +import org.apache.maven.archiva.consumers.RepositoryContentConsumer; import org.apache.maven.archiva.repository.scanner.functors.ConsumerProcessFileClosure; import org.apache.maven.archiva.repository.scanner.functors.ConsumerWantsFilePredicate; import org.apache.maven.archiva.repository.scanner.functors.TriggerBeginScanClosure; @@ -68,6 +71,10 @@ public class RepositoryScannerInstance private ConsumerWantsFilePredicate consumerWantsFile; + private Map consumerTimings; + + private Map consumerCounts; + public RepositoryScannerInstance( ManagedRepositoryConfiguration repository, List knownConsumerList, List invalidConsumerList ) @@ -76,7 +83,14 @@ public class RepositoryScannerInstance this.knownConsumers = knownConsumerList; this.invalidConsumers = invalidConsumerList; + consumerTimings = new HashMap(); + consumerCounts = new HashMap(); + this.consumerProcessFile = new ConsumerProcessFileClosure(); + consumerProcessFile.setExecuteOnEntireRepo( true ); + consumerProcessFile.setConsumerTimings( consumerTimings ); + consumerProcessFile.setConsumerCounts( consumerCounts ); + this.consumerWantsFile = new ConsumerWantsFilePredicate(); stats = new RepositoryScanStatistics(); @@ -109,6 +123,16 @@ public class RepositoryScannerInstance return stats; } + public Map getConsumerTimings() + { + return consumerTimings; + } + + public Map getConsumerCounts() + { + return consumerCounts; + } + public void directoryWalkStarting( File basedir ) { log.info( "Walk Started: [" + this.repository.getId() + "] " + this.repository.getLocation() ); @@ -123,20 +147,19 @@ public class RepositoryScannerInstance // consume files regardless - the predicate will check the timestamp BaseFile basefile = new BaseFile( repository.getLocation(), file ); - + // Timestamp finished points to the last successful scan, not this current one. if ( file.lastModified() >= changesSince ) { - stats.increaseNewFileCount(); + stats.increaseNewFileCount(); } - + consumerProcessFile.setBasefile( basefile ); - consumerProcessFile.setExecuteOnEntireRepo( true ); consumerWantsFile.setBasefile( basefile ); - + Closure processIfWanted = IfClosure.getInstance( consumerWantsFile, consumerProcessFile ); CollectionUtils.forAllDo( this.knownConsumers, processIfWanted ); - + if ( consumerWantsFile.getWantedFileCount() <= 0 ) { // Nothing known processed this file. It is invalid! @@ -150,6 +173,9 @@ public class RepositoryScannerInstance CollectionUtils.forAllDo( knownConsumers, scanCompletedClosure ); CollectionUtils.forAllDo( invalidConsumers, scanCompletedClosure ); + + stats.setConsumerTimings( consumerTimings ); + stats.setConsumerCounts( consumerCounts ); log.info( "Walk Finished: [" + this.repository.getId() + "] " + this.repository.getLocation() ); stats.triggerFinished(); diff --git a/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/functors/ConsumerProcessFileClosure.java b/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/functors/ConsumerProcessFileClosure.java index e1a493926..ec39d952c 100644 --- a/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/functors/ConsumerProcessFileClosure.java +++ b/archiva-modules/archiva-base/archiva-repository-layer/src/main/java/org/apache/maven/archiva/repository/scanner/functors/ConsumerProcessFileClosure.java @@ -25,6 +25,9 @@ import org.apache.maven.archiva.consumers.RepositoryContentConsumer; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import java.util.HashMap; +import java.util.Map; + /** * ConsumerProcessFileClosure * @@ -39,24 +42,43 @@ public class ConsumerProcessFileClosure private boolean executeOnEntireRepo; + private Map consumerTimings; + + private Map consumerCounts; + public void execute( Object input ) { if ( input instanceof RepositoryContentConsumer ) { RepositoryContentConsumer consumer = (RepositoryContentConsumer) input; + String id = consumer.getId(); try { - log.debug( "Sending to consumer: " + consumer.getId() ); + log.debug( "Sending to consumer: " + id ); + long startTime = System.currentTimeMillis(); consumer.processFile( basefile.getRelativePath(), executeOnEntireRepo ); + long endTime = System.currentTimeMillis(); + + if ( consumerTimings != null ) + { + Long value = consumerTimings.get( id ); + consumerTimings.put( id, ( value != null ? value : 0 ) + endTime - startTime ); + } + + if ( consumerCounts != null ) + { + Long value = consumerCounts.get( id ); + consumerCounts.put( id, ( value != null ? value : 0 ) + 1 ); + } } catch ( Exception e ) { /* Intentionally Catch all exceptions. * So that the discoverer processing can continue. */ - log.error( "Consumer [" + consumer.getId() + "] had an error when processing file [" + log.error( "Consumer [" + id + "] had an error when processing file [" + basefile.getAbsolutePath() + "]: " + e.getMessage(), e ); } } @@ -82,6 +104,16 @@ public class ConsumerProcessFileClosure this.executeOnEntireRepo = executeOnEntireRepo; } + public void setConsumerTimings( Map consumerTimings ) + { + this.consumerTimings = consumerTimings; + } + + public void setConsumerCounts( Map consumerCounts ) + { + this.consumerCounts = consumerCounts; + } + public Logger getLogger() { return log; diff --git a/archiva-modules/archiva-web/archiva-webapp/src/main/webapp/WEB-INF/jsp/admin/systemStatus.jsp b/archiva-modules/archiva-web/archiva-webapp/src/main/webapp/WEB-INF/jsp/admin/systemStatus.jsp index c9a9fd8cb..e5fd5041d 100644 --- a/archiva-modules/archiva-web/archiva-webapp/src/main/webapp/WEB-INF/jsp/admin/systemStatus.jsp +++ b/archiva-modules/archiva-web/archiva-webapp/src/main/webapp/WEB-INF/jsp/admin/systemStatus.jsp @@ -49,7 +49,7 @@ ${queueEntry.key} - ${fn:length(queue)} + ${fn:length(queue)} @@ -67,8 +67,29 @@ ${scan.repository.name} (${scan.repository.id}) - ${scan.stats.totalFileCount} - ${scan.stats.newFileCount} + ${scan.stats.totalFileCount} + ${scan.stats.newFileCount} + + + + + + + + + + + + + + + + + + + +
NameTotalAverageInvocations
${entry.key}${entry.value}msms${total}
+ @@ -92,10 +113,10 @@ ${cacheEntry.key} - ${cacheEntry.value.statistics.size} - ${cacheEntry.value.statistics.cacheHits} - ${cacheEntry.value.statistics.cacheMiss} - + ${cacheEntry.value.statistics.size} + ${cacheEntry.value.statistics.cacheHits} + ${cacheEntry.value.statistics.cacheMiss} + Flush -- 2.39.5