Hi Oskar: I have been trying to figure out why the routingTime values are still so long on my machine even with the the Accept connection setup time discounted.
I have been watching the values reported by diagnostics, i.e.: http://127.0.0.1:8889/diagnostics/routingTime/occurrences Usually the value is ~= 5 - 150ms, but intermittently, my node appears to get stuck for a little while, and I see values as high as 70000ms (yes 70 seconds!). It eventually unsticks itself, and the values go back down. I attached a thread dump from when the node was in the stuck state. The most interesting follows below. It's holding a lock on the routing table and the the directory while it syncs. There are 16 other threads waiting on these two monitors. Do you think that this is a problem in itself, or the symptom of another problem? i.e. why would the sync call take very long? or why would it be hard to acquire the directory's lock? --gj PID:30081 "QThread-1448: freenet.Message: DataReply @freenet.ConnectionHandler@4931ac84 @ 8c7eddfb57b" (TID:0x40ecef08, sys_thread_t:0x84143d0, state:R, native ID:0x16d053) prio=5 at java.io.FileDescriptor.sync(Native Method) at freenet.fs.RAFStorage$FSOutputStream.flush(RAFStorage.java(Compiled Code)) at java.io.FilterOutputStream.flush(FilterOutputStream.java(Compiled Code)) at java.io.FilterOutputStream.close(FilterOutputStream.java(Compiled Code)) at freenet.fs.WriteLock$WriteLockOutputStream.close(WriteLock.java(Compiled Code)) at freenet.fs.acct.AccountingTable.putBlock(AccountingTable.java:164) at freenet.fs.acct.AccountingTable$BlockOutputStream.close(AccountingTable.java:183) at java.io.FilterOutputStream.close(FilterOutputStream.java(Compiled Code)) at freenet.fs.acct.SingleAccountingProcess.flush(SingleAccountingProcess.java(Compiled Code)) at freenet.fs.dir.FSDirectory.flush(FSDirectory.java:318) at freenet.fs.dir.SharedDirectory.flush(SharedDirectory.java:30) at freenet.fs.dir.LossyDirectory.forceFlush(LossyDirectory.java:62) at freenet.fs.dir.FSDataObjectStore.flush(FSDataObjectStore.java:46) at freenet.fs.dir.FSDataObjectStore.keys(FSDataObjectStore.java:116) at freenet.node.rt.DataObjectRoutingStore.remove(DataObjectRoutingStore.java:70) at freenet.node.rt.TreeRoutingTable.discard(TreeRoutingTable.java:118) at freenet.node.rt.TreeRoutingTable.reference(TreeRoutingTable.java:80) at freenet.node.rt.FilterRoutingTable.reference(FilterRoutingTable.java:38) at freenet.node.states.request.AwaitingStoreData.relayStoreData(AwaitingStoreData.java:103) at freenet.node.states.request.AwaitingStoreData.receivedMessage(AwaitingStoreData.java:85) at java.lang.reflect.Method.invoke(Native Method) at freenet.node.State.received(State.java(Compiled Code)) at freenet.node.StateChain.received(StateChain.java(Compiled Code)) at freenet.node.StateChain.received(StateChain.java(Compiled Code)) at freenet.node.StateChain.received(StateChain.java(Compiled Code)) at freenet.node.StandardMessageHandler$Ticket.run(StandardMessageHandler.java(Compiled Code)) at freenet.node.StandardMessageHandler$Ticket.received(StandardMessageHandler.java(Compiled Code)) at freenet.node.StandardMessageHandler$Ticket.access$100(StandardMessageHandler.java(Compiled Code)) at freenet.node.StandardMessageHandler.handle(StandardMessageHandler.java(Compiled Code)) at freenet.Ticker$Event.run(Ticker.java(Compiled Code)) at freenet.thread.QThreadFactory$QThread.run(QThreadFactory.java(Compiled Code)) -- Freesite (0.4) freenet:SSK@npfV5XQijFkF6sXZvuO0o~kG4wEPAgM/homepage//
javacore28517.1027789635.txt.gz
Description: GNU Zip compressed data
Continuous:
routingTime
The amount of time between when requests are dispatched (client call or message received) and when the first route is found.Aggregated over every minute . Recorded occurrences:
| Time | Mean | Std. Dev. | Minimum | Maximum | Observations |
|---|---|---|---|---|---|
| 7/27/02 5:14:44 PM EDT | 60387.0 | 0.0 | 60387.0 | 60387.0 | 1 |
| 7/27/02 5:14:44 PM EDT | 2067.0 | 0.0 | 2067.0 | 2067.0 | 1 |
| 7/27/02 5:14:44 PM EDT | 3438.0 | 0.0 | 3438.0 | 3438.0 | 1 |
| 7/27/02 5:14:44 PM EDT | 4475.0 | 0.0 | 4475.0 | 4475.0 | 1 |
| 7/27/02 5:14:58 PM EDT | 22653.0 | 0.0 | 22653.0 | 22653.0 | 1 |
| 7/27/02 5:14:59 PM EDT | 74160.0 | 0.0 | 74160.0 | 74160.0 | 1 |
| 7/27/02 5:14:59 PM EDT | 3966.0 | 0.0 | 3966.0 | 3966.0 | 1 |
| 7/27/02 5:14:59 PM EDT | 9755.0 | 0.0 | 9755.0 | 9755.0 | 1 |
| 7/27/02 5:14:59 PM EDT | 70628.0 | 0.0 | 70628.0 | 70628.0 | 1 |
| 7/27/02 5:14:59 PM EDT | 11412.0 | 0.0 | 11412.0 | 11412.0 | 1 |
| 7/27/02 5:14:59 PM EDT | 8764.0 | 0.0 | 8764.0 | 8764.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 70585.0 | 0.0 | 70585.0 | 70585.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 67320.0 | 0.0 | 67320.0 | 67320.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 67108.0 | 0.0 | 67108.0 | 67108.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 65124.0 | 0.0 | 65124.0 | 65124.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 64649.0 | 0.0 | 64649.0 | 64649.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 63619.0 | 0.0 | 63619.0 | 63619.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 52996.0 | 0.0 | 52996.0 | 52996.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 51656.0 | 0.0 | 51656.0 | 51656.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 51123.0 | 0.0 | 51123.0 | 51123.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 51137.0 | 0.0 | 51137.0 | 51137.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 50098.0 | 0.0 | 50098.0 | 50098.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 47135.0 | 0.0 | 47135.0 | 47135.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 44417.0 | 0.0 | 44417.0 | 44417.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 43692.0 | 0.0 | 43692.0 | 43692.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 43024.0 | 0.0 | 43024.0 | 43024.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 34911.0 | 0.0 | 34911.0 | 34911.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 34001.0 | 0.0 | 34001.0 | 34001.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 31581.0 | 0.0 | 31581.0 | 31581.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 31034.0 | 0.0 | 31034.0 | 31034.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 30474.0 | 0.0 | 30474.0 | 30474.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 30367.0 | 0.0 | 30367.0 | 30367.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 27064.0 | 0.0 | 27064.0 | 27064.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 1740.0 | 0.0 | 1740.0 | 1740.0 | 1 |
| 7/27/02 5:15:00 PM EDT | 64758.0 | 0.0 | 64758.0 | 64758.0 | 1 |
| 7/27/02 5:15:01 PM EDT | 2394.0 | 0.0 | 2394.0 | 2394.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 9708.0 | 0.0 | 9708.0 | 9708.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 251.0 | 0.0 | 251.0 | 251.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 8795.0 | 0.0 | 8795.0 | 8795.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 7638.0 | 0.0 | 7638.0 | 7638.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 1309.0 | 0.0 | 1309.0 | 1309.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 809.0 | 0.0 | 809.0 | 809.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 1193.0 | 0.0 | 1193.0 | 1193.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 1105.0 | 0.0 | 1105.0 | 1105.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 835.0 | 0.0 | 835.0 | 835.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 9937.0 | 0.0 | 9937.0 | 9937.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 632.0 | 0.0 | 632.0 | 632.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 209.0 | 0.0 | 209.0 | 209.0 | 1 |
| 7/27/02 5:15:10 PM EDT | 26.0 | 0.0 | 26.0 | 26.0 | 1 |
| 7/27/02 5:15:14 PM EDT | 5.0 | 0.0 | 5.0 | 5.0 | 1 |
| 7/27/02 5:15:18 PM EDT | 6.0 | 0.0 | 6.0 | 6.0 | 1 |
| 7/27/02 5:15:18 PM EDT | 5.0 | 0.0 | 5.0 | 5.0 | 1 |
| 7/27/02 5:15:18 PM EDT | 6.0 | 0.0 | 6.0 | 6.0 | 1 |
| 7/27/02 5:15:18 PM EDT | 4.0 | 0.0 | 4.0 | 4.0 | 1 |
| 7/27/02 5:15:19 PM EDT | 5.0 | 0.0 | 5.0 | 5.0 | 1 |
| 7/27/02 5:15:19 PM EDT | 4.0 | 0.0 | 4.0 | 4.0 | 1 |
| 7/27/02 5:15:19 PM EDT | 4.0 | 0.0 | 4.0 | 4.0 | 1 |
| 7/27/02 5:15:19 PM EDT | 5.0 | 0.0 | 5.0 | 5.0 | 1 |
| 7/27/02 5:15:21 PM EDT | 6.0 | 0.0 | 6.0 | 6.0 | 1 |
| 7/27/02 5:15:25 PM EDT | 5.0 | 0.0 | 5.0 | 5.0 | 1 |
