/// <summary>
        /// Reports a stack trace
        /// </summary>
        /// <param name="ct">The cancellation token</param>
        /// <param name="console"></param>
        /// <param name="processId">The process to report the stack from.</param>
        /// <param name="name">The name of process to report the stack from.</param>
        /// <param name="output">The output path for the collected trace data.</param>
        /// <param name="duration">The duration of to trace the target for. </param>
        /// <returns></returns>
        private static async Task <int> Report(CancellationToken ct, IConsole console, int processId, string name, TimeSpan duration)
        {
            string tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace";
            string tempEtlxFilename     = "";

            try
            {
                // Either processName or processId has to be specified.
                if (!string.IsNullOrEmpty(name))
                {
                    if (processId != 0)
                    {
                        Console.WriteLine("Can only specify either --name or --process-id option.");
                        return(-1);
                    }
                    processId = CommandUtils.FindProcessIdWithName(name);
                    if (processId < 0)
                    {
                        return(-1);
                    }
                }

                if (processId < 0)
                {
                    console.Error.WriteLine("Process ID should not be negative.");
                    return(-1);
                }
                else if (processId == 0)
                {
                    console.Error.WriteLine("--process-id is required");
                    return(-1);
                }


                var client    = new DiagnosticsClient(processId);
                var providers = new List <EventPipeProvider>()
                {
                    new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational)
                };

                // collect a *short* trace with stack samples
                // the hidden '--duration' flag can increase the time of this trace in case 10ms
                // is too short in a given environment, e.g., resource constrained systems
                // N.B. - This trace INCLUDES rundown.  For sufficiently large applications, it may take non-trivial time to collect
                //        the symbol data in rundown.
                using (EventPipeSession session = client.StartEventPipeSession(providers))
                    using (FileStream fs = File.OpenWrite(tempNetTraceFilename))
                    {
                        Task copyTask = session.EventStream.CopyToAsync(fs);
                        await Task.Delay(duration);

                        session.Stop();

                        // check if rundown is taking more than 5 seconds and add comment to report
                        Task timeoutTask   = Task.Delay(TimeSpan.FromSeconds(5));
                        Task completedTask = await Task.WhenAny(copyTask, timeoutTask);

                        if (completedTask == timeoutTask)
                        {
                            console.Out.WriteLine($"# Sufficiently large applications can cause this command to take non-trivial amounts of time");
                        }
                        await copyTask;
                    }

                // using the generated trace file, symbolocate and compute stacks.
                tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename);
                using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null)
                {
                    SymbolPath = SymbolPath.MicrosoftSymbolServerPath
                })
                    using (var eventLog = new TraceLog(tempEtlxFilename))
                    {
                        var stackSource = new MutableTraceEventStackSource(eventLog)
                        {
                            OnlyManagedCodeStacks = true
                        };

                        var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader);
                        computer.GenerateThreadTimeStacks(stackSource);

                        var samplesForThread = new Dictionary <int, List <StackSourceSample> >();

                        stackSource.ForEach((sample) =>
                        {
                            var stackIndex = sample.StackIndex;
                            while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread ("))
                            {
                                stackIndex = stackSource.GetCallerIndex(stackIndex);
                            }

                            // long form for: int.Parse(threadFrame["Thread (".Length..^1)])
                            // Thread id is in the frame name as "Thread (<ID>)"
                            string template    = "Thread (";
                            string threadFrame = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false);
                            int threadId       = int.Parse(threadFrame.Substring(template.Length, threadFrame.Length - (template.Length + 1)));

                            if (samplesForThread.TryGetValue(threadId, out var samples))
                            {
                                samples.Add(sample);
                            }
                            else
                            {
                                samplesForThread[threadId] = new List <StackSourceSample>()
                                {
                                    sample
                                };
                            }
                        });

                        // For every thread recorded in our trace, print the first stack
                        foreach (var(threadId, samples) in samplesForThread)
                        {
#if DEBUG
                            console.Out.WriteLine($"Found {samples.Count} stacks for thread 0x{threadId:X}");
#endif
                            PrintStack(console, threadId, samples[0], stackSource);
                        }
                    }
            }
            catch (Exception ex)
            {
                Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
                return(-1);
            }
            finally
            {
                if (File.Exists(tempNetTraceFilename))
                {
                    File.Delete(tempNetTraceFilename);
                }
                if (File.Exists(tempEtlxFilename))
                {
                    File.Delete(tempEtlxFilename);
                }
            }

            return(0);
        }
        //Code is inspired by https://github.com/Microsoft/perfview/blob/master/src/PerfView/PerfViewData.cs#L5719-L5944
        public IEnumerable <Metric> Parse()
        {
            using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath)))
            {
                var stackSource = new MutableTraceEventStackSource(traceLog);
                var eventSource = traceLog.Events.GetSource();

                var bdnEventsParser = new EngineEventLogParser(eventSource);

                var start = false;
                var isFirstActualStartEnd = false;

                long totalOperation         = 0;
                long countOfAllocatedObject = 0;

                bdnEventsParser.WorkloadActualStart += data =>
                {
                    if (!isFirstActualStartEnd)
                    {
                        start = true;
                    }

                    totalOperation = data.TotalOperations;
                };
                bdnEventsParser.WorkloadActualStop += data =>
                {
                    start = false;
                    isFirstActualStartEnd = true;
                };

                var heapParser = new HeapTraceProviderTraceEventParser(eventSource);
                // We index by heap address and then within the heap we remember the allocation stack
                var heaps = new Dictionary <Address, Dictionary <Address, long> >();
                Dictionary <Address, long> lastHeapAllocs = null;

                Address lastHeapHandle = 0;

                long nativeLeakSize  = 0;
                long totalAllocation = 0;

                heapParser.HeapTraceAlloc += delegate(HeapAllocTraceData data)
                {
                    if (!start)
                    {
                        return;
                    }

                    var call       = data.CallStackIndex();
                    var frameIndex = stackSource.GetCallStack(call, data);

                    if (!IsCallStackIn(frameIndex))
                    {
                        return;
                    }

                    var allocs = lastHeapAllocs;
                    if (data.HeapHandle != lastHeapHandle)
                    {
                        allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
                    }

                    allocs[data.AllocAddress] = data.AllocSize;

                    checked
                    {
                        countOfAllocatedObject++;
                        nativeLeakSize  += data.AllocSize;
                        totalAllocation += data.AllocSize;
                    }

                    bool IsCallStackIn(StackSourceCallStackIndex index)
                    {
                        while (index != StackSourceCallStackIndex.Invalid)
                        {
                            var frame = stackSource.GetFrameIndex(index);
                            var name  = stackSource.GetFrameName(frame, false);

                            if (name.StartsWith(moduleName, StringComparison.Ordinal) &&
                                name.IndexOf(functionName, StringComparison.Ordinal) > 0)
                            {
                                return(true);
                            }

                            index = stackSource.GetCallerIndex(index);
                        }

                        return(false);
                    }
                };

                heapParser.HeapTraceFree += delegate(HeapFreeTraceData data)
                {
                    if (!start)
                    {
                        return;
                    }

                    var allocs = lastHeapAllocs;
                    if (data.HeapHandle != lastHeapHandle)
                    {
                        allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
                    }

                    if (allocs.TryGetValue(data.FreeAddress, out long alloc))
                    {
                        nativeLeakSize -= alloc;

                        allocs.Remove(data.FreeAddress);
                    }
                };

                heapParser.HeapTraceReAlloc += delegate(HeapReallocTraceData data)
                {
                    if (!start)
                    {
                        return;
                    }
                    // Reallocs that actually move stuff will cause a Alloc and delete event
                    // so there is nothing to do for those events. But when the address is
                    // the same we need to resize.
                    if (data.OldAllocAddress != data.NewAllocAddress)
                    {
                        return;
                    }

                    var allocs = lastHeapAllocs;
                    if (data.HeapHandle != lastHeapHandle)
                    {
                        allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
                    }

                    if (allocs.TryGetValue(data.OldAllocAddress, out long alloc))
                    {
                        // Free
                        nativeLeakSize -= alloc;

                        allocs.Remove(data.OldAllocAddress);

                        // Alloc
                        allocs[data.NewAllocAddress] = data.NewAllocSize;

                        checked
                        {
                            nativeLeakSize += data.NewAllocSize;
                        }
                    }
                };

                heapParser.HeapTraceDestroy += delegate(HeapTraceData data)
                {
                    if (!start)
                    {
                        return;
                    }

                    // Heap is dieing, kill all objects in it.
                    var allocs = lastHeapAllocs;
                    if (data.HeapHandle != lastHeapHandle)
                    {
                        allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
                    }

                    foreach (var alloc in allocs.Values)
                    {
                        nativeLeakSize -= alloc;
                    }
                };

                eventSource.Process();

                logger.WriteLine();
                logger.WriteLineHeader(LogSeparator);
                logger.WriteLineInfo($"{benchmarkCase.DisplayInfo}");
                logger.WriteLineHeader(LogSeparator);

                if (totalOperation == 0)
                {
                    logger.WriteLine($"Something went wrong. The trace file {etlFilePath} does not contain BenchmarkDotNet engine events.");
                    yield break;
                }

                var memoryAllocatedPerOperation = totalAllocation / totalOperation;
                var memoryLeakPerOperation      = nativeLeakSize / totalOperation;

                logger.WriteLine($"Native memory allocated per single operation: {SizeValue.FromBytes(memoryAllocatedPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
                logger.WriteLine($"Count of allocated object: {countOfAllocatedObject / totalOperation}");

                if (nativeLeakSize != 0)
                {
                    logger.WriteLine($"Native memory leak per single operation: {SizeValue.FromBytes(memoryLeakPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
                }

                var heapInfoList = heaps.Select(h => new { Address = h.Key, h.Value.Count, types = h.Value.Values });
                foreach (var item in heapInfoList.Where(p => p.Count > 0))
                {
                    logger.WriteLine($"Count of not deallocated object: {item.Count / totalOperation}");
                }

                yield return(new Metric(new AllocatedNativeMemoryDescriptor(), memoryAllocatedPerOperation));

                yield return(new Metric(new NativeMemoryLeakDescriptor(), memoryLeakPerOperation));
            }
        }
Ejemplo n.º 3
0
        static async Task <int> Main(string[] args)
        {
            if (args.Length == 0 || args.Length > 1 || (args.Length == 1 && _helpFlags.Contains(args[0])))
            {
                PrintUsage();
                return(-1);
            }

            var pid = int.Parse(args[0]);

            var tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace";
            var tempEtlxFilename     = "";

            try
            {
                var client    = new DiagnosticsClient(pid);
                var providers = new List <EventPipeProvider>()
                {
                    new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational)
                };

                using (EventPipeSession session = client.StartEventPipeSession(providers))
                    using (FileStream fs = File.OpenWrite(tempNetTraceFilename))
                    {
                        Task copyTask = session.EventStream.CopyToAsync(fs);
                        await Task.Delay(10);

                        session.Stop();
                        await copyTask;
                    }

                tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename);
                using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null)
                {
                    SymbolPath = SymbolPath.MicrosoftSymbolServerPath
                })
                    using (var eventLog = new TraceLog(tempEtlxFilename))
                    {
                        var stackSource = new MutableTraceEventStackSource(eventLog)
                        {
                            OnlyManagedCodeStacks = true
                        };

                        var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader);
                        computer.GenerateThreadTimeStacks(stackSource);

                        var samplesForThread = new Dictionary <string, List <StackSourceSample> >();

                        stackSource.ForEach((sample) =>
                        {
                            var stackIndex = sample.StackIndex;
                            while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread ("))
                            {
                                stackIndex = stackSource.GetCallerIndex(stackIndex);
                            }

                            var threadName = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false);
                            if (samplesForThread.TryGetValue(threadName, out var samples))
                            {
                                samples.Add(sample);
                            }
                            else
                            {
                                samplesForThread[threadName] = new List <StackSourceSample>()
                                {
                                    sample
                                };
                            }
                        });

                        foreach (var(threadName, samples) in samplesForThread)
                        {
#if DEBUG
                            Console.WriteLine($"Found {samples.Count} stacks for thread {threadName}");
#endif
                            PrintStack(threadName, samples[0], stackSource);
                        }
                    }
                return(0);
            }
            catch (System.Exception e)
            {
                Console.WriteLine(e);
                return(-1);
            }
            finally
            {
                if (File.Exists(tempNetTraceFilename))
                {
                    File.Delete(tempNetTraceFilename);
                }
                if (File.Exists(tempEtlxFilename))
                {
                    File.Delete(tempEtlxFilename);
                }
            }
        }
Ejemplo n.º 4
0
        /// <summary>
        /// Reads trace and prints managed stacks
        /// </summary>
        /// <param name="console"></param>
        /// <param name="traceFile"></param>
        /// <returns>Returns 0 for success and 1 for failure</returns>
        /// <remarks>This code is adopted from josalem code https://github.com/josalem/DotStack </remarks>
        public static int Analyze(IConsole console, FileInfo traceFile)
        {
            if (string.IsNullOrEmpty(traceFile.FullName))
            {
                Console.ForegroundColor = ConsoleColor.Red;
                console.Error.WriteLine("-f [process-id] Process ID is required.");
                Console.ResetColor();
                return(1);
            }

            Console.WriteLine("[Trace analysis started...]\n");

            // Both the namespaces have TraceLog, here we use Microsoft.Diagnostics.Tracing.Etlx.TraceLog;
            // The following line creates a etlx file and then does analysis using that.
            string tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(traceFile.FullName);

            using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null)
            {
                SymbolPath = SymbolPath.MicrosoftSymbolServerPath
            })

                using (var eventLog = new TraceLog(tempEtlxFilename))
                {
                    var stackSource = new MutableTraceEventStackSource(eventLog)
                    {
                        OnlyManagedCodeStacks = true
                    };

                    var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader);
                    computer.GenerateThreadTimeStacks(stackSource);

                    var samplesForThread = new Dictionary <string, List <StackSourceSample> >();

                    stackSource.ForEach((sample) =>
                    {
                        var stackIndex = sample.StackIndex;
                        while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread ("))
                        {
                            stackIndex = stackSource.GetCallerIndex(stackIndex);
                        }

                        var threadName = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false);
                        if (samplesForThread.TryGetValue(threadName, out var samples))
                        {
                            samples.Add(sample);
                        }
                        else
                        {
                            samplesForThread[threadName] = new List <StackSourceSample>()
                            {
                                sample
                            };
                        }
                    });

                    foreach (var(threadName, samples) in samplesForThread)
                    {
                        PrintStack(threadName, samples[0], stackSource);
                    }
                }

            Console.WriteLine("\n[Trace analysis completed...]");
            return(0);
        }