Use StopWatch to time performance

src/main/java/org/genesys/geotools/CountryCLI.java

@@ -24,6 +24,8 @@ import java.util.Arrays;
 import java.util.regex.Matcher;
 import java.util.regex.Pattern;
 
+import org.apache.commons.lang3.time.StopWatch;
+
 import com.opencsv.CSVReader;
 import com.opencsv.CSVWriter;
 
@@ -56,8 +58,12 @@ public class CountryCLI {
 					float longitude = Float.parseFloat(matcher.group(2).replace(",", "."));
 					float latitude = Float.parseFloat(matcher.group(3).replace(",", "."));
 
-					System.out.println(longitude + ", " + latitude + ", " + countryOfOriginService
-							.getCountries(longitude, latitude, origCty, ALLOWED_DISTANCE_MARGIN));
+					System.out.println(longitude
+							+ ", "
+							+ latitude
+							+ ", "
+							+ countryOfOriginService
+									.getCountries(longitude, latitude, origCty, ALLOWED_DISTANCE_MARGIN));
 
 				} else {
 					System.err.println("Invalid format: " + input);
@@ -79,13 +85,23 @@ public class CountryCLI {
 		CountryOfOriginServiceImpl countryOfOriginService = new CountryOfOriginServiceImpl();
 		countryOfOriginService.afterPropertiesSet();
 
+		StopWatch stopWatch = new StopWatch();
+
 		String[] nextLine;
 		int lineCount = 0;
+
+		long lastLogTime = 0;
+		stopWatch.start();
 		while ((nextLine = reader.readNext()) != null) {
 
 			lineCount++;
-			if (lineCount % 1000 == 0) {
-				System.err.println("FYI, " + lineCount + " entries have been processed.");
+			stopWatch.split();
+			long processingTimeSeconds = stopWatch.getSplitTime() / 1000;
+			if ((lineCount % 1000 == 0) || (lastLogTime != processingTimeSeconds && processingTimeSeconds % 10 == 0)) {
+				System.err.println("FYI, " + lineCount + " entries have been processed in " + processingTimeSeconds
+						+ " = " + (lineCount / processingTimeSeconds) + " lines/second");
+				countryOfOriginService.printCache();
+				lastLogTime = processingTimeSeconds;
 			}
 
 			String[] writeLine = Arrays.copyOf(nextLine, nextLine.length + 1);
@@ -111,6 +127,8 @@ public class CountryCLI {
 
 			writer.writeNext(writeLine);
 		}
+		stopWatch.stop();
+
 		writer.close();
 		reader.close();
 	}

src/main/java/org/genesys/geotools/CountryOfOriginServiceImpl.java

@@ -21,6 +21,7 @@ import java.net.MalformedURLException;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
 
+import org.apache.commons.lang3.time.StopWatch;
 import org.geotools.data.DataStore;
 import org.geotools.data.FeatureSource;
 import org.geotools.factory.CommonFactoryFinder;
@@ -36,6 +37,7 @@ import org.opengis.filter.FilterFactory2;
 
 import com.google.common.cache.CacheBuilder;
 import com.google.common.cache.CacheLoader;
+import com.google.common.cache.CacheStats;
 import com.google.common.cache.LoadingCache;
 import com.vividsolutions.jts.geom.Coordinate;
 import com.vividsolutions.jts.geom.GeometryFactory;
@@ -52,6 +54,8 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 	private FeatureSource<SimpleFeatureType, SimpleFeature> sourceAdmin0X;
 	private LoadingCache<LonLatCacheKey, String> countryCache;
 
+	private boolean debug = false;
+
 	static {
 		try {
 			// Initialize stuff
@@ -66,12 +70,12 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 		// http://www.gadm.org/version2
 		// Use "six dissolved layers"
 		DataStore dataStoreAdm0 = ShapefileUtils.openShapeFile("TM_WORLD_BORDERS-0.3.shp");
-		DataStore dataStoreAdm0X = ShapefileUtils.openShapeFile("gadm28_adm0.shp");
+		DataStore dataStoreAdm0X = ShapefileUtils.openShapeFile("gadm28_adm1.shp");
 
 		sourceAdmin0 = dataStoreAdm0.getFeatureSource(dataStoreAdm0.getTypeNames()[0]);
 		sourceAdmin0X = dataStoreAdm0X.getFeatureSource(dataStoreAdm0X.getTypeNames()[0]);
 
-		countryCache = CacheBuilder.newBuilder().maximumSize(1000).expireAfterWrite(20, TimeUnit.SECONDS)
+		countryCache = CacheBuilder.newBuilder().maximumSize(1000).recordStats().expireAfterWrite(20, TimeUnit.SECONDS)
 				.build(new CacheLoader<LonLatCacheKey, String>() {
 					@Override
 					public String load(LonLatCacheKey key) throws Exception {
@@ -90,6 +94,15 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 	@Override
 	public String getCountries(float longitude, float latitude, String origCty, int allowedDistanceMargin)
 			throws Exception {
+
+		// 1 geographical mile is 1855.3248 metres for WGS84
+		// 1855.3248m * 60 = 111319.488m
+		// 111319.488m for 1 degree, can trim by 1000 for 100m precision at
+		// equator
+
+		 longitude = (long) (longitude * 1000) / 1000f;
+		 latitude = (long) (latitude * 1000) / 1000f;
+
 		try {
 			return countryCache.get(new LonLatCacheKey(longitude, latitude, origCty, allowedDistanceMargin));
 		} catch (ExecutionException e) {
@@ -101,6 +114,7 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 			throws Exception {
 
 		// System.err.println(longitude + ", " + latitude + " " + origCtyISO);
+		StopWatch stopWatch = new StopWatch();
 
 		Point point = geometryFactory.createPoint(new Coordinate(longitude, latitude));
 		String geometryPropertyName = sourceAdmin0.getSchema().getGeometryDescriptor().getLocalName();
@@ -119,6 +133,7 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 
 		StringBuffer sb = new StringBuffer();
 
+		stopWatch.start();
 		// System.err.println(1);
 		FeatureCollection<SimpleFeatureType, SimpleFeature> matchingFeatures = sourceAdmin0.getFeatures(filterExact);
 		try (FeatureIterator<SimpleFeature> features = matchingFeatures.features()) {
@@ -134,6 +149,12 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 			}
 		}
 
+		stopWatch.split();
+		long processingTime = stopWatch.getSplitTime();
+		if (debug) {
+			System.err.println("Processing time split: " + processingTime);
+		}
+		
 		if (sb.length() == 0 || !sb.toString().contains(origCtyISO)) {
 			// if (sb.length() > 0) sb.append(", ");
 			// sb.append("???");
@@ -153,7 +174,7 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 					// System.out.print(feature.getID());
 					// System.out.print(": ");
 					//
-					// System.out.println(feature.getDefaultGeometryProperty().getValue());
+//					 System.out.println(feature.getDefaultGeometryProperty().getValue());
 					Object isoAttr = feature.getAttribute("ISO");
 
 					String countryIsoCode = isoAttr == null ? "" : isoAttr.toString();
@@ -165,8 +186,20 @@ public class CountryOfOriginServiceImpl implements CountryOfOriginService {
 				}
 			}
 		}
+		stopWatch.stop();
+		processingTime = stopWatch.getTime();
+		if (debug || processingTime > 3000) {
+			System.err
+					.println("Total processing time: " + processingTime + " for\t" + origCtyISO + "\t" + longitude + "\t" + latitude);
+		}
 
 		// System.err.println(sb);
 		return sb.toString();
 	}
+
+	public void printCache() {
+		CacheStats stats = countryCache.stats();
+		System.err.println("Hit count=" + stats.hitCount() + " rate=" + stats.hitRate() + "  Miss count="
+				+ stats.missCount() + " rate=" + stats.missRate());
+	}
 }