[MLA-803] Add timer metadata to C# and python (#3758)

* Add timer metadata to C# and python

* end time last

* changelog

* add commandline args

com.unity.ml-agents/CHANGELOG.md

  - Format of console output has changed slightly and now matches the name of the model/summary directory. (#3630, #3616)
  - Added a feature to allow sending stats from C# environments to TensorBoard (and other python StatsWriters). To do this from your code, use `SideChannelUtils.GetSideChannel<StatsSideChannel>().AddStat(key, value)` (#3660)
  - Renamed 'Generalization' feature to 'Environment Parameter Randomization'.
+ - Timer files now contain a dictionary of metadata, including things like the package version numbers.
  - SideChannel IncomingMessages methods now take an optional default argument, which is used when trying to read more data than the message contains.
  - The way that UnityEnvironment decides the port was changed. If no port is specified, the behavior will depend on the `file_name` parameter. If it is `None`, 5004 (the editor port) will be used; otherwise 5005 (the base environment port) will be used.
  - Fixed an issue where exceptions from environments provided a returncode of 0. (#3680)

com.unity.ml-agents/Runtime/Academy.cs

         /// </summary>
         void InitializeEnvironment()
         {
+            TimerStack.Instance.AddMetadata("communication_protocol_version", k_ApiVersion);
+            TimerStack.Instance.AddMetadata("package_version", k_PackageVersion);
+
             EnableAutomaticStepping();
 
             SideChannelUtils.RegisterSideChannel(new EngineConfigurationChannel());

com.unity.ml-agents/Runtime/Timer.cs

         Dictionary<string, TimerNode> m_Children;
 
         /// <summary>
-        /// Gauge Nodes to measure arbitrary values.
-        /// </summary>
-        [DataMember(Name = "gauges", EmitDefaultValue = false)]
-        Dictionary<string, GaugeNode> m_Gauges;
-
-        /// <summary>
         /// Custom sampler used to add timings to the profiler.
         /// </summary>
         CustomSampler m_Sampler;
             set {}  // Serialization needs this, but unused.
         }
 
-        public Dictionary<string, GaugeNode> Gauges
-        {
-            get { return m_Gauges; }
-        }
-
         /// <summary>
         /// Total seconds spent in this block, excluding it's children.
         /// </summary>
                 // The root node doesn't have a sampler since that could interfere with the profiler.
                 m_NumCalls = 1;
                 m_TickStart = DateTime.Now.Ticks;
-                m_Gauges = new Dictionary<string, GaugeNode>();
             }
             else
             {
         }
     }
 
+    [DataContract]
+    internal class RootNode : TimerNode
+    {
+        // Timer output format version
+        internal const string k_timerFormatVersion = "0.1.0";
+
+        [DataMember(Name = "metadata", Order = 0)]
+        Dictionary<string, string> m_Metadata = new Dictionary<string, string>();
+
+        /// <summary>
+        /// Gauge Nodes to measure arbitrary values.
+        /// </summary>
+        [DataMember(Name = "gauges", EmitDefaultValue = false)]
+        Dictionary<string, GaugeNode> m_Gauges = new Dictionary<string, GaugeNode>();
+
+        public RootNode(string name="root") : base(name, true)
+        {
+            m_Metadata.Add("timer_format_version", k_timerFormatVersion);
+            m_Metadata.Add("start_time_seconds", $"{DateTimeOffset.Now.ToUnixTimeSeconds()}");
+            m_Metadata.Add("unity_version", Application.unityVersion);
+            m_Metadata.Add("command_line_arguments", String.Join(" ", Environment.GetCommandLineArgs()));
+        }
+
+        public void AddMetadata(string key, string value)
+        {
+            m_Metadata[key] = value;
+        }
+
+        public Dictionary<string, GaugeNode> Gauges
+        {
+            get { return m_Gauges; }
+        }
+
+        public Dictionary<string, string> Metadata
+        {
+            get { return m_Metadata; }
+        }
+    }
+
     /// <summary>
     /// Tracks the most recent value of a metric. This is analogous to gauges in statsd.
     /// </summary>
         static readonly TimerStack k_Instance = new TimerStack();
 
         Stack<TimerNode> m_Stack;
-        TimerNode m_RootNode;
+        RootNode m_RootNode;
+        Dictionary<string, string> m_Metadata;
 
         // Explicit static constructor to tell C# compiler
         // not to mark type as beforefieldinit
         public void Reset(string name = "root")
         {
             m_Stack = new Stack<TimerNode>();
-            m_RootNode = new TimerNode(name, true);
+            m_RootNode = new RootNode(name);
             m_Stack.Push(m_RootNode);
         }
 
             get { return k_Instance; }
         }
 
-        internal TimerNode RootNode
+        internal RootNode RootNode
         {
             get { return m_RootNode; }
         }
                     m_RootNode.Gauges[name] = new GaugeNode(value);
                 }
             }
+        }
+
+        public void AddMetadata(string key, string value)
+        {
+            m_RootNode.AddMetadata(key, value);
         }
 
         void Push(string name)
         /// <param name="stream"></param>
         public void SaveJsonTimers(Stream stream)
         {
+            // Add some final metadata info
+            AddMetadata("scene_name", SceneManager.GetActiveScene().name);
+            AddMetadata("end_time_seconds", $"{DateTimeOffset.Now.ToUnixTimeSeconds()}");
+
-            var ser = new DataContractJsonSerializer(typeof(TimerNode), jsonSettings);
+            var ser = new DataContractJsonSerializer(typeof(RootNode), jsonSettings);
             ser.WriteObject(stream, m_RootNode);
         }
     }

com.unity.ml-agents/Tests/Editor/TimerTest.cs

                     using (myTimer.Scoped("bar"))
                     {
                         myTimer.SetGauge("my_gauge", i);
+                        myTimer.AddMetadata("i", $"{i}");
                     }
                 }
             }
             Assert.AreEqual(0, gauge.minValue);
             Assert.AreEqual(4, gauge.maxValue);
             Assert.AreEqual(4, gauge.value);
+            Assert.AreEqual("4", myTimer.RootNode.Metadata["i"]);
 
             var fooChildren = rootChildren["foo"].Children;
             Assert.That(fooChildren, Contains.Key("bar"));

ml-agents-envs/mlagents_envs/tests/test_timers.py

                 }
             },
             "gauges": {"my_gauge": {"value": 4.0, "max": 4.0, "min": 0.0, "count": 3}},
+            "metadata": {
+                "timer_format_version": timers.TIMER_FORMAT_VERSION,
+                "start_time_seconds": mock.ANY,
+                "end_time_seconds": mock.ANY,
+                "python_version": mock.ANY,
+                "command_line_arguments": mock.ANY,
+            },
         }
 
         assert timer_tree == expected_tree

ml-agents-envs/mlagents_envs/timers.py

 """
 
 import math
-from time import perf_counter
+import sys
+import time
+
+TIMER_FORMAT_VERSION = "0.1.0"
 
 
 class TimerNode:
     sure that pushes and pops are already matched.
     """
 
-    __slots__ = ["root", "stack", "start_time", "gauges"]
+    __slots__ = ["root", "stack", "start_time", "gauges", "metadata"]
-        self.start_time = perf_counter()
+        self.start_time = time.perf_counter()
+        self.metadata: Dict[str, str] = {}
+        self._add_default_metadata()
-        self.start_time = perf_counter()
+        self.start_time = time.perf_counter()
+        self.metadata: Dict[str, str] = {}
+        self._add_default_metadata()
 
     def push(self, name: str) -> TimerNode:
         """
         Update the total time and count of the root name, and return it.
         """
         root = self.root
-        root.total = perf_counter() - self.start_time
+        root.total = time.perf_counter() - self.start_time
         root.count = 1
         return root
 
             if self.gauges:
                 res["gauges"] = self._get_gauges()
 
+            if self.metadata:
+                self.metadata["end_time_seconds"] = str(int(time.time()))
+                res["metadata"] = self.metadata
+
         res["total"] = node.total
         res["count"] = node.count
 
         else:
             self.gauges[name] = GaugeNode(value)
 
+    def add_metadata(self, key: str, value: str) -> None:
+        self.metadata[key] = value
+
+
+    def _add_default_metadata(self):
+        self.metadata["timer_format_version"] = TIMER_FORMAT_VERSION
+        self.metadata["start_time_seconds"] = str(int(time.time()))
+        self.metadata["python_version"] = sys.version
+        self.metadata["command_line_arguments"] = " ".join(sys.argv)
 
 
 # Global instance of a TimerStack. This is generally all that we need for profiling, but you can potentially
     """
     timer_stack = timer_stack or _global_timer_stack
     timer_node = timer_stack.push(name)
-    start_time = perf_counter()
+    start_time = time.perf_counter()
 
     try:
         # The wrapped code block will run here.
         # We'll accumulate the time, and the exception (if any) gets raised automatically.
-        elapsed = perf_counter() - start_time
+        elapsed = time.perf_counter() - start_time
         timer_node.add_time(elapsed)
         timer_stack.pop()
 
     """
     timer_stack = timer_stack or _global_timer_stack
     timer_stack.set_gauge(name, value)
+
+
+def add_metadata(key: str, value: str, timer_stack: TimerStack = None) -> None:
+    timer_stack = timer_stack or _global_timer_stack
+    timer_stack.add_metadata(key, value)
 
 
 def get_timer_tree(timer_stack: TimerStack = None) -> Dict[str, Any]:

ml-agents/mlagents/trainers/learn.py

 from mlagents_envs.side_channel.side_channel import SideChannel
 from mlagents_envs.side_channel.engine_configuration_channel import EngineConfig
 from mlagents_envs.exception import UnityEnvironmentException
-from mlagents_envs.timers import hierarchical_timer, get_timer_tree
+from mlagents_envs.timers import (
+    hierarchical_timer,
+    get_timer_tree,
+    add_metadata as add_timer_metadata,
+)
 from mlagents_envs import logging_util
 
 logger = logging_util.get_logger(__name__)
     run_seed = options.seed
     if options.cpu:
         os.environ["CUDA_VISIBLE_DEVICES"] = "-1"
+
+    # Add some timer metadata
+    add_timer_metadata("mlagents_version", mlagents.trainers.__version__)
+    add_timer_metadata("mlagents_envs_version", mlagents_envs.__version__)
+    add_timer_metadata("communication_protocol_version", UnityEnvironment.API_VERSION)
+    add_timer_metadata("tensorflow_version", tf_utils.tf.__version__)
 
     if options.seed == -1:
         run_seed = np.random.randint(0, 10000)