Opened 8 years ago

Closed 8 years ago

Last modified 8 years ago

#397 closed defect (fixed)

Router runs out of memory.

Reported by: guest Owned by: zzz
Priority: blocker Milestone: 0.8.4
Component: api/i2cp Version: 0.8.3
Keywords: out of memory Cc:
Parent Tickets:

Description

I have configured wrapper.java.maxmemory=640
Router runs for about 2 days then it does not work anymore. No memory clean up and logs full of errors from java:
Full thread dump Java HotSpot?(TM) 64-Bit Server VM (19.0-b09 mixed mode), but none I have seen from the i2prouter. If I don't restart it, it runs into deadlock and does not work anymore.

Router.memoryUsed every 12 hours or so:

(Bytes) Max is 568MB
avg: 122.88M max: 164.93M now: 125.22M
avg: 199.18M max: 307.47M now: 233.19M
avg: 268.59M max: 365.34M now: 340.54M
avg: 456.19M max: 574.10M now: 406.80M
avg: 504.14M max: 556.52M now: 549.92M

I2P version: 0.8.3-0
Java version: Sun Microsystems Inc. 1.6.0_23 (Java(TM) SE Runtime Environment 1.6.0_23-b05)
Platform: Linux amd64 2.6.35
Processor: uninitialized (athlon64)
Jbigi: Optimized native BigInteger? library 'libjbigi-linux-athlon64.so' loaded from resource
Encoding: UTF-8

Subtickets

Change History (20)

comment:1 Changed 8 years ago by echelon

  • Owner set to echelon
  • Status changed from new to accepted

Moin!

What usage do you have to use so much memory?
Any torrent client, to much torrents in I2Psnark, to much clients?

What does the memory graph on http://127.0.0.1:7657/graphs ?

Looks like you do have some >100 torrents running.

echelon

comment:2 Changed 8 years ago by guest

I have come to set 640M to see if setting more memory solves my problem but it doesn't.
My usage is far away from your assumption. I have 9 torrents at i2psnark, robert has 5. Imule has a bunch, but there are none active or just about 2 or 3 that depends.
What I do is small and it has been running at the past. Not anymore.
The "Router.memoryUsed every 12 hours or so" from my first post come from http://127.0.0.1:7657/graphs

comment:3 Changed 8 years ago by echelon

Moin.
Strange at all. Could you try to figure out which app does use lots of memory?
E.g. start without snark, robert and imule and watch the graph?
After a few hours, start one of these apps and watch again?

For me I2P uses ~240 MB with i2psnark, imule and ~200 tunnels.
Some option runs mad at your config.

echelon

comment:4 Changed 8 years ago by zzz

Maybe we now have a memory leak. There were lots of changes in 0.8.3 so it's certainly possible. The best way to diagnose is to disable your apps (snark, robert, imule) one at a time. Or start them one at a time. Which is pretty much what echelon said.

comment:5 Changed 8 years ago by guest

In between there was an update, now my router is running since 36 hours, it's looking well, I'll keep watching it.
I also looked at http://java.sun.com/j2se/1.5.0/docs/guide/vm/server-class.html and my machine runs only as server (AMD64, more than 2 GB RAM), so I changed wrapper.java.additional.6=-server to wrapper.java.additional.6=-d64 maybe it doesn't change a thing but I wanted to make shure.
If the java machine runs oom again, I'll investigate client after client. So, an answer will take a few days, I suppose.

comment:6 Changed 8 years ago by sponge

I'm seeing these for all kinds of stuff, even IRC, and the eepproxy... Related to the OOM?

Memory use currently holding @ ~ 180MB, will look at the saved log of the mem usage and see what's happening.

[7.0.0.1:7658] unnel.I2PTunnelHTTPBidirServer: Error connecting to HTTP server /127.0.0.1:7658

java.net.ConnectException?: Connection refused
at java.net.PlainSocketImpl?.socketConnect(Native Method)
at java.net.PlainSocketImpl?.doConnect(Unknown Source)
at java.net.PlainSocketImpl?.connectToAddress(Unknown Source)
at java.net.PlainSocketImpl?.connect(Unknown Source)
at java.net.SocksSocketImpl?.connect(Unknown Source)
at java.net.Socket.connect(Unknown Source)
at java.net.Socket.connect(Unknown Source)
at java.net.Socket.<init>(Unknown Source)
at java.net.Socket.<init>(Unknown Source)
at net.i2p.i2ptunnel.I2PTunnelHTTPServer.blockingHandle(I2PTunnelHTTPServer.java:121)
at net.i2p.i2ptunnel.I2PTunnelServer$Handler.run(I2PTunnelServer.java:371)
at java.util.concurrent.ThreadPoolExecutor?$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor?$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

comment:7 Changed 8 years ago by guest

I could not repeat the oom error I have reported. Even increasing the torrent count slightly didn't change it.
Currently i2p is running for 2 days stable and normally, memory is:
avg 265.06M max 340.24M now 240.47M

I don't have errors like sponge reported. Everything looks fine, now.

comment:8 Changed 8 years ago by sponge

With a newer JVM, I got a more pinpointed set of what's happening, and better messages. There were like over 100 gc related fixes since I last upgraded. The upgraded jvm dod allow the router to last longer since it does a better job managing memory.

I think it is because we are attempting to synchronize on non-final fields. Doing that doesn't explicitly allow concurrency, and can fail. My best guess is that the changes that we are expecting to happen, are not happening the way they need to happen, and changes are not made to the set in net.i2p.client.I2PSessionImpl2, or anything that is similar or implementing it.

In short net.i2p.client.MessageState?, isn't getting changed or is getting changed when we don't want it to be changed, or, is seeing old data. In other words, a race condition. We should really fix all the synchronization errors, I think it would clean up a lot of problems.

I've located something for us to use a concurrent set, eliminating the need to synchronize on java.util.Set, which isn't going to do what is needed anyway.

http://www.java2s.com/Tutorial/Java/0140__Collections/Concurrentset.htm

Bonus is we'd get concurrent access to the set, which is good for performance too!

Here's the router log, it shows what is happening.

2/7/11 4:51:24 AM ERROR [7.0.0.1:7658] unnel.I2PTunnelHTTPBidirServer: Error connecting to HTTP server /127.0.0.1:7658
java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:529)
        at java.net.Socket.connect(Socket.java:478)
        at java.net.Socket.<init>(Socket.java:375)
        at java.net.Socket.<init>(Socket.java:218)
        at net.i2p.i2ptunnel.I2PTunnelHTTPServer.blockingHandle(I2PTunnelHTTPServer.java:121)
        at net.i2p.i2ptunnel.I2PTunnelServer$Handler.run(I2PTunnelServer.java:371)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
2/7/11 4:51:37 AM ERROR [7.0.0.1:7658] unnel.I2PTunnelHTTPBidirServer: Error connecting to HTTP server /127.0.0.1:7658
java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:529)
        at java.net.Socket.connect(Socket.java:478)
        at java.net.Socket.<init>(Socket.java:375)
        at java.net.Socket.<init>(Socket.java:218)
        at net.i2p.i2ptunnel.I2PTunnelHTTPServer.blockingHandle(I2PTunnelHTTPServer.java:121)
        at net.i2p.i2ptunnel.I2PTunnelServer$Handler.run(I2PTunnelServer.java:371)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
2/7/11 4:52:10 AM ERROR [7.0.0.1:7658] unnel.I2PTunnelHTTPBidirServer: Error connecting to HTTP server /127.0.0.1:7658
java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:529)
        at java.net.Socket.connect(Socket.java:478)
        at java.net.Socket.<init>(Socket.java:375)
        at java.net.Socket.<init>(Socket.java:218)
        at net.i2p.i2ptunnel.I2PTunnelHTTPServer.blockingHandle(I2PTunnelHTTPServer.java:121)
        at net.i2p.i2ptunnel.I2PTunnelServer$Handler.run(I2PTunnelServer.java:371)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
2/7/11 4:55:23 PM ERROR [Reader 39614] .tunnel.pool.TunnelPoolManager: Want the inbound tunnel for *CENSORED* but there isn't a pool?
2/7/11 6:17:24 PM ERROR [uildExecutor] t.i2p.router.OutNetMessagePool: Already expired!  wtf: [OutNetMessage contains a 4262 byte net.i2p.data.i2np.TunnelGatewayMessage expiring on Mon Feb 07 23:17:20 GMT 2011 targetting *CENSORED* with onFailedSend job: net.i2p.router.tunnel.pool.BuildHandler$TunnelBuildNextHopFailJob@875440: Job 8855314: Timeout contacting next peer for tunnel join {timestamps:
}]
java.lang.Exception: Expired message
        at net.i2p.router.OutNetMessagePool.validate(OutNetMessagePool.java:81)
        at net.i2p.router.OutNetMessagePool.add(OutNetMessagePool.java:44)
        at net.i2p.router.tunnel.pool.BuildHandler.handleReq(BuildHandler.java:684)
        at net.i2p.router.tunnel.pool.BuildHandler.handleRequest(BuildHandler.java:390)
        at net.i2p.router.tunnel.pool.BuildHandler.handleInboundRequests(BuildHandler.java:162)
        at net.i2p.router.tunnel.pool.BuildExecutor.run(BuildExecutor.java:357)
        at java.lang.Thread.run(Thread.java:662)
        at net.i2p.util.I2PThread.run(I2PThread.java:77)
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23641: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23641
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23661: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23661
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23663: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23663
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23665: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23665
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23666: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23666
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23667: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23667
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23668: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23668
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=23721: [MessagePayloadMessage:
        SessionId: 26711
        MessageId: 23721
        Payload: [Payload]]
2/7/11 6:23:37 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23641 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23641 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23661 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23661 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23663 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23663 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23665 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23665 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23666 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23666 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23667 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23667 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23668 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23668 already received!
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 23721 had no matches
2/7/11 6:23:38 PM ERROR [45-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 23721 already received!
2/7/11 6:25:48 PM ERROR [W pumper 3/4] t.i2p.router.OutNetMessagePool: Already expired!  wtf: [OutNetMessage contains a 1044 byte net.i2p.data.i2np.TunnelDataMessage expiring on Mon Feb 07 23:25:46 GMT 2011 targetting *CENSORED* {timestamps:
}]
java.lang.Exception: Expired message
        at net.i2p.router.OutNetMessagePool.validate(OutNetMessagePool.java:81)
        at net.i2p.router.OutNetMessagePool.add(OutNetMessagePool.java:44)
        at net.i2p.router.tunnel.OutboundReceiver.send(OutboundReceiver.java:59)
        at net.i2p.router.tunnel.OutboundReceiver.receiveEncrypted(OutboundReceiver.java:40)
        at net.i2p.router.tunnel.OutboundSender.sendPreprocessed(OutboundSender.java:34)
        at net.i2p.router.tunnel.BatchedPreprocessor.send(BatchedPreprocessor.java:398)
        at net.i2p.router.tunnel.BatchedPreprocessor.preprocessQueue(BatchedPreprocessor.java:174)
        at net.i2p.router.tunnel.PumpedTunnelGateway.pump(PumpedTunnelGateway.java:108)
        at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:63)
        at java.lang.Thread.run(Thread.java:662)
        at net.i2p.util.I2PThread.run(I2PThread.java:77)
2/7/11 6:26:50 PM ERROR [W pumper 4/4] t.i2p.router.OutNetMessagePool: Already expired!  wtf: [OutNetMessage contains a 1044 byte net.i2p.data.i2np.TunnelDataMessage expiring on Mon Feb 07 23:26:50 GMT 2011 targetting *CENSORED* {timestamps:
}]
java.lang.Exception: Expired message
        at net.i2p.router.OutNetMessagePool.validate(OutNetMessagePool.java:81)
        at net.i2p.router.OutNetMessagePool.add(OutNetMessagePool.java:44)
        at net.i2p.router.tunnel.OutboundReceiver.send(OutboundReceiver.java:59)
        at net.i2p.router.tunnel.OutboundReceiver.receiveEncrypted(OutboundReceiver.java:40)
        at net.i2p.router.tunnel.OutboundSender.sendPreprocessed(OutboundSender.java:34)
        at net.i2p.router.tunnel.BatchedPreprocessor.send(BatchedPreprocessor.java:398)
        at net.i2p.router.tunnel.BatchedPreprocessor.preprocessQueue(BatchedPreprocessor.java:240)
        at net.i2p.router.tunnel.PumpedTunnelGateway.pump(PumpedTunnelGateway.java:108)
        at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:63)
        at java.lang.Thread.run(Thread.java:662)
        at net.i2p.util.I2PThread.run(I2PThread.java:77)
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24395: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24395
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24396: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24396
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24398: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24398
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24400: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24400
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24402: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24402
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24407: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24407
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24410: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24410
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24413: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24413
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24427: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24427
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24428: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24428
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24429: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24429
        Payload: [Payload]]
2/7/11 6:30:55 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24430: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24430
        Payload: [Payload]]
2/7/11 6:31:09 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24439: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24439
        Payload: [Payload]]
2/7/11 6:31:09 PM ERROR [cheduler 2/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24440: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24440
        Payload: [Payload]]
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24395 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24395 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24396 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24396 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24398 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24398 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24400 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24400 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24402 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24402 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24407 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24407 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24410 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24410 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24413 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24413 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24427 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24427 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24428 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24428 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24429 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24429 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24430 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24430 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24439 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24439 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24440 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24440 already received!
2/7/11 6:31:09 PM ERROR [cheduler 3/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24442: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24442
        Payload: [Payload]]
2/7/11 6:31:09 PM ERROR [cheduler 3/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24443: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24443
        Payload: [Payload]]
2/7/11 6:31:09 PM ERROR [cheduler 3/4] net.i2p.client.I2PSessionImpl2: Message NOT removed!  id=24444: [MessagePayloadMessage:
        SessionId: 26712
        MessageId: 24444
        Payload: [Payload]]
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24442 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24442 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24443 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24443 already received!
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Receive message 24444 had no matches
2/7/11 6:31:09 PM ERROR [d9-Single]: ] net.i2p.client.I2PSessionImpl2: Error: message 24444 already received!
2/7/11 6:39:12 PM ERROR [W pumper 1/4] t.i2p.router.OutNetMessagePool: Already expired!  wtf: [OutNetMessage contains a 1044 byte net.i2p.data.i2np.TunnelDataMessage expiring on Mon Feb 07 23:39:10 GMT 2011 targetting *CENSORED* {timestamps:
}]
java.lang.Exception: Expired message
        at net.i2p.router.OutNetMessagePool.validate(OutNetMessagePool.java:81)
        at net.i2p.router.OutNetMessagePool.add(OutNetMessagePool.java:44)
        at net.i2p.router.tunnel.OutboundReceiver.send(OutboundReceiver.java:59)
        at net.i2p.router.tunnel.OutboundReceiver.receiveEncrypted(OutboundReceiver.java:40)
        at net.i2p.router.tunnel.OutboundSender.sendPreprocessed(OutboundSender.java:34)
        at net.i2p.router.tunnel.BatchedPreprocessor.send(BatchedPreprocessor.java:398)
        at net.i2p.router.tunnel.BatchedPreprocessor.preprocessQueue(BatchedPreprocessor.java:174)
        at net.i2p.router.tunnel.PumpedTunnelGateway.pump(PumpedTunnelGateway.java:108)
        at net.i2p.router.tunnel.TunnelGatewayPumper.run(TunnelGatewayPumper.java:63)
        at java.lang.Thread.run(Thread.java:662)
        at net.i2p.util.I2PThread.run(I2PThread.java:77)

comment:9 Changed 8 years ago by zzz

<zzz> as I said, we already have a concurrent set implementation.
<zzz> you have any evidence from jvisualvm to add?
<zzz> is this only a bidir tunnel problem?
<zzz> there's a lot of changes to i2cp in 0.8.3, it's a lot more likely to be related to those changes then some far-out theory about synchronization/finalization
<zzz> and you can't get rid of the synch in MessageState? anyway as you must lock a monitor to notify
<zzz> which is why that hasnt been converted to CHS
<zzz> it sounds to me like sessions arent being closed completely. If so that should be readily apparent in jvisualvm.
<zzz> and MessageState? is essentially unused as of 0.8.3, except for datagrams
<zzz> so you havent connected the dots for me by a long shot

comment:10 Changed 8 years ago by zzz

<sponge> the effects show up in other places
<sponge> just idle, no gains
<sponge> use streaming lib, stuff explodes
<sponge> see the 45-Single?
<sponge> see the d9-Single?
<sponge> those are streaming lib
<zzz> no
<zzz> all those msgs are from i2cp
<zzz> how many MessageState? objects you see in jvisualvm?
<sponge> fine, but those are streaming lib tunnels
<sponge> I'll start things up and look again
<zzz> all non-datagram tunnels are "streaming lib tunnels". so?
<zzz> streaming lib likely has nothing at all to do with this. you haven't pasted a single streaming lib message and there were no streaming lib changes in 0.8.3 iirc
<zzz> my guess is you will find ZERO MessageStates? since they are now unused. You've got a few error messages then you jumped 5 miles to a cause.
<sponge> moment pls
<zzz> what are 45-single and d9-single? bidir tunnels?
<zzz> or bob?
<sponge> BOB
<sponge> showing only 144 right now, let me start ramping things up
<zzz> from the looks of it those clients are not responding or have gone away
<zzz> 144 messagestates? that's 144 more than I thought would be there
<sponge> :-)
<sponge> and I've not run Robert yet
<zzz> interesting
<sponge> waiting for robert to warm up
<sponge> and then I can stop it and see if the number lowers, or not
<sponge> my guess is that it is the leak
<sponge> note, it's a guess
<sponge> based on reading about how syncronizing on non-final fields caused it to not be synced
<sponge> I can paste a small paragraph here about it if you want
<sponge> actually, I will...
<sponge> Why you should not be synchronizing on non-final field? Because if field value may change, then different threads may be synchronizing on different objects (different values of the field) - so there could be no synchronization at all (every thread may enter synchronized block at the same time).
<zzz> I don't need theories, I need data
<zzz> is the object count for it growing unbounded?
<sponge> will know in about 20 minutes, I want it to warm up well enough
<sponge> it's up to > 1k now
<sponge> (cough)
<sponge> no wait, 15, wrong column
<zzz> ok, well I found one thing. MessageStates? are now disabled for everything except datagrams.... and BOB
<sponge> will see after some time, it does take a while to build up
<zzz> apps/BOB/src/net/i2p/BOB/BOB.java
<zzz> props.setProperty(I2PClient.PROP_RELIABILITY, I2PClient.PROP_RELIABILITY_BEST_EFFORT);
<zzz> so everybody is getting the optimization except for BOB
<sponge> so BOB isn't using it?
<zzz> the default in streaming is now PROP_RELIABILITY_NONE. But you are overriding it in BOB.
<sponge> yep
<sponge> but it is changable in the config
<zzz> you can just remove it and you'll get the streaming default
<sponge> it also seems to stream better from what I've found
<sponge> well, the idea is it is configurable
<zzz> bull. BEST_EFFORT was the only supported option before.
<sponge> exactly
<sponge> and I put it in there to be in-line at the time BOB was written
<zzz> you're saying you've compared NONE vs. BEST_EFFORT in the last 2 weeks?
<sponge> no, I assumed (based on my recollections from way back) there were different delivery types
<sponge> and was tring them
<zzz> there were, but only before you wrote BOB, probably 5 years ago there was GUARANTEED
<sponge> perhaps it was pure luck, I don't know
<zzz> you probably just copied it from somewhere
<sponge> right
<sponge> so, I'll let this run a while
<sponge> now you are saying that it's using something else?
<sponge> a different path?
<zzz> maybe I broke BEST_EFFORT somehow, and only BOB is seeing it
<sponge> 77 on message state right now
<zzz> I'm saying I did a big optimization to remove use of MessageState?. But only for RELIABILITY_NONE. Which is the new streaming default.
<sponge> ok
<zzz> But you haven't given me any evidence yet of a MessageState? leak anyway.
<sponge> well, I can test and see
<sponge> it does take time if it is a real race
<zzz> hard for a race to cause an OOM.
<sponge> if the race causes a leak, though....
<zzz> if you are getting lots of I2CP errors like in the ticket, seems like the client is going away.
<sponge> again, I'm mostly guessing here, and basing it on stuff I have read about syncronized fields
<sponge> some of it right on sun's site
<sponge> it certainly can't hurt to change to a concurrent set
<zzz> don't guess. you're making good progress with the error messages, dont give up on detective work and start guessing :)
<zzz> yes it can for the reasons above.
<zzz> you can't change because you can't notify an unsynched monitor.
<zzz> and we already have a concurrent hash set class so the code you found isnt helpful.
<sponge> any way to make it final via a factory then?
<zzz> I dont know, I have to look at it again. But the whole thing is unused now, it's pointless.
<sponge> ahhh I see
<zzz> anyway, change best effort to none for a minor optimization
<sponge> hmmm
<sponge> in caps?
<zzz> even better just delete it. streaming knows what it wants, dont override it
<sponge> I can do that

  • korg_ has quit (Ping timeout)

<sponge> going to keep my eyes peeled on the things with the most instances first though.
<sponge> are you going to be ditching that code? If not, shouldn't we fix it? what if that's not the problem?
<zzz> what problem
<zzz> and, btw, _receivedStatus _is_ final.
<zzz> _you_ made it final on 8/11/2009.
<sponge> not _receivedStatus ...
<sponge> I2PSessionImpl2.java
<sponge> line 36
<sponge> private /* FIXME final FIXME */ Set<MessageState?> _sendingStates;
<sponge> hmmm... something using byte[] is growing and growing
<sponge> will be testing 'none' in a couple minutes
<sponge> ...and we'll see if it makes a difference
<sponge> I'll know for certain if there is any sort of leak via 'none' in an hour or so.
<zzz> sponge _sendingStates never changes, so not a problem there

comment:11 Changed 8 years ago by guest

oom behaviour hit me again. I noticed my router is stuttering in up- and downloads. When no traffic, no cpu consumption. If updload high cpu. I stopped robert, imule and i2psnark, makes no difference.
See http://pic.i2p/img/251-d02f019d1c880a8.png
There is no zig-zag router memory ups and downs.
Now, there is only the router running. Should have freed memory but hasn't. Still at 490MB RAM usage staying there, currently increasing to 561MB.
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11496 i2p 20 0 1512m 750m 3692 S 45 21.8 3432:14 java

Still free RAM available. No router logs.

comment:12 Changed 8 years ago by guest

Correction: Tahoe LAFS was running all the time started by I2P router plugin.

comment:13 Changed 8 years ago by zzz

  • Component changed from unspecified to api/i2cp
  • Owner changed from echelon to zzz
  • Priority changed from major to blocker

This is a router-side I2CP memory leak issue, triggered by frequent naming lookups in Robert. Thanks to sponge for pointing me to the cause. It's my bug and is not in any way the fault of BOB, Robert, or sponge, however the short-term workaround is to not use Robert.

The fix will be in net.i2p.internal.QueuedI2CPMessageReader.java and should be checked in in a day or two.

comment:14 Changed 8 years ago by guest

That is good news. Thanks to all.

comment:15 Changed 8 years ago by zzz

Fixed in 0.8.3-7, with the assistance of sponge.

comment:16 Changed 8 years ago by zzz

  • Resolution set to fixed
  • Status changed from accepted to closed

comment:17 Changed 8 years ago by guest

I have had auto update (history.txt: 2011-02-09 sponge * BOB: fixup delivery in config, adds config file versioning. * I2CP: Fix most of the I2CP leaks. Two leaks remain, but they are small. net.i2p.internal.QueuedI2CPMessageReader and net.i2p.router.client.I2CPMessageQueueImpl are the two remaining leaks.)

Still oom:

2011/02/11 01:58:18 | 11.02.2011 00:58:18 org.mortbay.util.Container start
2011/02/11 01:58:18 | INFO: Started WebApplicationContext[/tahoe-lafs-controller,/tahoe-lafs-controller]

==> ../.i2p/logs/log-router-1.txt <==

12.02.11 11:00:55 CRIT  [Mv3Handler 2] net.i2p.util.I2PThread        
: Thread terminated unexpectedly: SAMv3Handler 2
java.lang.NullPointerException
        at net.i2p.data.i2cp.I2CPMessageReader.stopReading(I2CPMessageReader.java:90)
        at net.i2p.client.I2PSessionImpl.closeSocket(I2PSessionImpl.java:707)
        at net.i2p.client.I2PSessionImpl.destroySession(I2PSessionImpl.java:695)
        at net.i2p.client.I2PSessionImpl2.destroySession(I2PSessionImpl2.java:87)
        at net.i2p.client.I2PSessionImpl.destroySession(I2PSessionImpl.java:660)
        at net.i2p.client.streaming.I2PSocketManagerFull.destroySocketManager(I2PSocketManagerFull.java:302)
        at net.i2p.sam.SAMv3StreamSession.close(SAMv3StreamSession.java:401)
        at net.i2p.sam.SAMv3Handler.die(SAMv3Handler.java:444)
        at net.i2p.sam.SAMv3Handler.handle(SAMv3Handler.java:436)
        at net.i2p.sam.SAMHandler.run(SAMHandler.java:192)
        at java.lang.Thread.run(Thread.java:662)
        at net.i2p.util.I2PThread.run(I2PThread.java:77)

i2p router almost dead. Torrents no data exchange.
Looking forward for the final fix.

comment:18 Changed 8 years ago by zzz

Thanks for testing.

It appears that what you tested is not the complete fix (please report a dev version as 0.8.3-?, displayed on the console summary bar). And yes it has NPE's in it.

The complete fix is in 0.8.3-7. Our friend echelon does the development builds that you are downloading, and he builds them on a somewhat erratic schedule. Next time I see him on IRC, I'll ask him to build the latest.

comment:19 Changed 8 years ago by guest

I2P version: 0.8.3-5
How to get 0.8.3-7 if it is not yet ready?

comment:20 Changed 8 years ago by zzz

Pull source from monotone and build it. http://www.i2p2.i2p/newdevelopers

Note: See TracTickets for help on using tickets.