* BuildExecutor: Add tunnel.buildConfigTime stat

* FloodfillMonitorJob: Log tweak (ticket #533)
  * I2CP: Improve error message (ticket #533)
  * JobQueue:
    - Log error when queue is out of order
    - Log tweaks
  * FloodfillPeerSelector: Fix stat NPE (tickets #534,535)
  * RouterThrottle:
    - Fix stat NPE (tickets #534,535)
    - Increase max tunnels and max delay again
  * OutNetMessagePool: Log tweak (ticket #533)
  * Router:
    - Add OOM help (ticket #533)
    - Prevent parallel shutdowns after multiple OOMs (tickets #534,535)
This commit is contained in:
zzz
2011-10-15 17:30:24 +00:00
parent 3dbefa8d01
commit 82ac0db333
11 changed files with 78 additions and 23 deletions

View File

@@ -395,7 +395,7 @@ abstract class I2PSessionImpl implements I2PSession, I2CPMessageReader.I2CPMessa
_producer.disconnect(this);
} catch (I2PSessionException ipe) {}
closeSocket();
throw new IOException("No tunnels built after waiting 5 minutes... are there network problems?");
throw new IOException("No tunnels built after waiting 5 minutes. Your network connection may be down, or there is severe network congestion.");
}
synchronized (_leaseSetWait) {
try {

View File

@@ -1,3 +1,31 @@
* 2011-10-15 zzz
* BuildExecutor: Add tunnel.buildConfigTime stat
* configupdate.jsp:
- Fix setting to 'never' (ticket #523)
- Fix always saying trusted keys changed
- Parameterize tags
* EepGet:
- Add gunzip support (nonproxied only)
- Clean up progress formatting
* FloodfillMonitorJob: Log tweak (ticket #533)
* I2CP: Improve error message (ticket #533)
* JobQueue:
- Log error when queue is out of order
- Log tweaks
* FloodfillPeerSelector: Fix stat NPE (tickets #534,535)
* RouterThrottle:
- Fix stat NPE (tickets #534,535)
- Increase max tunnels and max delay again
* OutNetMessagePool: Log tweak (ticket #533)
* Router:
- Add OOM help (ticket #533)
- Prevent parallel shutdowns after multiple OOMs (tickets #534,535)
* Stats: Add API methods for zero duration
* SSLEepGet:
- Add gunzip support
- Increase buffer size
* SSU: Fix concurrency errors (ticket #536)
* 2011-10-13 kytv
* Updated translations from Transifex
- Swedish: debconf and i2psnark

View File

@@ -172,7 +172,9 @@ public class JobQueue {
// alreadyExists = true;
// Always remove and re-add, since it needs to be
// re-sorted in the TreeSet.
_timedJobs.remove(job);
boolean removed = _timedJobs.remove(job);
if (removed && _log.shouldLog(Log.WARN))
_log.warn("Rescheduling job: " + job);
}
if ((!alreadyExists) && shouldDrop(job, numReady)) {
@@ -197,9 +199,8 @@ public class JobQueue {
_context.statManager().addRateData("jobQueue.readyJobs", numReady, 0);
if (dropped) {
_context.statManager().addRateData("jobQueue.droppedJobs", 1, 1);
if (_log.shouldLog(Log.ERROR))
_log.error("Dropping job due to overload! # ready jobs: "
_context.statManager().addRateData("jobQueue.droppedJobs", 1, 0);
_log.logAlways(Log.WARN, "Dropping job due to overload! # ready jobs: "
+ numReady + ": job = " + job);
}
}
@@ -461,10 +462,18 @@ public class JobQueue {
long timeToWait = -1;
try {
synchronized (_jobLock) {
Job lastJob = null;
long lastTime = Long.MIN_VALUE;
for (Iterator<Job> iter = _timedJobs.iterator(); iter.hasNext(); ) {
Job j = iter.next();
// find jobs due to start before now
long timeLeft = j.getTiming().getStartAfter() - now;
if (lastJob != null && lastTime > j.getTiming().getStartAfter()) {
_log.error("Job " + lastJob + " out of order with job " + j +
" difference of " + DataHelper.formatDuration(lastTime - j.getTiming().getStartAfter()));
}
lastJob = j;
lastTime = lastJob.getTiming().getStartAfter();
if (timeLeft <= 0) {
if (j instanceof JobImpl)
((JobImpl)j).madeReady();

View File

@@ -66,11 +66,12 @@ public class OutNetMessagePool {
return false;
}
if (msg.getPriority() < 0) {
_log.warn("Priority less than 0? sounds like nonsense to me... " + msg, new Exception("Negative priority"));
_log.error("Priority less than 0? sounds like nonsense to me... " + msg, new Exception());
return false;
}
if (msg.getExpiration() <= _context.clock().now()) {
_log.error("Already expired! wtf: " + msg, new Exception("Expired message"));
if (_log.shouldLog(Log.WARN))
_log.warn("Dropping expired outbound msg: " + msg, new Exception());
return false;
}
return true;

View File

@@ -74,6 +74,8 @@ public class Router implements RouterClock.ClockShiftListener {
private int _gracefulExitCode;
private I2PThread.OOMEventListener _oomListener;
private ShutdownHook _shutdownHook;
/** non-cancellable shutdown has begun */
private volatile boolean _shutdownInProgress;
private final I2PThread _gracefulShutdownDetector;
private final RouterWatchdog _watchdog;
private final Thread _watchdogThread;
@@ -275,7 +277,10 @@ public class Router implements RouterClock.ClockShiftListener {
_oomListener = new I2PThread.OOMEventListener() {
public void outOfMemory(OutOfMemoryError oom) {
clearCaches();
_log.log(Log.CRIT, "Thread ran out of memory", oom);
_log.log(Log.CRIT, "Thread ran out of memory, shutting down I2P", oom);
// prevent multiple parallel shutdowns (when you OOM, you OOM a lot...)
if (_shutdownInProgress)
return;
for (int i = 0; i < 5; i++) { // try this 5 times, in case it OOMs
try {
_log.log(Log.CRIT, "free mem: " + Runtime.getRuntime().freeMemory() +
@@ -285,6 +290,7 @@ public class Router implements RouterClock.ClockShiftListener {
// gobble
}
}
_log.log(Log.CRIT, "To prevent future shutdowns, increase wrapper.java.maxmemory in $I2P/wrapper.config");
shutdown(EXIT_OOM);
}
};
@@ -999,6 +1005,9 @@ public class Router implements RouterClock.ClockShiftListener {
* Shutdown with no chance of cancellation
*/
public void shutdown(int exitCode) {
if (_shutdownInProgress)
return;
_shutdownInProgress = true;
if (_shutdownHook != null) {
try {
Runtime.getRuntime().removeShutdownHook(_shutdownHook);

View File

@@ -31,14 +31,14 @@ class RouterThrottleImpl implements RouterThrottle {
private static int THROTTLE_EVENT_LIMIT = 30;
private static final String PROP_MAX_TUNNELS = "router.maxParticipatingTunnels";
private static final int DEFAULT_MAX_TUNNELS = 3500;
private static final int DEFAULT_MAX_TUNNELS = 5000;
private static final String PROP_DEFAULT_KBPS_THROTTLE = "router.defaultKBpsThrottle";
private static final String PROP_MAX_PROCESSINGTIME = "router.defaultProcessingTimeThrottle";
/**
* TO BE FIXED - SEE COMMENTS BELOW
*/
private static final int DEFAULT_MAX_PROCESSINGTIME = 1750;
private static final int DEFAULT_MAX_PROCESSINGTIME = 2250;
/** tunnel acceptance */
public static final int TUNNEL_ACCEPT = 0;
@@ -113,7 +113,9 @@ class RouterThrottleImpl implements RouterThrottle {
// counterintuitively be more when there is low traffic)
// Change the stat or pick a better stat.
RateStat rs = _context.statManager().getRate("transport.sendProcessingTime");
Rate r = rs.getRate(60*1000);
Rate r = null;
if (rs != null)
r = rs.getRate(60*1000);
//Reject tunnels if the time to process messages and send them is too large. Too much time implies congestion.
if(r != null) {

View File

@@ -18,7 +18,7 @@ public class RouterVersion {
/** deprecated */
public final static String ID = "Monotone";
public final static String VERSION = CoreVersion.VERSION;
public final static long BUILD = 0;
public final static long BUILD = 1;
/** for example "-test" */
public final static String EXTRA = "";

View File

@@ -144,8 +144,7 @@ class FloodfillMonitorJob extends JobImpl {
if (good < MIN_FF && happy) {
if (!wasFF) {
_lastChanged = now;
if (_log.shouldLog(Log.ERROR))
_log.error("Only " + good + " ff peers and we want " + MIN_FF + " so we are becoming floodfill");
_log.logAlways(Log.INFO, "Only " + good + " ff peers and we want " + MIN_FF + " so we are becoming floodfill");
}
return true;
}
@@ -154,8 +153,7 @@ class FloodfillMonitorJob extends JobImpl {
if (good > MAX_FF || (good > MIN_FF && !happy)) {
if (wasFF) {
_lastChanged = now;
if (_log.shouldLog(Log.ERROR))
_log.error("Have " + good + " ff peers and we need only " + MIN_FF + " to " + MAX_FF +
_log.logAlways(Log.INFO, "Have " + good + " ff peers and we need only " + MIN_FF + " to " + MAX_FF +
" so we are disabling floodfill; reachable? " + happy);
}
return false;

View File

@@ -193,12 +193,16 @@ class FloodfillPeerSelector extends PeerSelector {
int found = 0;
long now = _context.clock().now();
double maxFailRate;
double maxFailRate = 100;
if (_context.router().getUptime() > 60*60*1000) {
double currentFailRate = _context.statManager().getRate("peer.failedLookupRate").getRate(60*60*1000).getAverageValue();
maxFailRate = Math.max(0.20d, 1.5d * currentFailRate);
} else {
maxFailRate = 100d; // disable
RateStat rs = _context.statManager().getRate("peer.failedLookupRate");
if (rs != null) {
Rate r = rs.getRate(60*60*1000);
if (r != null) {
double currentFailRate = r.getAverageValue();
maxFailRate = Math.max(0.20d, 1.5d * currentFailRate);
}
}
}
// 8 == FNDF.MAX_TO_FLOOD + 1

View File

@@ -216,8 +216,8 @@ class ProfilePersistenceHelper {
long lastSentToSuccessfully = getLong(props, "lastSentToSuccessfully");
if (isExpired(lastSentToSuccessfully)) {
if (_log.shouldLog(Log.WARN))
_log.warn("Dropping old profile for " + file.getName() +
if (_log.shouldLog(Log.INFO))
_log.info("Dropping old profile " + file.getName() +
", since we haven't heard from them in a long time");
file.delete();
return null;

View File

@@ -61,6 +61,7 @@ class BuildExecutor implements Runnable {
_context.statManager().createRequiredRateStat("tunnel.buildExploratoryReject", "Response time for rejection (ms)", "Tunnels", new long[] { 10*60*1000, 60*60*1000 });
_context.statManager().createRequiredRateStat("tunnel.buildClientReject", "Response time for rejection (ms)", "Tunnels", new long[] { 10*60*1000, 60*60*1000 });
_context.statManager().createRequiredRateStat("tunnel.buildRequestTime", "Time to build a tunnel request (ms)", "Tunnels", new long[] { 60*1000, 10*60*1000 });
_context.statManager().createRateStat("tunnel.buildConfigTime", "Time to build a tunnel request (ms)", "Tunnels", new long[] { 60*1000, 10*60*1000 });
_context.statManager().createRateStat("tunnel.buildRequestZeroHopTime", "How long it takes to build a zero hop tunnel", "Tunnels", new long[] { 60*1000, 10*60*1000 });
_context.statManager().createRateStat("tunnel.pendingRemaining", "How many inbound requests are pending after a pass (period is how long the pass takes)?", "Tunnels", new long[] { 60*1000, 10*60*1000 });
_context.statManager().createRateStat("tunnel.buildFailFirstHop", "How often we fail to build a OB tunnel because we can't contact the first hop", "Tunnels", new long[] { 60*1000, 10*60*1000 });
@@ -327,6 +328,7 @@ class BuildExecutor implements Runnable {
TunnelPool pool = wanted.remove(0);
//if (pool.countWantedTunnels() <= 0)
// continue;
long bef = System.currentTimeMillis();
PooledTunnelCreatorConfig cfg = pool.configureNewTunnel();
if (cfg != null) {
// 0hops are taken care of above, these are nonstandard 0hops
@@ -337,6 +339,8 @@ class BuildExecutor implements Runnable {
pool.buildComplete(cfg);
continue;
}
long pTime = System.currentTimeMillis() - bef;
_context.statManager().addRateData("tunnel.buildConfigTime", pTime, 0);
if (_log.shouldLog(Log.DEBUG))
_log.debug("Configuring new tunnel " + i + " for " + pool + ": " + cfg);
buildTunnel(pool, cfg);