diff --git a/src/main/java/com/conveyal/r5/profile/ExecutionTimer.java b/src/main/java/com/conveyal/r5/profile/ExecutionTimer.java index e99da759..86bfa8bc 100644 --- a/src/main/java/com/conveyal/r5/profile/ExecutionTimer.java +++ b/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 () { diff --git a/src/main/java/com/conveyal/r5/profile/FastRaptorWorker.java b/src/main/java/com/conveyal/r5/profile/FastRaptorWorker.java index 26caa7cc..b2989f63 100644 --- a/src/main/java/com/conveyal/r5/profile/FastRaptorWorker.java +++ b/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,11 +863,16 @@ 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; @@ -864,7 +880,7 @@ private BitSet patternsToExploreInNextRound (RaptorState state, BitSet runningPa 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(); diff --git a/src/main/java/com/conveyal/r5/profile/PerTargetPropagater.java b/src/main/java/com/conveyal/r5/profile/PerTargetPropagater.java index fbfcf097..a14e5ba3 100644 --- a/src/main/java/com/conveyal/r5/profile/PerTargetPropagater.java +++ b/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); } /** diff --git a/src/main/java/com/conveyal/r5/profile/PropagationTimer.java b/src/main/java/com/conveyal/r5/profile/PropagationTimer.java new file mode 100644 index 00000000..5af1bd5c --- /dev/null +++ b/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(); + } + +} diff --git a/src/main/java/com/conveyal/r5/profile/RaptorState.java b/src/main/java/com/conveyal/r5/profile/RaptorState.java index 1433e6b1..1adfc1f8 100644 --- a/src/main/java/com/conveyal/r5/profile/RaptorState.java +++ b/src/main/java/com/conveyal/r5/profile/RaptorState.java @@ -4,6 +4,7 @@ import org.slf4j.LoggerFactory; import java.util.Arrays; +import java.util.BitSet; import static com.conveyal.r5.common.Util.newIntArray; import static com.conveyal.r5.profile.FastRaptorWorker.ENABLE_OPTIMIZATION_CLEAR_LONG_PATHS; @@ -103,6 +104,21 @@ public class RaptorState { */ public int maxDurationSeconds; + /** + * A set of all the stops whose arrival times were improved in this round, in the current raptor search in progress. + * Note that in range-raptor, when reusing state from a later departure minute, arrival times may be earlier at + * a particular stop than in the previous round due to those already-finished searches. That fact can easily be + * detected by looking at the times themselves. Here we are separately tracking the updates made on top of those + * upper bound times by this single-departure-minute (or single-randomized-schedule) search in progress. + */ + public final BitSet stopsUpdated = new BitSet(); + + /** + * Same as stopsUpdated, but before transfers are applied. + * This is mostly needed to prevent concurrent iteration and modification of the set when evaluating transfers. + */ + public final BitSet nonTransferStopsUpdated = new BitSet(); + /** * Create a RaptorState for a network with a particular number of stops, and a given maximum travel duration. * Travel times to all stops are initialized to UNREACHED, which will be improved upon by the search process. @@ -130,10 +146,10 @@ public RaptorState (int nStops, int maxDurationSeconds) { /** * Copy constructor for reusing search state from one minute to the next in a range raptor search. - * This makes a deep copy of all fields, except the sets of updated stops (which are cleared) and the reference + * This makes a deep copy of all fields, except the sets of stopsUpdated (which are cleared) and the reference * to the previous round's state (which should be set as needed by the caller). */ - private RaptorState(RaptorState state) { + private RaptorState (RaptorState state) { this.bestTimes = Arrays.copyOf(state.bestTimes, state.bestTimes.length); this.bestNonTransferTimes = Arrays.copyOf(state.bestNonTransferTimes, state.bestNonTransferTimes.length); this.previousPatterns = Arrays.copyOf(state.previousPatterns, state.previousPatterns.length); @@ -248,6 +264,7 @@ public boolean setTimeAtStop(int stop, int time, int fromPattern, int fromStop, "Components of travel time are greater than total travel time."); optimal = true; + nonTransferStopsUpdated.set(stop); } // At a given stop, bestTimes is always less than or equal to bestNonTransferTimes. It will always be equal to @@ -263,8 +280,8 @@ public boolean setTimeAtStop(int stop, int time, int fromPattern, int fromStop, transferStop[stop] = -1; } optimal = true; + stopsUpdated.set(stop); } - return optimal; } @@ -293,7 +310,8 @@ public void setDepartureTime(int departureTime) { // a separate code path, and in fact does not apply the range raptor optimization. checkState(additionalWaitSeconds == 60, "Departure times may only be decremented by one minute."); this.departureTime = departureTime; - + stopsUpdated.clear(); + nonTransferStopsUpdated.clear(); // Remove trips that exceed the maximum trip duration when the rider departs earlier (due to more wait time). // This whole loop does not seem strictly necessary. In testing, removing it does not change results since // real travel times and INF can both compare greater than a cutoff. In fact multi-cutoff depends on this being @@ -324,18 +342,18 @@ public void setDepartureTime(int departureTime) { } } - /** @return whether the time was updated (with or without transfer) in the round represented by this state. */ - public boolean stopWasUpdated (int stop) { - int time = this.bestTimes[stop]; - int prevTime = (previous != null) ? previous.bestTimes[stop] : UNREACHED; - return time < prevTime; - } - - /** @return whether the time was updated before transfers were applied in the round represented by this state. */ - public boolean stopWasUpdatedPreTransfer (int stop) { - int time = this.bestNonTransferTimes[stop]; - int prevTime = (previous != null) ? previous.bestNonTransferTimes[stop] : UNREACHED; - return time < prevTime; + /** + * @param withinMinute if true, use the bitsets for the current minute, otherwise look at effects of all minutes. + * @return whether the time was updated (with or without transfer) in the round represented by this state. + */ + public boolean stopWasUpdated (int stop, boolean withinMinute) { + if (withinMinute) { + return stopsUpdated.get(stop); + } else { + int time = this.bestTimes[stop]; + int prevTime = (previous != null) ? previous.bestTimes[stop] : UNREACHED; + return time < prevTime; + } } } diff --git a/src/main/resources/logback.xml b/src/main/resources/logback.xml index ced3cb03..9a893278 100644 --- a/src/main/resources/logback.xml +++ b/src/main/resources/logback.xml @@ -14,5 +14,6 @@ + \ No newline at end of file