[logcat-parse] Support repeated handles. (#35)

I've come across some log files which would contain *several thousand*
global references, as per the `grefc` values, but when processing via
logcat-parse `grefs.AlivePeers.Count()` would invariably return `11`,
or some other ludicrously low value given the input.

On further investigation, a problem is with repeated handle values.
Once a handle has been disposed, there's no reason why it couldn't be
reused again:

	+g+ grefc 1 gwrefc 0 obj-handle 0x4a00009/L -> new-handle 0x19004aa/G from thread '(null)'(3)
	-g- grefc 0 gwrefc 0 handle 0x19004aa/G from thread '(null)'(3)
	# OK, created + destroyed an instance...

	+g+ grefc 1 gwrefc 0 obj-handle 0x4a00009/L -> new-handle 0x19004aa/G from thread '(null)'(3)
	# OK, created a *different* instance

Unfortunately, `logcat-parse` would treat the second +g+ as if it were
an alias of the originally created instance. As such,
`grefs.AlivePeers.Count()` would return 0, not 1, which is wrong.

To better support this, keep a separate `alive` list of peers, and
only consult the "alive" list when performing handle lookups. This
prevents the original -- dead! -- PeerInfo from being reused, allowing
us to have (more?) accurate peer information.

tools/logcat-parse/Grefs.cs

@@ -13,7 +13,7 @@ public class Grefs {
 		const string ThreadAndStack       = @"(thread (?<thread>'[^']+'\([^)]+\)))?(?<stack>.*)$";
 		const string AddGrefFormat        = Prefix + @"\+g\+ grefc (?<gcount>\d+) gwrefc (?<wgcount>\d+) obj-handle (?<handle>0x[0-9A-Fa-f]+)/(?<handle_type>.) -> new-handle (?<ghandle>0x[0-9A-Fa-f]+)/(?<ghandle_type>.) from " + ThreadAndStack;
 		const string AddWgrefFormat       = Prefix + @"\+w\+ grefc (?<gcount>\d+) gwrefc (?<wgcount>\d+) obj-handle (?<handle>0x[0-9A-Fa-f]+)/(?<handle_type>.) -> new-handle (?<whandle>0x[0-9A-Fa-f]+)/(?<whandle_type>.) from " + ThreadAndStack;
-		const string AtFormat             = Prefix + @"(?<stack>   at.*$)";
+		const string AtFormat             = Prefix + @"(?<stack>\s+at.*$)";
 		const string DisposingFormat      = Prefix + @"Disposing handle (?<handle>0x[0-9A-Fa-f]+)$";
 		const string FinalizingFormat     = Prefix + @"Finalizing (?<type>[^ ]+) handle (?<handle>0x[0-9A-Fa-f]+)$";
 		const string HandleFormat         = Prefix + @"handle (?<handle>0x[0-9A-Fa-f]+); key_handle (?<key_handle>0x[0-9A-Fa-f]+): Java Type: `(?<jtype>[^`]+)`; MCW type: `(?<mtype>.*)`$";
@@ -53,11 +53,12 @@ public static Grefs Parse (TextReader reader, int? pid = null, GrefParseOptions
 		HashSet<JniHandleInfo>      WeakRefs    = new HashSet<JniHandleInfo>();
 
 		List<PeerInfo>      allocated   = new List<PeerInfo> ();
+		List<PeerInfo>      alive       = new List<PeerInfo> ();
 
 		public GrefParseOptions         ParseOptions    {get; private set;}
 		public IList<PeerInfo>          AllocatedPeers  {get; private set;}
 		public IEnumerable<PeerInfo>    AlivePeers {
-			get {return allocated.Where (p => !p.Collected && !p.Disposed && !p.Finalized);}
+			get {return alive;}
 		}
 
 		public int                      GrefCount {
@@ -145,6 +146,7 @@ Dictionary<Regex, Action<Match, int>> CreateHandlers (int? pid)
 						if (!WeakRefs.Any (w => p.Handles.Contains (w))) {
 							p.Collected = true;
 							p.DestroyedOnThread = m.Groups ["thread"].Value;
+							alive.Remove (p);
 						}
 						CheckCounts (m, l);
 
@@ -158,6 +160,7 @@ Dictionary<Regex, Action<Match, int>> CreateHandlers (int? pid)
 						if (!GlobalRefs.Any (g => p.Handles.Contains (g))) {
 							p.Collected = true;
 							p.DestroyedOnThread = m.Groups ["thread"].Value;
+							alive.Remove (p);
 						}
 						CheckCounts (m, l);
 
@@ -208,9 +211,9 @@ void CheckCounts (Match m, int lineNumber)
 		PeerInfo GetPeerInfo (Match m)
 		{
 			var h = GetHandle (m, "handle");
-			var i = allocated.FindLastIndex (p => p.Handles.Contains (h));
+			var i = alive.FindLastIndex (p => p.Handles.Contains (h));
 			if (i >= 0)
-				return allocated [i];
+				return alive [i];
 			var pid = m.Groups ["pid"].Value;
 			var peer = new PeerInfo (pid) {
 				CreatedOnThread = m.Groups ["thread"].Value,
@@ -219,6 +222,7 @@ PeerInfo GetPeerInfo (Match m)
 				},
 			};
 			allocated.Add (peer);
+			alive.Add (peer);
 			return peer;
 		}
 	}

tools/logcat-parse/PeerInfo.cs

@@ -146,6 +146,10 @@ public bool                         Finalized {
 			set {state |= PeerInfoState.Finalized;}
 		}
 
+		public bool Alive {
+			get {return state == PeerInfoState.Alive;}
+		}
+
 		public string                       JniType     {get; internal set;}
 		public string                       McwType     {get; internal set;}
 

tools/logcat-parse/Tests/GrefsTest.cs

@@ -398,6 +398,56 @@ public void TrackThreadInformation ()
 					peer.GetStackTraceForHandle ("0x100492/G"));
 			}
 		}
+
+		[Test]
+		public void RepeatedThreadHandles ()
+		{
+			using (var source = new StreamReader (Assembly.GetExecutingAssembly ().GetManifestResourceStream ("stdio-repeated-handles"))) {
+				var info = Grefs.Parse (source, options: GrefParseOptions.ThrowOnCountMismatch);
+				Assert.AreEqual (2, info.AllocatedPeers.Count);
+				Assert.AreEqual (1, info.AlivePeers.Count ());
+				Assert.AreEqual (1, info.GrefCount);
+				Assert.AreEqual (0, info.WeakGrefCount);
+
+				var peer = info.AllocatedPeers [0];
+				Assert.IsTrue (peer.Collected);
+				Assert.IsTrue (peer.Disposed);
+				Assert.IsFalse (peer.Finalized);
+				Assert.AreEqual ("java/lang/String", peer.JniType);
+				Assert.AreEqual ("Java.Lang.String", peer.McwType);
+
+				Assert.AreEqual ("'(null)'(3)", peer.CreatedOnThread);
+				Assert.AreEqual ("'(null)'(3)", peer.DestroyedOnThread);
+
+				Assert.AreEqual ("0x41e29778", peer.KeyHandle);
+				Assert.AreEqual (2, peer.Handles.Count);
+				Assert.IsTrue (peer.Handles.Contains ("0x4a00009/L"));
+				Assert.IsTrue (peer.Handles.Contains ("0x19004aa/G"));
+
+				Assert.AreEqual (
+					"  at Doesn't Matter",
+					peer.GetStackTraceForHandle ("0x19004aa/G"));
+
+				peer = info.AllocatedPeers [1];
+				Assert.IsFalse (peer.Collected);
+				Assert.IsFalse (peer.Disposed);
+				Assert.IsFalse (peer.Finalized);
+				Assert.AreEqual ("java/lang/String", peer.JniType);
+				Assert.AreEqual ("Java.Lang.String", peer.McwType);
+
+				Assert.AreEqual ("'(null)'(3)", peer.CreatedOnThread);
+				Assert.AreEqual (null,          peer.DestroyedOnThread);
+
+				Assert.AreEqual ("0x41e29778", peer.KeyHandle);
+				Assert.AreEqual (2, peer.Handles.Count);
+				Assert.IsTrue (peer.Handles.Contains ("0x4a00009/L"));
+				Assert.IsTrue (peer.Handles.Contains ("0x19004aa/G"));
+
+				Assert.AreEqual (
+					"  at Doesn't Matter",
+					peer.GetStackTraceForHandle ("0x19004aa/G"));
+			}
+		}
 	}
 }
 

tools/logcat-parse/Tests/LogcatParse-Tests.csproj

@@ -84,5 +84,8 @@
     <EmbeddedResource Include="Resources\stdio-Finalized-threads.txt">
       <LogicalName>stdio-Finalized-threads</LogicalName>
     </EmbeddedResource>
+    <EmbeddedResource Include="Resources\stdio-repeated-handles.txt">
+      <LogicalName>stdio-repeated-handles</LogicalName>
+    </EmbeddedResource>
   </ItemGroup>
 </Project>

tools/logcat-parse/Tests/Resources/stdio-repeated-handles.txt

@@ -0,0 +1,9 @@
++g+ grefc 1 gwrefc 0 obj-handle 0x4a00009/L -> new-handle 0x19004aa/G from thread '(null)'(3)
+  at Doesn't Matter
+handle 0x19004aa; key_handle 0x41e29778: Java Type: `java/lang/String`; MCW type: `Java.Lang.String`
+Disposing handle 0x19004aa
+-g- grefc 0 gwrefc 0 handle 0x19004aa/G from thread '(null)'(3)
+  at Doesn't Matter
++g+ grefc 1 gwrefc 0 obj-handle 0x4a00009/L -> new-handle 0x19004aa/G from thread '(null)'(3)
+  at Doesn't Matter
+handle 0x19004aa; key_handle 0x41e29778: Java Type: `java/lang/String`; MCW type: `Java.Lang.String`