From 42ff1dc030184c1b3e07c5c3b118ffc4d38d9f5f Mon Sep 17 00:00:00 2001 From: Brord van Wierst Date: Thu, 7 May 2020 22:03:24 +0200 Subject: [PATCH 1/6] Made progressbar show up during syncdown --- .../impl/MilestoneSolidifierImpl.java | 40 ++++++++++++------- 1 file changed, 25 insertions(+), 15 deletions(-) diff --git a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java index a45d6cb1f9..26627c4e01 100644 --- a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java +++ b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java @@ -219,7 +219,11 @@ private void processSolidifyQueue() throws Exception { } } + int lowest = oldestMilestoneInQueue == null ? -1 : oldestMilestoneInQueue.getValue(); scanMilestonesInQueue(); + if (lowest != -1 && lowest > oldestMilestoneInQueue.getValue()) { + logChange(-1); + } } /** @@ -446,31 +450,34 @@ private boolean applySolidMilestoneToLedger(MilestoneViewModel milestone) throws return false; } } - - - - + + /** + * Logs changes to the console based on a change in syncing state + * + * @param prevSolidMilestoneIndex THe previous solid milestone, -1 if we went down 1 ms in oldestMilestoneInQueue + */ private void logChange(int prevSolidMilestoneIndex) { Snapshot latestSnapshot = snapshotProvider.getLatestSnapshot(); int nextLatestSolidMilestone = latestSnapshot.getIndex(); - setLatestSolidMilestone(nextLatestSolidMilestone); + + if (prevSolidMilestoneIndex != -1) { + if (prevSolidMilestoneIndex == nextLatestSolidMilestone) { + return; + } + setLatestSolidMilestone(nextLatestSolidMilestone); + latestSolidMilestoneLogger.info("Latest SOLID milestone index changed from #" + prevSolidMilestoneIndex + " to #" + nextLatestSolidMilestone); - if (prevSolidMilestoneIndex == nextLatestSolidMilestone) { - return; + tangle.publish("lmsi %d %d", prevSolidMilestoneIndex, nextLatestSolidMilestone); + tangle.publish("lmhs %s", latestMilestoneHash); } - latestSolidMilestoneLogger.info("Latest SOLID milestone index changed from #" + prevSolidMilestoneIndex + " to #" + nextLatestSolidMilestone); - - tangle.publish("lmsi %d %d", prevSolidMilestoneIndex, nextLatestSolidMilestone); - tangle.publish("lmhs %s", latestMilestoneHash); - if (!config.isPrintSyncProgressEnabled()) { return; } // only print more sophisticated progress if we are coming from a more unsynced state - if (getLatestMilestoneIndex() - nextLatestSolidMilestone < 1) { + if (prevSolidMilestoneIndex != -1 && getLatestMilestoneIndex() - nextLatestSolidMilestone < 1) { syncProgressInfo.setSyncMilestoneStartIndex(nextLatestSolidMilestone); syncProgressInfo.resetMilestoneApplicationTimes(); return; @@ -480,9 +487,12 @@ private void logChange(int prevSolidMilestoneIndex) { nextLatestSolidMilestone); StringBuilder progressSB = new StringBuilder(); + double percentPreferDown = 95; + double percentageSynced = ((100d - oldestMilestoneInQueue.getValue() / latestMilestoneIndex.doubleValue() / 0.01d) / 100d * percentPreferDown) + + ((latestSolidMilestone.doubleValue() / latestMilestoneIndex.doubleValue() / 0.01d) / 100d * (100d - percentPreferDown)); + // add progress bar - progressSB.append(ASCIIProgressBar.getProgressBarString(syncProgressInfo.getSyncMilestoneStartIndex(), - getLatestMilestoneIndex(), nextLatestSolidMilestone)); + progressSB.append(ASCIIProgressBar.getProgressBarString(0, 1000, (int)Math.round(percentageSynced*10))); // add lsm to lm progressSB.append(String.format(" [LSM %d / LM %d - remaining: %d]", nextLatestSolidMilestone, getLatestMilestoneIndex(), getLatestMilestoneIndex() - nextLatestSolidMilestone)); From 5b025bc6452b6bd40e8979be5f8238c0d38c0a7c Mon Sep 17 00:00:00 2001 From: Brord van Wierst Date: Fri, 8 May 2020 15:43:22 +0200 Subject: [PATCH 2/6] Fixed nullpointer and added more explicit logging when an error occurs --- .../milestone/impl/MilestoneSolidifierImpl.java | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java index 26627c4e01..8c77b60c87 100644 --- a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java +++ b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java @@ -37,7 +37,7 @@ public class MilestoneSolidifierImpl implements MilestoneSolidifier { private static final IntervalLogger latestSolidMilestoneLogger = new IntervalLogger(MilestoneSolidifierImpl.class); - private static final IntervalLogger solidifyLogger = new IntervalLogger(MilestoneSolidifierImpl.class); + private static final IntervalLogger solidifyLogger = new IntervalLogger(MilestoneSolidifierImpl.class, 10000); private static final IntervalLogger progressBarLogger = new IntervalLogger(MilestoneSolidifierImpl.class); @@ -221,7 +221,7 @@ private void processSolidifyQueue() throws Exception { int lowest = oldestMilestoneInQueue == null ? -1 : oldestMilestoneInQueue.getValue(); scanMilestonesInQueue(); - if (lowest != -1 && lowest > oldestMilestoneInQueue.getValue()) { + if (oldestMilestoneInQueue != null && lowest > oldestMilestoneInQueue.getValue()) { logChange(-1); } } @@ -247,7 +247,7 @@ private void checkLatestSolidMilestone() { } } } catch (Exception e) { - log.info(e.getMessage()); + log.error(e.getMessage(), e); } } @@ -477,7 +477,8 @@ private void logChange(int prevSolidMilestoneIndex) { } // only print more sophisticated progress if we are coming from a more unsynced state - if (prevSolidMilestoneIndex != -1 && getLatestMilestoneIndex() - nextLatestSolidMilestone < 1) { + if (oldestMilestoneInQueue == null || + (prevSolidMilestoneIndex != -1 && getLatestMilestoneIndex() - nextLatestSolidMilestone < 1)) { syncProgressInfo.setSyncMilestoneStartIndex(nextLatestSolidMilestone); syncProgressInfo.resetMilestoneApplicationTimes(); return; @@ -492,7 +493,7 @@ private void logChange(int prevSolidMilestoneIndex) { + ((latestSolidMilestone.doubleValue() / latestMilestoneIndex.doubleValue() / 0.01d) / 100d * (100d - percentPreferDown)); // add progress bar - progressSB.append(ASCIIProgressBar.getProgressBarString(0, 1000, (int)Math.round(percentageSynced*10))); + progressSB.append(ASCIIProgressBar.getProgressBarString(0, 100, (int)Math.round(percentageSynced))); // add lsm to lm progressSB.append(String.format(" [LSM %d / LM %d - remaining: %d]", nextLatestSolidMilestone, getLatestMilestoneIndex(), getLatestMilestoneIndex() - nextLatestSolidMilestone)); From b4b37812c59fdabd3836787ccc87a11dbe3c79ac Mon Sep 17 00:00:00 2001 From: Brord van Wierst Date: Fri, 8 May 2020 16:03:49 +0200 Subject: [PATCH 3/6] made boostrapping less invasive --- .../iri/service/milestone/impl/MilestoneSolidifierImpl.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java index 8c77b60c87..76e4edf90c 100644 --- a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java +++ b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java @@ -292,7 +292,7 @@ private void bootStrapSolidMilestones() throws Exception { addMilestoneCandidate(hash, index); } } - if (processed % 1000 == 0 || processed % milestoneTransactions.size() == 0){ + if (processed % (milestoneTransactions.size()/10) == 0 || processed % milestoneTransactions.size() == 0){ log.info("Bootstrapping milestones: [ " + processed + " / " + milestoneTransactions.size() + " ]"); } } catch(Exception e) { From 4c15f006e5ae5d8f6c827385807ddb0e69d9ae09 Mon Sep 17 00:00:00 2001 From: Brord van Wierst Date: Tue, 12 May 2020 01:20:24 +0200 Subject: [PATCH 4/6] Added fix for syncingon xisting db --- .../impl/MilestoneSolidifierImpl.java | 36 ++++++++++++++----- 1 file changed, 28 insertions(+), 8 deletions(-) diff --git a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java index 76e4edf90c..d938912963 100644 --- a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java +++ b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java @@ -113,7 +113,6 @@ public void start() { setLatestMilestone(latestSnapshot.getHash(), latestSnapshot.getIndex()); logChange(snapshotProvider.getInitialSnapshot().getIndex()); - syncProgressInfo.setSyncMilestoneStartIndex(snapshotProvider.getInitialSnapshot().getIndex()); milestoneSolidifier.start(); } catch (Exception e) { @@ -222,6 +221,8 @@ private void processSolidifyQueue() throws Exception { int lowest = oldestMilestoneInQueue == null ? -1 : oldestMilestoneInQueue.getValue(); scanMilestonesInQueue(); if (oldestMilestoneInQueue != null && lowest > oldestMilestoneInQueue.getValue()) { + // Going down or going up doesnt matter to the calculation + syncProgressInfo.addMilestoneApplicationTime(); logChange(-1); } } @@ -477,8 +478,7 @@ private void logChange(int prevSolidMilestoneIndex) { } // only print more sophisticated progress if we are coming from a more unsynced state - if (oldestMilestoneInQueue == null || - (prevSolidMilestoneIndex != -1 && getLatestMilestoneIndex() - nextLatestSolidMilestone < 1)) { + if (prevSolidMilestoneIndex != -1 && getLatestMilestoneIndex() - nextLatestSolidMilestone < 1) { syncProgressInfo.setSyncMilestoneStartIndex(nextLatestSolidMilestone); syncProgressInfo.resetMilestoneApplicationTimes(); return; @@ -486,12 +486,14 @@ private void logChange(int prevSolidMilestoneIndex) { int estSecondsToBeSynced = syncProgressInfo.computeEstimatedTimeToSyncUpSeconds(getLatestMilestoneIndex(), nextLatestSolidMilestone); - StringBuilder progressSB = new StringBuilder(); - - double percentPreferDown = 95; - double percentageSynced = ((100d - oldestMilestoneInQueue.getValue() / latestMilestoneIndex.doubleValue() / 0.01d) / 100d * percentPreferDown) - + ((latestSolidMilestone.doubleValue() / latestMilestoneIndex.doubleValue() / 0.01d) / 100d * (100d - percentPreferDown)); + + // oldestMilestoneInQueue can be null if they are processed faster than coming in. + // Unlikely to happen on mainnet though. + double percentageSynced = syncProgressInfo.calculatePercentageSynced(getLatestMilestoneIndex(), + getLatestSolidMilestoneIndex(), + oldestMilestoneInQueue == null ? getLatestSolidMilestoneIndex() : oldestMilestoneInQueue.getValue()); + StringBuilder progressSB = new StringBuilder(); // add progress bar progressSB.append(ASCIIProgressBar.getProgressBarString(0, 100, (int)Math.round(percentageSynced))); // add lsm to lm @@ -509,6 +511,9 @@ private void logChange(int prevSolidMilestoneIndex) { * Holds variables containing information needed for sync progress calculation. */ private static class SyncProgressInfo { + + static final double PERCENT_WEIGHT_DOWN = 95; + /** * The actual start milestone index from which the node started from when syncing up. */ @@ -579,6 +584,21 @@ int computeEstimatedTimeToSyncUpSeconds(int latestMilestoneIndex, int latestSoli return (int) ((avgMilestoneApplyMillisec / 1000) * (latestMilestoneIndex - latestSolidMilestoneIndex)); } + + /** + * + * @param latest + * @param latestSolid + * @return + */ + double calculatePercentageSynced(int latest, int latestSolid, int oldestInQueue) { + double currentD = oldestInQueue - latestSolid; + double targetD = latest - latestSolid; + double processPercentage = 100 - currentD / targetD / 0.01d / 100d * PERCENT_WEIGHT_DOWN; + + double percentageSynced = processPercentage + ((latestSolid / latest / 0.01d) / 100d * (100d - PERCENT_WEIGHT_DOWN)); + return percentageSynced; + } } } From 469b8ec8363ead7e62c4b40c3777e12b1336abdf Mon Sep 17 00:00:00 2001 From: Brord van Wierst Date: Tue, 12 May 2020 17:06:28 +0200 Subject: [PATCH 5/6] Added a 'lil cheat --- .../milestone/impl/MilestoneSolidifierImpl.java | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java index d938912963..cc6ca6a2c9 100644 --- a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java +++ b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java @@ -484,15 +484,19 @@ private void logChange(int prevSolidMilestoneIndex) { return; } - int estSecondsToBeSynced = syncProgressInfo.computeEstimatedTimeToSyncUpSeconds(getLatestMilestoneIndex(), - nextLatestSolidMilestone); - // oldestMilestoneInQueue can be null if they are processed faster than coming in. // Unlikely to happen on mainnet though. double percentageSynced = syncProgressInfo.calculatePercentageSynced(getLatestMilestoneIndex(), getLatestSolidMilestoneIndex(), oldestMilestoneInQueue == null ? getLatestSolidMilestoneIndex() : oldestMilestoneInQueue.getValue()); + if (percentageSynced >= 100 && getLatestSolidMilestoneIndex() != getLatestMilestoneIndex()) { + // Were still starting up things... + return; + } + int estSecondsToBeSynced = syncProgressInfo.computeEstimatedTimeToSyncUpSeconds(getLatestMilestoneIndex(), + nextLatestSolidMilestone); + StringBuilder progressSB = new StringBuilder(); // add progress bar progressSB.append(ASCIIProgressBar.getProgressBarString(0, 100, (int)Math.round(percentageSynced))); From a8aafd030d91afc1de48441355e7f4be906f6a98 Mon Sep 17 00:00:00 2001 From: Brord van Wierst Date: Wed, 13 May 2020 01:32:09 +0200 Subject: [PATCH 6/6] More fixes :/ --- .../impl/MilestoneSolidifierImpl.java | 34 ++++++++++++++----- 1 file changed, 26 insertions(+), 8 deletions(-) diff --git a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java index cc6ca6a2c9..370a1aaa12 100644 --- a/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java +++ b/src/main/java/com/iota/iri/service/milestone/impl/MilestoneSolidifierImpl.java @@ -111,7 +111,7 @@ public void start() { Snapshot latestSnapshot = snapshotProvider.getLatestSnapshot(); setLatestMilestone(latestSnapshot.getHash(), latestSnapshot.getIndex()); - logChange(snapshotProvider.getInitialSnapshot().getIndex()); + //logChange(snapshotProvider.getInitialSnapshot().getIndex()); milestoneSolidifier.start(); @@ -488,8 +488,8 @@ private void logChange(int prevSolidMilestoneIndex) { // Unlikely to happen on mainnet though. double percentageSynced = syncProgressInfo.calculatePercentageSynced(getLatestMilestoneIndex(), getLatestSolidMilestoneIndex(), - oldestMilestoneInQueue == null ? getLatestSolidMilestoneIndex() : oldestMilestoneInQueue.getValue()); - if (percentageSynced >= 100 && getLatestSolidMilestoneIndex() != getLatestMilestoneIndex()) { + oldestMilestoneInQueue == null ? 0 : oldestMilestoneInQueue.getValue()); + if (percentageSynced == -1) { // Were still starting up things... return; } @@ -522,6 +522,12 @@ private static class SyncProgressInfo { * The actual start milestone index from which the node started from when syncing up. */ private int syncMilestoneStartIndex; + + /** + * The oldest milestone index we have seen. + * Cached so that once we synced down, it doesnt revert to the new latest milestone index + */ + private int oldestSeenMilestoneIndex; /** * Used to calculate the average time needed to apply a milestone. @@ -561,6 +567,7 @@ void addMilestoneApplicationTime() { */ void resetMilestoneApplicationTimes() { lastMilestoneApplyTimes.clear(); + oldestSeenMilestoneIndex = 0; } /** @@ -590,15 +597,26 @@ int computeEstimatedTimeToSyncUpSeconds(int latestMilestoneIndex, int latestSoli } /** + * Calculates the percentage we are synced * - * @param latest - * @param latestSolid - * @return + * @param latest latest milestone index + * @param latestSolid latest solid milestone index + * @param oldestInQueue oldest milestone index we process, can be null + * @return A percentage value of syncedness */ double calculatePercentageSynced(int latest, int latestSolid, int oldestInQueue) { - double currentD = oldestInQueue - latestSolid; + if (oldestInQueue != 0 && oldestInQueue > latestSolid && + (oldestSeenMilestoneIndex > oldestInQueue || oldestSeenMilestoneIndex == 0)) { + oldestSeenMilestoneIndex = oldestInQueue; + } + + double currentD = (oldestInQueue == 0 ? latestSolid : oldestSeenMilestoneIndex) - latestSolid; double targetD = latest - latestSolid; - double processPercentage = 100 - currentD / targetD / 0.01d / 100d * PERCENT_WEIGHT_DOWN; + + double processPercentage = (100 - currentD / targetD / 0.01d) / 100d * PERCENT_WEIGHT_DOWN; + if (processPercentage >= 95 && latestSolid != latest) { + return -1; + } double percentageSynced = processPercentage + ((latestSolid / latest / 0.01d) / 100d * (100d - PERCENT_WEIGHT_DOWN)); return percentageSynced;