diff --git a/java/server/pom.xml b/java/server/pom.xml --- a/java/server/pom.xml +++ b/java/server/pom.xml @@ -18,6 +18,11 @@ + ch.qos.logback + logback-classic + 1.2.3 + + junit junit 4.11 diff --git a/java/server/src/main/java/org/softwareheritage/graph/Endpoint.java b/java/server/src/main/java/org/softwareheritage/graph/Endpoint.java --- a/java/server/src/main/java/org/softwareheritage/graph/Endpoint.java +++ b/java/server/src/main/java/org/softwareheritage/graph/Endpoint.java @@ -2,6 +2,9 @@ import java.util.ArrayList; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + import org.softwareheritage.graph.Graph; import org.softwareheritage.graph.SwhId; import org.softwareheritage.graph.SwhPath; @@ -21,6 +24,9 @@ /** Internal traversal API */ Traversal traversal; + /** Timings logger */ + private static final Logger logger = LoggerFactory.getLogger(Endpoint.class); + /** * Constructor. * @@ -34,16 +40,40 @@ } /** + * Returns measurement starting timestamp for logging purposes. + * + * @return timestamp used for time measurement + */ + private long startTiming() { + return System.nanoTime(); + } + + /** + * Ends timing measurement and returns total duration in seconds for logging purposes. + * + * @param startTime measurement starting timestamp + * @return time in seconds elapsed since starting point + */ + private float stopTiming(long startTime) { + long endTime = System.nanoTime(); + float duration = (float) (endTime - startTime) / 1_000_000_000; + return duration; + } + + /** * Converts a list of (internal) long node ids to a list of corresponding (external) SWH PIDs. * * @param nodeIds the list of long node ids * @return a list of corresponding SWH PIDs */ private ArrayList convertNodesToSwhIds(ArrayList nodeIds) { + long startTime = this.startTiming(); ArrayList swhIds = new ArrayList<>(); for (long nodeId : nodeIds) { swhIds.add(graph.getSwhId(nodeId)); } + float duration = this.stopTiming(startTime); + logger.debug("convertNodesToSwhIds() took {} s.", duration); return swhIds; } @@ -55,10 +85,13 @@ * @see org.softwareheritage.graph.SwhPath */ private SwhPath convertNodesToSwhPath(ArrayList nodeIds) { + long startTime = this.startTiming(); SwhPath path = new SwhPath(); for (long nodeId : nodeIds) { path.add(graph.getSwhId(nodeId)); } + float duration = this.stopTiming(startTime); + logger.debug("convertNodesToSwhPath() took {} s.", duration); return path; } @@ -70,10 +103,13 @@ * @see org.softwareheritage.graph.SwhPath */ private ArrayList convertPathsToSwhIds(ArrayList> pathsNodeId) { + long startTime = this.startTiming(); ArrayList paths = new ArrayList<>(); for (ArrayList path : pathsNodeId) { paths.add(convertNodesToSwhPath(path)); } + float duration = this.stopTiming(startTime); + logger.debug("convertPathsToSwhIds() took {} s.", duration); return paths; } @@ -87,7 +123,12 @@ */ public ArrayList leaves(SwhId src) { long srcNodeId = graph.getNodeId(src); + + long startTime = this.startTiming(); ArrayList nodeIds = traversal.leaves(srcNodeId); + float duration = this.stopTiming(startTime); + logger.debug("leaves({}) took {} s.", src, duration); + return convertNodesToSwhIds(nodeIds); } @@ -101,7 +142,12 @@ */ public ArrayList neighbors(SwhId src) { long srcNodeId = graph.getNodeId(src); + + long startTime = this.startTiming(); ArrayList nodeIds = traversal.neighbors(srcNodeId); + float duration = this.stopTiming(startTime); + logger.debug("neighbors({}) took {} s.", src, duration); + return convertNodesToSwhIds(nodeIds); } @@ -124,11 +170,19 @@ try { SwhId dstSwhId = new SwhId(dstFmt); long dstNodeId = graph.getNodeId(dstSwhId); + + long startTime = this.startTiming(); nodeIds = traversal.walk(srcNodeId, dstNodeId, algorithm); + float duration = this.stopTiming(startTime); + logger.debug("walk({}) took {} s.", src, duration); } catch (IllegalArgumentException ignored1) { try { Node.Type dstType = Node.Type.fromStr(dstFmt); + + long startTime = this.startTiming(); nodeIds = traversal.walk(srcNodeId, dstType, algorithm); + float duration = this.stopTiming(startTime); + logger.debug("walk({}) took {} s.", src, duration); } catch (IllegalArgumentException ignored2) { } } @@ -145,7 +199,12 @@ */ public ArrayList visitNodes(SwhId src) { long srcNodeId = graph.getNodeId(src); + + long startTime = this.startTiming(); ArrayList nodeIds = traversal.visitNodes(srcNodeId); + float duration = this.stopTiming(startTime); + logger.debug("visitNodes({}) took {} s.", src, duration); + return convertNodesToSwhIds(nodeIds); } @@ -160,7 +219,12 @@ */ public ArrayList visitPaths(SwhId src) { long srcNodeId = graph.getNodeId(src); + + long startTime = this.startTiming(); ArrayList> paths = traversal.visitPaths(srcNodeId); + float duration = this.stopTiming(startTime); + logger.debug("visitPaths({}) took {} s.", src, duration); + return convertPathsToSwhIds(paths); } }