Opened 7 years ago

Closed 7 years ago

#665 closed enhancement (fixed)

Debugging with (new Exception()) should not be used in hot paths

Reported by: zab Owned by: zzz
Priority: minor Milestone: 0.9.1
Component: router/transport Version: 0.9
Keywords: SSU memory OOM Cc:
Parent Tickets:

Description

Creating new Exception(...) objects is convenient, but very expensive both CPU-wise and memory-wise. You do not want it to be enabled by default on code paths that are executed frequently, or you risk the following situation where the debugging code causes an OutOfMemoryError?:

2012/07/21 02:50:48 | java.lang.OutOfMemoryError: Java heap space
2012/07/21 02:50:48 |   at java.util.LinkedHashMap.createEntry(LinkedHashMap.java:441)
2012/07/21 02:50:48 |   at java.util.LinkedHashMap.addEntry(LinkedHashMap.java:423)
2012/07/21 02:50:48 |   at java.util.HashMap.put(HashMap.java:402)
2012/07/21 02:50:48 |   at sun.util.resources.OpenListResourceBundle.loadLookup(OpenListResourceBundle.java:134)
2012/07/21 02:50:48 |   at sun.util.resources.OpenListResourceBundle.loadLookupTablesIfNecessary(OpenListResourceBundle.java:113)
2012/07/21 02:50:48 |   at sun.util.resources.OpenListResourceBundle.handleGetObject(OpenListResourceBundle.java:74)
2012/07/21 02:50:48 |   at sun.util.resources.TimeZoneNamesBundle.handleGetObject(TimeZoneNamesBundle.java:75)
2012/07/21 02:50:48 |   at java.util.ResourceBundle.getObject(ResourceBundle.java:387)
2012/07/21 02:50:48 |   at java.util.ResourceBundle.getObject(ResourceBundle.java:390)
2012/07/21 02:50:48 |   at java.util.ResourceBundle.getStringArray(ResourceBundle.java:370)
2012/07/21 02:50:48 |   at sun.util.TimeZoneNameUtility.retrieveDisplayNames(TimeZoneNameUtility.java:118)
2012/07/21 02:50:48 |   at sun.util.TimeZoneNameUtility.retrieveDisplayNames(TimeZoneNameUtility.java:99)
2012/07/21 02:50:48 |   at java.util.TimeZone.getDisplayNames(TimeZone.java:452)
2012/07/21 02:50:48 |   at java.util.TimeZone.getDisplayName(TimeZone.java:403)
2012/07/21 02:50:48 |   at java.util.Date.toString(Date.java:1042)
2012/07/21 02:50:48 |   at java.lang.String.valueOf(String.java:2902)
2012/07/21 02:50:48 |   at java.lang.StringBuilder.append(StringBuilder.java:128)
2012/07/21 02:50:48 |   at net.i2p.router.transport.udp.OutboundMessageState.releaseResources(OutboundMessageState.java:141)
2012/07/21 02:50:48 |   at net.i2p.router.transport.udp.PeerState.finishMessages(PeerState.java:1323)
2012/07/21 02:50:48 |   at net.i2p.router.transport.udp.OutboundMessageFragments.getNextVolley(OutboundMessageFragments.java:281)
2012/07/21 02:50:48 |   at net.i2p.router.transport.udp.PacketPusher.run(PacketPusher.java:37)
2012/07/21 02:50:48 |   at java.lang.Thread.run(Thread.java:722)
2012/07/21 02:50:48 |   at net.i2p.util.I2PThread.run(I2PThread.java:85)

The above was copied from a full bug report here http://http://pastethis.i2p/show/1465/ . Post mortem:

  1. NTCP thread ran out of cache, started allocated new byte[]
  2. It ran out of memory
  3. The code that is supposed to track use-after-free ran out of memory itself while trying to construct a descriptive exception.

Unfortunately there is no way to eat one's cake and keep it at the same time. If you are willing to forgo the stack traces and record just the thread that caused the problem, you can do it orders of magnitude cheaper this way:

#
# old_revision [2a403f031d73e2b624fd6cfcdde5e12a91d792f3]
#
# patch "router/java/src/net/i2p/router/transport/udp/OutboundMessageState.java"
#  from [ef587f13c90bbf09d0348f0aab4e175d3e35541e]
#    to [ad89db5af607d3e3a44c899a6bb6340fe62da3da]
#
============================================================
--- router/java/src/net/i2p/router/transport/udp/OutboundMessageState.java	ef587f13c90bbf09d0348f0aab4e175d3e35541e
+++ router/java/src/net/i2p/router/transport/udp/OutboundMessageState.java	ad89db5af607d3e3a44c899a6bb6340fe62da3da
@@ -35,7 +35,7 @@ class OutboundMessageState {
     // private int _nextSendFragment;
     /** for tracking use-after-free bugs */
     private boolean _released;
-    private Exception _releasedBy;
+    private Thread _releasedBy;
     
     public static final int MAX_MSG_SIZE = 32 * 1024;
     /** is this enough for a high-bandwidth router? */
@@ -138,7 +138,7 @@ class OutboundMessageState {
         if (_messageBuf != null && !_released) {
             _cache.release(_messageBuf);
             _released = true;
-            _releasedBy = new Exception ("Released on " + new Date() + " by:");
+            _releasedBy = Thread.currentThread();
         }
         //_messageBuf = null;
     }
@@ -336,8 +336,10 @@ class OutboundMessageState {
                 	at java.lang.Thread.run(Thread.java:619)
                 	at net.i2p.util.I2PThread.run(I2PThread.java:71)
             *******/
+        	final String threadInfo = _releasedBy == null ? "nobody?" :
+        		String.format("thread id %d name %s",_releasedBy.getId(),_releasedBy.getName());
             if (_log.shouldLog(Log.WARN))
-                _log.log(Log.WARN, "SSU OMS Use after free: " + toString(), _releasedBy);
+                _log.log(Log.WARN, "SSU OMS Use after free: " + toString()+" released by "+threadInfo);
             return -1;
             //throw new RuntimeException("SSU OMS Use after free: " + toString());
         }

Subtickets

Change History (1)

comment:1 Changed 7 years ago by zzz

  • Milestone set to 0.9.1
  • Resolution set to fixed
  • Status changed from new to closed

Good catch. Left over from debugging in 2009.

Fixed in 0.9-26-rc by only storing to _releasedBy when log level is WARN.

Note: See TracTickets for help on using tickets.