Exemplo n.º 1
0
        public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
        {
            var    results       = new List <double>();
            var    reloadResults = new List <double>();
            var    ins           = new Dictionary <int, double>();
            double start         = -1;
            int?   pid           = null;

            using (var source = new TraceSourceManager(mergeTraceFile))
            {
                source.Kernel.ProcessStart += evt =>
                {
                    if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
                    {
                        Console.WriteLine("Process Start");
                        pid   = evt.ProcessID;
                        start = evt.TimeStampRelativeMSec;
                    }
                };

                source.Source.Dynamic.AddCallbackForProviderEvent("HotReload", "HotReload/Start", evt =>
                {
                    if (evt.PayloadStringByName("handlerType").ToLower() == "main")
                    {
                        if (pid.HasValue)
                        {
                            results.Add(evt.TimeStampRelativeMSec - start);
                            start = evt.TimeStampRelativeMSec;
                        }
                    }
                });

                source.Source.Dynamic.AddCallbackForProviderEvent("HotReload", "HotReloadEnd", evt =>
                {
                    if (evt.PayloadStringByName("handlerType").ToLower() == "main")
                    {
                        if (pid.HasValue)
                        {
                            reloadResults.Add(evt.TimeStampRelativeMSec - start);
                            start = 0;
                            pid   = null;
                        }
                    }
                });

                source.Process();
            }

            return(new[] {
                new Counter()
                {
                    Name = "Time to Hot Reload Start", MetricName = "ms", TopCounter = true, Results = results.ToArray()
                },
                new Counter()
                {
                    Name = "Hot Reload Time", MetricName = "ms", TopCounter = true, DefaultCounter = true, Results = reloadResults.ToArray()
                },
            });
        }
Exemplo n.º 2
0
 public void AddEventStartCallback(TraceSourceManager source, DynamicTraceEventParser dynamicParser, string provider, IList <int> pids)
 {
     dynamicParser.AddCallbackForProviderEvent(provider, $"{EventName}/Start", evt =>
     {
         if (!Pid.HasValue && ParserUtility.MatchProcessID(evt, source, pids))
         {
             Pid   = evt.ProcessID;
             Start = evt.TimeStampRelativeMSec;
         }
     });
 }
        public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
        {
            var    results        = new List <double>();
            var    threadTimes    = new List <double>();
            var    buildEvalTime  = new List <double>();
            double threadTime     = 0;
            var    ins            = new Dictionary <int, double>();
            double start          = -1;
            double buildEvalStart = -1;
            int?   pid            = null;
            Dictionary <string, List <double> > firstRun   = new Dictionary <string, List <double> >();
            Dictionary <string, List <double> > secondRun  = new Dictionary <string, List <double> >();
            Dictionary <string, List <double> > currentRun = firstRun;

            using (var source = new TraceSourceManager(mergeTraceFile))
            {
                source.Kernel.ProcessStart += evt =>
                {
                    if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
                    {
                        pid   = evt.ProcessID;
                        start = evt.TimeStampRelativeMSec;
                    }
                };

                if (source.IsWindows)
                {
                    ((ETWTraceEventSource)source.Source).Kernel.ThreadCSwitch += evt =>
                    {
                        if (!pid.HasValue) // we're currently in a measurement interval
                        {
                            return;
                        }

                        if (evt.NewProcessID != pid && evt.OldProcessID != pid)
                        {
                            return;                                              // but this isn't our process
                        }
                        if (evt.OldProcessID == pid)                             // this is a switch out from our process
                        {
                            if (ins.TryGetValue(evt.OldThreadID, out var value)) // had we ever recorded a switch in for this thread?
                            {
                                threadTime += evt.TimeStampRelativeMSec - value;
                                ins.Remove(evt.OldThreadID);
                            }
                        }
                        else // this is a switch in to our process
                        {
                            ins[evt.NewThreadID] = evt.TimeStampRelativeMSec;
                        }
                    };
                }


                source.Kernel.ProcessStop += evt =>
                {
                    if (pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)pid))
                    {
                        if (!currentRun.ContainsKey(evt.EventName))
                        {
                            currentRun.Add(evt.EventName, new List <double>());
                            currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - start);
                        }
                        else
                        {
                            currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - start);
                        }
                        results.Add(evt.TimeStampRelativeMSec - start);
                        pid   = null;
                        start = 0;
                        if (source.IsWindows)
                        {
                            if (!currentRun.ContainsKey("ThreadCSwitch"))
                            {
                                currentRun.Add("ThreadCSwitch", new List <double>());
                                currentRun["ThreadCSwitch"].Add(threadTime);
                            }
                            else
                            {
                                currentRun["ThreadCSwitch"].Add(threadTime);
                            }
                            threadTimes.Add(threadTime);
                            threadTime = 0;
                        }
                    }
                };


                source.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Build", "Evaluate/Start", evt =>
                {
                    if (pid.HasValue && evt.ProcessID == pid.Value)
                    {
                        buildEvalStart = evt.TimeStampRelativeMSec;
                    }
                });

                source.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Build", "Evaluate/Stop", evt =>
                {
                    if (pid.HasValue && evt.ProcessID == pid.Value)
                    {
                        if (!currentRun.ContainsKey(evt.EventName))
                        {
                            currentRun.Add(evt.EventName, new List <double>());
                            currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - buildEvalStart);
                        }
                        else
                        {
                            currentRun[evt.EventName].Add(evt.TimeStampRelativeMSec - buildEvalStart);
                        }
                    }
                });

                source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "Split", evt =>
                {
                    currentRun = secondRun;
                });

                source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "EndIteration", evt =>
                {
                    currentRun = firstRun;
                });

                source.Process();
            }

            List <double> diffGS  = new List <double>();
            List <double> diffTOT = new List <double>();
            List <double> diffEBT = new List <double>();

            for (int i = 0; i < firstRun["Process/Stop"].Count; i++)
            {
                diffGS.Add(firstRun["Process/Stop"][i] - secondRun["Process/Stop"][i]);
            }
            for (int i = 0; i < firstRun["ThreadCSwitch"].Count; i++)
            {
                diffTOT.Add(firstRun["ThreadCSwitch"][i] - secondRun["ThreadCSwitch"][i]);
            }
            for (int i = 0; i < firstRun["Evaluate/Stop"].Count; i++)
            {
                diffEBT.Add(firstRun["Evaluate/Stop"][i] - secondRun["Evaluate/Stop"][i]);
            }

            return(new[] {
                new Counter()
                {
                    Name = "Generic Startup First Run", MetricName = "ms", TopCounter = true, Results = firstRun["Process/Stop"].ToArray()
                },
                new Counter()
                {
                    Name = "Generic Startup Second Run", MetricName = "ms", TopCounter = true, Results = secondRun["Process/Stop"].ToArray()
                },
                new Counter()
                {
                    Name = "Generic Startup Diff", MetricName = "ms", DefaultCounter = true, TopCounter = true, Results = diffGS.ToArray()
                },
                new Counter()
                {
                    Name = "Time on Thread Diff", MetricName = "ms", TopCounter = true, Results = diffTOT.ToArray()
                },
                new Counter()
                {
                    Name = "Build Evaluate Time First Run", MetricName = "ms", TopCounter = true, Results = firstRun["Evaluate/Stop"].ToArray()
                },
                new Counter()
                {
                    Name = "Build Evaluate Time Second Run", MetricName = "ms", TopCounter = true, Results = secondRun["Evaluate/Stop"].ToArray()
                },
                new Counter()
                {
                    Name = "Build Evaluate Time Diff", MetricName = "ms", TopCounter = true, Results = diffEBT.ToArray()
                }
            });
        }
        public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
        {
            var    results     = new List <double>();
            double threadTime  = 0;
            var    threadTimes = new List <double>();
            var    ins         = new Dictionary <int, double>();
            double start       = -1;
            int?   pid         = null;

            using (var source = new TraceSourceManager(mergeTraceFile))
            {
                source.Kernel.ProcessStart += evt =>
                {
                    if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
                    {
                        pid   = evt.ProcessID;
                        start = evt.TimeStampRelativeMSec;
                    }
                };

                if (source.IsWindows)
                {
                    ((ETWTraceEventSource)source.Source).Kernel.ThreadCSwitch += evt =>
                    {
                        if (!pid.HasValue) // we're currently in a measurement interval
                        {
                            return;
                        }

                        if (evt.NewProcessID != pid && evt.OldProcessID != pid)
                        {
                            return;                                              // but this isn't our process
                        }
                        if (evt.OldProcessID == pid)                             // this is a switch out from our process
                        {
                            if (ins.TryGetValue(evt.OldThreadID, out var value)) // had we ever recorded a switch in for this thread?
                            {
                                threadTime += evt.TimeStampRelativeMSec - value;
                                ins.Remove(evt.OldThreadID);
                            }
                        }
                        else // this is a switch in to our process
                        {
                            ins[evt.NewThreadID] = evt.TimeStampRelativeMSec;
                        }
                    };
                }

                ClrPrivateTraceEventParser clrpriv = new ClrPrivateTraceEventParser(source.Source);
                clrpriv.StartupMainStart += evt =>
                {
                    if (pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)pid))
                    {
                        results.Add(evt.TimeStampRelativeMSec - start);
                        pid   = null;
                        start = 0;
                        if (source.IsWindows)
                        {
                            threadTimes.Add(threadTime);
                            threadTime = 0;
                        }
                    }
                };
                source.Process();
            }

            var ret = new List <Counter> {
                new Counter()
                {
                    Name = "Time To Main", Results = results.ToArray(), TopCounter = true, DefaultCounter = true, HigherIsBetter = false, MetricName = "ms"
                }
            };

            if (threadTimes.Count != 0)
            {
                ret.Add(new Counter()
                {
                    Name = "Time on Thread", Results = threadTimes.ToArray(), TopCounter = true, DefaultCounter = false, HigherIsBetter = false, MetricName = "ms"
                });
            }
            return(ret);
        }
        public IEnumerable <Counter> Parse(string mergeTraceFile, string processName, IList <int> pids, string commandLine)
        {
            var    results                  = new List <double>();
            var    threadTimes              = new List <double>();
            double threadTime               = 0;
            var    ins                      = new Dictionary <int, double>();
            double start                    = -1;
            int?   pid                      = null;
            List <List <double> > firstRun  = new List <List <double> >();
            List <List <double> > secondRun = new List <List <double> >();

            using (var source = new TraceSourceManager(mergeTraceFile))
            {
                source.Kernel.ProcessStart += evt =>
                {
                    if (!pid.HasValue && ParserUtility.MatchProcessStart(evt, source, processName, pids, commandLine))
                    {
                        pid   = evt.ProcessID;
                        start = evt.TimeStampRelativeMSec;
                    }
                };

                if (source.IsWindows)
                {
                    ((ETWTraceEventSource)source.Source).Kernel.ThreadCSwitch += evt =>
                    {
                        if (!pid.HasValue) // we're currently in a measurement interval
                        {
                            return;
                        }

                        if (evt.NewProcessID != pid && evt.OldProcessID != pid)
                        {
                            return;                                              // but this isn't our process
                        }
                        if (evt.OldProcessID == pid)                             // this is a switch out from our process
                        {
                            if (ins.TryGetValue(evt.OldThreadID, out var value)) // had we ever recorded a switch in for this thread?
                            {
                                threadTime += evt.TimeStampRelativeMSec - value;
                                ins.Remove(evt.OldThreadID);
                            }
                        }
                        else // this is a switch in to our process
                        {
                            ins[evt.NewThreadID] = evt.TimeStampRelativeMSec;
                        }
                    };
                }

                if (useLoggingExtension)
                {
                    source.Source.Dynamic.AddCallbackForProviderEvent("Microsoft-Extensions-Logging", "FormattedMessage", evt =>
                    {
                        if (evt.PayloadString(5).ToLower() == "hosting started")
                        {
                            if (pid.HasValue)
                            {
                                results.Add(evt.TimeStampRelativeMSec - start);
                                pid   = null;
                                start = 0;
                                if (source.IsWindows)
                                {
                                    threadTimes.Add(threadTime);
                                    threadTime = 0;
                                }
                            }
                        }
                    });
                }
                else
                {
                    source.Kernel.ProcessStop += evt =>
                    {
                        if (pid.HasValue && ParserUtility.MatchSingleProcessID(evt, source, (int)pid))
                        {
                            results.Add(evt.TimeStampRelativeMSec - start);
                            pid   = null;
                            start = 0;
                            if (source.IsWindows)
                            {
                                threadTimes.Add(threadTime);
                                threadTime = 0;
                            }
                        }
                    };
                }

                source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "Split", evt =>
                {
                    if (firstRun.Count == 0)
                    {
                        firstRun.Add(new List <double>());
                        firstRun.Add(new List <double>());
                    }
                    firstRun[0].AddRange(results);
                    firstRun[1].AddRange(threadTimes);
                    results     = new List <double>();
                    threadTimes = new List <double>();
                });

                source.Source.Dynamic.AddCallbackForProviderEvent("InnerLoopMarkerEventSource", "EndIteration", evt =>
                {
                    if (secondRun.Count == 0)
                    {
                        secondRun.Add(new List <double>());
                        secondRun.Add(new List <double>());
                    }
                    secondRun[0].AddRange(results);
                    secondRun[1].AddRange(threadTimes);
                    results     = new List <double>();
                    threadTimes = new List <double>();
                });

                source.Process();
            }

            List <double> diffGS  = new List <double>();
            List <double> diffTOT = new List <double>();

            for (int i = 0; i < firstRun[0].Count; i++)
            {
                diffGS.Add(firstRun[0][i] - secondRun[0][i]);
            }
            for (int i = 0; i < firstRun[1].Count; i++)
            {
                diffTOT.Add(firstRun[1][i] - secondRun[1][i]);
            }

            return(new[] {
                new Counter()
                {
                    Name = "Generic Startup First Run", MetricName = "ms", TopCounter = true, Results = firstRun[0].ToArray()
                },
                new Counter()
                {
                    Name = "Generic Startup Second Run", MetricName = "ms", TopCounter = true, Results = secondRun[0].ToArray()
                },
                new Counter()
                {
                    Name = "Generic Startup Diff", MetricName = "ms", DefaultCounter = true, TopCounter = true, Results = diffGS.ToArray()
                },
                new Counter()
                {
                    Name = "Time on Thread Diff", MetricName = "ms", TopCounter = true, Results = diffTOT.ToArray()
                }
            });
        }