Merge pull request #276 from conveyal/updated-stops

Track updated stops separately within and across departure minutes

src/main/java/com/conveyal/r5/profile/ExecutionTimer.java

@@ -18,6 +18,9 @@
  * sub-millisecond in duration. (Arguably on large numbers of operations using msec would be fine because the number of
  * times we cross a millisecond boundary would be proportional to the portion of a millisecond that operation took, but
  * nanoTime() avoids the problem entirely.)
+ *
+ * TODO ability to dump to JSON or JsonNode tree for inclusion in response, via some kind of request-scoped context
+ *  object. This should help enable continuous performance tracking in CI.
  */
 public class ExecutionTimer {
 
@@ -67,9 +70,14 @@ public String getMessage () {
         return String.format("%s: %s", name, description);
     }
 
+    /** Root timer is logged at INFO level, and details of children at DEBUG level. */
     public void log (int indentLevel) {
-        String indent = Strings.repeat("- ", indentLevel);
-        LOG.debug(indent + this.getMessage());
+        if (indentLevel == 0) {
+            LOG.info(getMessage());
+        } else {
+            String indent = Strings.repeat("- ", indentLevel);
+            LOG.debug(indent + getMessage());
+        }
     }
 
     public void logWithChildren () {

src/main/java/com/conveyal/r5/profile/FastRaptorWorker.java

@@ -350,17 +350,18 @@ private int[][] runRaptorForDepartureMinute (int departureTime) {
                 scheduleState[round].minMergePrevious();
 
                 raptorTimer.scheduledSearchTransit.start();
-                doScheduledSearchForRound(scheduleState[round - 1], scheduleState[round]);
+                doScheduledSearchForRound(scheduleState[round]);
                 raptorTimer.scheduledSearchTransit.stop();
 
                 // If there are frequency routes, we will be randomizing the schedules (phase) of those routes.
                 // First perform a frequency search using worst-case boarding time to provide a tighter upper bound on
-                // total travel time. Each randomized schedule will then improve on these travel times.
-                // This should be a pure optimization, which is only helpful for Monte Carlo mode (not half-headway).
+                // total travel time. Each randomized schedule will then improve on these travel times. This should be
+                // a pure optimization, which is only helpful for Monte Carlo mode (not half-headway). Note that unlike
+                // the monte carlo draws, this frequency search is interleaved with the scheduled search in each round.
                 // Perhaps we should only do it when iterationsPerMinute is high (2 or more?)
                 if (ENABLE_OPTIMIZATION_FREQ_UPPER_BOUND && transit.hasFrequencies && boardingMode == MONTE_CARLO) {
                     raptorTimer.scheduledSearchFrequencyBounds.start();
-                    doFrequencySearchForRound(scheduleState[round - 1], scheduleState[round], UPPER_BOUND);
+                    doFrequencySearchForRound(scheduleState[round], UPPER_BOUND);
                     raptorTimer.scheduledSearchFrequencyBounds.stop();
                 }
                 // Apply transfers to the scheduled result that will be reused for the previous departure minute.
@@ -397,11 +398,11 @@ private int[][] runRaptorForDepartureMinute (int departureTime) {
                     frequencyState[round].minMergePrevious();
 
                     raptorTimer.frequencySearchScheduled.start();
-                    doScheduledSearchForRound(frequencyState[round - 1], frequencyState[round]);
+                    doScheduledSearchForRound(frequencyState[round]);
                     raptorTimer.frequencySearchScheduled.stop();
 
                     raptorTimer.frequencySearchFrequency.start();
-                    doFrequencySearchForRound(frequencyState[round - 1], frequencyState[round], boardingMode);
+                    doFrequencySearchForRound(frequencyState[round], boardingMode);
                     raptorTimer.frequencySearchFrequency.stop();
 
                     raptorTimer.frequencySearchTransfers.start();
@@ -480,10 +481,10 @@ private static Path[] pathToEachStop (RaptorState state) {
      * A sub-step in the process of performing a RAPTOR search at one specific departure time (at one specific minute).
      * This method handles only the routes that have exact schedules. There is another method that handles only the
      * other kind of routes: the frequency-based routes.
-     * TODO force inputState = outputState.previous instead of passing in an arbitrary input state
      */
-    private void doScheduledSearchForRound(RaptorState inputState, RaptorState outputState) {
-        BitSet patternsToExplore = patternsToExploreInNextRound(inputState, runningScheduledPatterns);
+    private void doScheduledSearchForRound (RaptorState outputState) {
+        final RaptorState inputState = outputState.previous;
+        BitSet patternsToExplore = patternsToExploreInNextRound(inputState, runningScheduledPatterns, true);
         for (int patternIndex = patternsToExplore.nextSetBit(0);
              patternIndex >= 0;
              patternIndex = patternsToExplore.nextSetBit(patternIndex + 1)
@@ -512,7 +513,8 @@ private void doScheduledSearchForRound(RaptorState inputState, RaptorState outpu
                 }
 
                 // Don't attempt to board if this stop was not reached in the last round or if pick up is not allowed.
-                if (inputState.stopWasUpdated(stop) &&
+                // Scheduled searches only care about updates within this departure minute, enabling range-raptor.
+                if (inputState.stopWasUpdated(stop, true) &&
                     pattern.pickups[stopPositionInPattern] != PickDropType.NONE
                 ) {
                     int earliestBoardTime = inputState.bestTimes[stop] + MINIMUM_BOARD_WAIT_SEC;
@@ -578,22 +580,25 @@ public enum FrequencyBoardingMode {
 
     /**
      * Perform one round of a Raptor search, considering only the frequency-based routes. These results are layered
-     * on top of (may improve upon) those from the fully scheduled routes.
-     * If the boarding mode is UPPER_BOUND, worst-case boarding time will be used at every boarding event.
-     * Arrival times produced can then be used as a valid upper bound for previous departure minutes in range RAPTOR.
+     * on top of (may improve upon) those from the fully scheduled routes. If the boarding mode is UPPER_BOUND,
+     * worst-case boarding time will be used at every boarding event. Arrival times produced can then be used as a
+     * valid upper bound for previous departure minutes in range-raptor, and for randomized schedules at the same
+     * departure minute.
      *
-     * Otherwise randomized schedules will be used to improve upon the output of the range-RAPTOR bounds search.
-     * Those outputs may not be reused in successive iterations as schedules will change from one iteration to the next.
+     * If the boarding mode is MONTE_CARLO, randomized schedules will be used to improve upon the output of the
+     * range-raptor upper bound search described above. Those outputs may not be reused in successive iterations, as
+     * these Monte Carlo schedules will change from one iteration to the next.
      *
      * TODO maybe convert all these functions to pure functions that create and output new round states.
      * @param frequencyBoardingMode see comments on enum values.
      */
-    private void doFrequencySearchForRound (
-            RaptorState inputState,
-            RaptorState outputState,
-            FrequencyBoardingMode frequencyBoardingMode
-    ) {
-        BitSet patternsToExplore = patternsToExploreInNextRound(inputState, runningFrequencyPatterns);
+    private void doFrequencySearchForRound (RaptorState outputState, FrequencyBoardingMode frequencyBoardingMode) {
+        final RaptorState inputState = outputState.previous;
+        // Determine which routes are capable of improving on travel times in this round. Monte Carlo frequency searches
+        // are applying randomized schedules that are not present in the accumulated range-raptor upper bound state.
+        // Those randomized frequency routes may cascade improvements from updates made at previous departure minutes.
+        final boolean withinMinute = (frequencyBoardingMode == UPPER_BOUND);
+        BitSet patternsToExplore = patternsToExploreInNextRound(inputState, runningFrequencyPatterns, withinMinute);
         for (int patternIndex = patternsToExplore.nextSetBit(0);
                  patternIndex >= 0;
                  patternIndex = patternsToExplore.nextSetBit(patternIndex + 1)
@@ -638,7 +643,9 @@ private void doFrequencySearchForRound (
                         // If this stop was updated in the previous round and pickup is allowed at this stop, see if
                         // we can board an earlier trip.
                         // (even if already boarded, since this is a frequency trip and we could move back)
-                        if (inputState.stopWasUpdated(stop) && pattern.pickups[stopPositionInPattern] != PickDropType.NONE) {
+                        if (inputState.stopWasUpdated(stop, withinMinute) &&
+                            pattern.pickups[stopPositionInPattern] != PickDropType.NONE
+                        ) {
                             int earliestBoardTime = inputState.bestTimes[stop] + MINIMUM_BOARD_WAIT_SEC;
 
                             // if we're computing the upper bound, we want the worst case. This is the only thing that is
@@ -833,8 +840,12 @@ private void doTransfers (RaptorState state) {
         final int walkSpeedMillimetersPerSecond = (int) (request.walkSpeed * 1000);
         final int maxWalkMillimeters = walkSpeedMillimetersPerSecond * (request.maxWalkTime * SECONDS_PER_MINUTE);
         final int nStops = state.bestNonTransferTimes.length;
-        for (int stop = 0; stop < nStops; stop++) {
-            if (!state.stopWasUpdatedPreTransfer(stop)) continue;
+        // Compute transfers only from stops updated pre-transfer within this departure minute / randomized schedule.
+        // These transfers then update the post-transfers bitset to avoid concurrent modification while iterating.
+        for (int stop = state.nonTransferStopsUpdated.nextSetBit(0);
+                 stop > 0;
+                 stop = state.nonTransferStopsUpdated.nextSetBit(stop + 1)
+        ) {
             TIntList transfersFromStop = transit.transfersForStop.get(stop);
             if (transfersFromStop != null) {
                 for (int i = 0; i < transfersFromStop.size(); i += 2) {
@@ -852,19 +863,24 @@ private void doTransfers (RaptorState state) {
     }
 
     /**
-     * Find all patterns that could lead to improvements in the next round after the given state's raptor round.
-     * Specifically, the patterns passing through all stops that were updated in the given state's round.
-     * The pattern indexes returned are limited to those in the supplied set.
+     * Find all patterns that could lead to improvements in the next raptor round after the given state's round.
+     * Specifically, these are the patterns passing through all stops that were updated in the given state's round.
+     * When the set of patterns being considered is consistent with those present in the accumulated range raptor state,
+     * it is sufficient to cascade updates from round to round within the current departure minute, without looking at
+     * the accumulated state from other minutes. But when the set of patterns being considered is different than those
+     * in the accumulated state (as when we're layering on randomized frequency routes), updates must be cascaded from
+     * things that happened in the other departure minutes - in this case the withinMinute parameter should be false.
+     * The pattern indexes returned are limited to those in the supplied set, reflecting active service on a given day.
      */
-    private BitSet patternsToExploreInNextRound (RaptorState state, BitSet runningPatterns) {
+    private BitSet patternsToExploreInNextRound (RaptorState state, BitSet runningPatterns, boolean withinMinute) {
         if (!ENABLE_OPTIMIZATION_UPDATED_STOPS) {
             // We do not write to the returned bitset, only iterate over it, so do not need to make a protective copy.
             return runningPatterns;
         }
         BitSet patternsToExplore = new BitSet();
         final int nStops = state.bestTimes.length;
         for (int stop = 0; stop < nStops; stop++) {
-            if (!state.stopWasUpdated(stop)) continue;
+            if (!state.stopWasUpdated(stop, withinMinute)) continue;
             TIntIterator patternsAtStop = transit.patternsForStop.get(stop).iterator();
             while (patternsAtStop.hasNext()) {
                 int pattern = patternsAtStop.next();

src/main/java/com/conveyal/r5/profile/PerTargetPropagater.java

@@ -108,6 +108,8 @@ public class PerTargetPropagater {
      */
     private Path[] perIterationPaths;
 
+    private final PropagationTimer timer = new PropagationTimer();
+
     /**
      * Constructor.
      */
@@ -119,27 +121,29 @@ public PerTargetPropagater(
             int[][] travelTimesToStopsForIteration,
             int[] nonTransitTravelTimesToTargets
     ) {
-        this.maxTravelTimeSeconds = task.maxTripDurationMinutes * SECONDS_PER_MINUTE;
         this.targets = targets;
         this.modes = modes;
         this.request = task;
         this.travelTimesToStopsForIteration = travelTimesToStopsForIteration;
         this.nonTransitTravelTimesToTargets = nonTransitTravelTimesToTargets;
+
         // If we're making a static site we'll break travel times down into components and make paths.
         // This expects the pathsToStopsForIteration and pathWriter fields to be set separately by the caller.
-        this.calculateComponents = task.makeTauiSite;
+        calculateComponents = task.makeTauiSite;
 
+        maxTravelTimeSeconds = task.maxTripDurationMinutes * SECONDS_PER_MINUTE;
         oneToOne = request instanceof RegionalTask && ((RegionalTask) request).oneToOne;
-
         nIterations = travelTimesToStopsForIteration.length;
         nStops = travelTimesToStopsForIteration[0].length;
-        invertTravelTimes();
         nTargets = targets.featureCount();
+        linkedTargets = new ArrayList<>(modes.size());
+
+        timer.fullPropagation.start();
+        timer.transposition.start();
+        invertTravelTimes();
         if (nonTransitTravelTimesToTargets.length != nTargets) {
             throw new IllegalArgumentException("Non-transit travel times must have the same number of entries as there are points.");
         }
-        linkedTargets = new ArrayList<>(modes.size());
-
         for (StreetMode streetMode : modes) {
             LinkedPointSet linkedTargetsForMode = streetLayer.parentNetwork.linkageCache
                     .getLinkage(targets, streetLayer, streetMode);
@@ -148,6 +152,9 @@ public PerTargetPropagater(
             linkedTargetsForMode.getEgressCostTable().destructivelyTransposeForPropagationAsNeeded();
             linkedTargets.add(linkedTargetsForMode);
         }
+        timer.transposition.stop();
+        // Prevent top-level timer from counting any intervening actions until caller calls propagate()
+        timer.fullPropagation.stop();
     }
 
     /**
@@ -156,7 +163,7 @@ public PerTargetPropagater(
      */
     public OneOriginResult propagate () {
 
-        long startTimeMillis = System.currentTimeMillis();
+        timer.fullPropagation.start();
 
         // perIterationTravelTimes and perIterationDetails are reused when processing each target.
         perIterationTravelTimes = new int[nIterations];
@@ -189,7 +196,9 @@ public OneOriginResult propagate () {
 
             // Improve upon these non-transit travel times based on transit travel times to nearby stops.
             // This fills in perIterationTravelTimes and perIterationPaths for one particular target.
+            timer.propagation.start();
             propagateTransit(targetIdx);
+            timer.propagation.stop();
 
             // Construct the PathScorer before extracting percentiles because the scorer needs to make a copy of
             // the unsorted complete travel times.
@@ -202,7 +211,9 @@ public OneOriginResult propagate () {
 
             // Extract the requested percentiles and save them (and/or the resulting accessibility indicator values)
             int targetToWrite = oneToOne ? 0 : targetIdx;
+            timer.reducer.start();
             travelTimeReducer.extractTravelTimePercentilesAndRecord(targetToWrite, perIterationTravelTimes);
+            timer.reducer.stop();
 
             if (calculateComponents) {
                 // TODO Somehow report these in-vehicle, wait and walk breakdown values alongside the total travel time.
@@ -214,9 +225,8 @@ public OneOriginResult propagate () {
                 pathWriter.recordPathsForTarget(selectedPaths);
             }
         }
-        LOG.info("Propagating {} iterations from {} stops to {} target points took {}s",
-                nIterations, nStops, endTarget - startTarget, (System.currentTimeMillis() - startTimeMillis) / 1000d
-        );
+        timer.fullPropagation.stop();
+        timer.log();
         if (pathWriter != null) {
             pathWriter.finishAndStorePaths();
         }
@@ -244,14 +254,12 @@ public OneOriginResult propagate () {
      * locality problems elsewhere (since the pathfinding algorithm solves one iteration for all stops simultaneously).
      */
     private void invertTravelTimes() {
-        long startTime = System.currentTimeMillis();
         travelTimesToStop = new int[nStops][nIterations];
         for (int iteration = 0; iteration < nIterations; iteration++) {
             for (int stop = 0; stop < nStops; stop++) {
                 travelTimesToStop[stop][iteration] = travelTimesToStopsForIteration[iteration][stop];
             }
         }
-        LOG.info("Travel time matrix transposition took {} msec", System.currentTimeMillis() - startTime);
     }
 
     /**

src/main/java/com/conveyal/r5/profile/PropagationTimer.java

@@ -0,0 +1,26 @@
+package com.conveyal.r5.profile;
+
+/**
+ * This groups together all the timers recording execution time of various steps of travel time propagation, which
+ * is performed after the raptor search itself.
+ *
+ * TODO constructor that adds stop and target counts to top level message
+ *         LOG.info("Propagating {} iterations from {} stops to {} target points took {}s",
+ *                 nIterations, nStops, endTarget - startTarget, (System.currentTimeMillis() - startTimeMillis) / 1000d
+ *         );
+ */
+public class PropagationTimer {
+
+    public final ExecutionTimer fullPropagation = new ExecutionTimer("Full travel time propagation");
+
+    public final ExecutionTimer transposition = new ExecutionTimer(fullPropagation, "Travel time matrix transposition");
+
+    public final ExecutionTimer propagation = new ExecutionTimer(fullPropagation, "Propagation");
+
+    public final ExecutionTimer reducer = new ExecutionTimer(fullPropagation, "Travel time reducer");
+
+    public void log () {
+        fullPropagation.logWithChildren();
+    }
+
+}