Add some RTD logging

Source/ExcelDna.Integration/ExcelRtd.cs

@@ -70,7 +70,7 @@ public static void RegisterRtdServerTypes(IEnumerable<Type> rtdServerTypes)
         // ThreadSafe
         public static bool TryRTD(out object result, string progId, string server, params string[] topics)
         {
-            Debug.Print("### RtdRegistration.RTD " + progId);
+            Debug.Print($"[{DateTime.Now:HH:mm:ss.f}] ### RtdRegistration.RTD " + progId);
             // Check if this is any of our business.
             if (!string.IsNullOrEmpty(server))
             {

Source/ExcelDna.Integration/ExcelRtdServer.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using ExcelDna.Logging;
 
 namespace ExcelDna.Integration.Rtd
@@ -234,6 +235,7 @@ void SetDirty(Topic topic)
         // This is the private implementation of the IRtdServer interface
         int IRtdServer.ServerStart(IRTDUpdateEvent callbackObject)
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] ServerStart");
             try
             {
                 _updateSync = SynchronizationManager.RtdUpdateSynchronization;
@@ -264,6 +266,7 @@ int IRtdServer.ServerStart(IRTDUpdateEvent callbackObject)
         //            if newValues is now true, Excel will use the value returned by ConnectData.
         object IRtdServer.ConnectData(int topicId, ref Array strings, ref bool newValues)
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] ConnectData");
             try
             {
                 // Check for an active topic with the same topicId 
@@ -330,6 +333,7 @@ object IRtdServer.ConnectData(int topicId, ref Array strings, ref bool newValues
 
         Array IRtdServer.RefreshData(ref int topicCount)
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] RefreshData");
             // Get a copy of the dirty topics to work with, 
             // locking as briefly as possible (thanks Naju).
             Dictionary<Topic, object> temp;
@@ -352,13 +356,15 @@ Array IRtdServer.RefreshData(ref int topicCount)
             {
                 result[0, i] = topic.TopicId;
                 result[1, i] = topic.Value;
+                Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] RefreshData - TopicId: {topic.TopicId} Value: {topic.Value}");
                 i++;
             }
             return result;
         }
 
         void IRtdServer.DisconnectData(int topicId)
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] DisconnectData");
             try
             {
                 Topic topic;
@@ -387,6 +393,7 @@ void IRtdServer.DisconnectData(int topicId)
         // (though this should not be needed according to the RTD interface contract)
         int IRtdServer.Heartbeat()
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] Heartbeat");
             try
             {
                 // Re-post the notify in case something went wrong on the Excel side or our sync window
@@ -418,6 +425,7 @@ int IRtdServer.Heartbeat()
 
         void IRtdServer.ServerTerminate()
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] ServerTerminate");
             try
             {
                 // The Unregister call here just tells the reg-free loading that we are gone, 

Source/ExcelDna.Integration/ExcelSynchronizationContext.cs

@@ -115,6 +115,7 @@ public RtdUpdateSynchronization(SynchronizationWindow syncWindow)
         // We assume UpdateNotify is not called too often here (need RTD server to be careful).
         public void UpdateNotify(IRTDUpdateEvent updateEvent)
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] RtdUpdateSynchronization.UpdateNotify");
             lock (_lockObject)
             {
                 _pendingRtdUpdates[updateEvent] = null;
@@ -142,6 +143,7 @@ public void DeregisterUpdateNotify(IRTDUpdateEvent updateEvent)
         //       However, the problem reported there was surely when called from another thread. Does suspension of the object model affect us here?
         public void ProcessUpdateNotifications()
         {
+            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] ProcessUpdateNotifications");
             // CONSIDER: Do temp swap trick to reduce locking?
             lock (_lockObject)
             {
@@ -152,6 +154,7 @@ public void ProcessUpdateNotifications()
                     {
                         if (_registeredRtdUpdates.ContainsKey(pendingRtdUpdate))
                         {
+                            Debug.WriteLine($"[{DateTime.Now:HH:mm:ss.f}] Calling UpdateNotify - Thread: {System.Threading.Thread.CurrentThread.ManagedThreadId}");
                             pendingRtdUpdate.UpdateNotify();
                         }
                     }