From 733de4a1669f3806964d93d657cd2ee729833199 Mon Sep 17 00:00:00 2001 From: Louis DeJardin Date: Tue, 30 Nov 2010 13:46:13 -0800 Subject: [PATCH] Adding a component to experimental module to capture ioc costing --HG-- branch : perf extra : rebase_source : aa936df6717501a84fafce41f8130ced8217fa42 --- .../profiling-setup-commands.txt | 2 +- .../Orchard.Experimental/ContainerSpy.cs | 311 ++++++++++++++++++ .../Controllers/HomeController.cs | 11 +- .../Orchard.Experimental.csproj | 2 + 4 files changed, 324 insertions(+), 2 deletions(-) create mode 100644 src/Orchard.Web/Modules/Orchard.Experimental/ContainerSpy.cs diff --git a/src/Orchard.Profile/profiling-setup-commands.txt b/src/Orchard.Profile/profiling-setup-commands.txt index 5f23eb33a..0ce689258 100644 --- a/src/Orchard.Profile/profiling-setup-commands.txt +++ b/src/Orchard.Profile/profiling-setup-commands.txt @@ -1 +1 @@ -setup /SiteName:Profiling /AdminUsername:admin /AdminPassword:profiling-secret /DatabaseProvider:SqlCe /EnabledFeatures:Profiling,Orchard.Framework,Routable,Common,Dashboard,Feeds,Orchard.PublishLater,HomePage,Contents,Navigation,Reports,Scheduling,Indexing,Settings,Localization,XmlRpc,Orchard.Users,Orchard.Roles,TinyMce,Orchard.Themes,Orchard.MultiTenancy,Orchard.Blogs,Orchard.Comments,Orchard.Modules,Orchard.Scripting,Orchard.Scripting.Lightweight,Orchard.Widgets,Orchard.Media,Orchard.Tags,Orchard.Experimental +setup /SiteName:Profiling /AdminUsername:admin /AdminPassword:profiling-secret /DatabaseProvider:SQLServer /DatabaseConnectionString:"Data Source=.;Initial Catalog=Orchard;Integrated Security=True" /EnabledFeatures:Profiling,Orchard.Framework,Common,Containers,Contents,Dashboard,Feeds,HomePage,Navigation,Reports,Routable,Scheduling,Settings,Shapes,Orchard.PublishLater,Orchard.Blogs,Orchard.Comments,Orchard.ContentTypes,Orchard.jQuery,Orchard.Lists,Orchard.Media,Orchard.Modules,Orchard.Pages,Orchard.Roles,Orchard.Tags,Orchard.Themes,Orchard.Users,Orchard.Scripting,Orchard.Scripting.Lightweight,Orchard.Widgets,TinyMce,TheThemeMachine diff --git a/src/Orchard.Web/Modules/Orchard.Experimental/ContainerSpy.cs b/src/Orchard.Web/Modules/Orchard.Experimental/ContainerSpy.cs new file mode 100644 index 000000000..1dc981610 --- /dev/null +++ b/src/Orchard.Web/Modules/Orchard.Experimental/ContainerSpy.cs @@ -0,0 +1,311 @@ +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Xml.Linq; +using Autofac; +using Autofac.Core; + +namespace Orchard.Experimental { + // note - not thread aware + + public interface IContainerSpyOutput { + void Write(XElement target); + } + + public class ContainerSpy : Module, IDependency { + private readonly ConcurrentDictionary _contexts = new ConcurrentDictionary(); + + protected override void Load(ContainerBuilder builder) { + builder.RegisterInstance(new Output(_contexts)).As(); + + //builder.RegisterCallback(cr => cr.Registered += (_, registered) => { + // registered.ComponentRegistration.Preparing += (__, preparing) => Preparing(GetContext(_contexts), preparing); + // registered.ComponentRegistration.Activating += (__, activating) => Activating(GetContext(_contexts), activating); + // registered.ComponentRegistration.Activated += (__, activated) => Activated(GetContext(_contexts), activated); + //}); + } + + protected override void AttachToComponentRegistration(IComponentRegistry componentRegistry, IComponentRegistration registration) { + registration.Preparing += (__, preparing) => Preparing(GetContext(_contexts), preparing); + registration.Activating += (__, activating) => Activating(GetContext(_contexts), activating); + registration.Activated += (__, activated) => Activated(GetContext(_contexts), activated); + } + + static ThreadContext GetContext(ConcurrentDictionary nodes) { + return nodes.GetOrAdd(Thread.CurrentThread.ManagedThreadId, _ => { + var tc = new ThreadContext(); + tc.Root = tc.Clock = tc.Chain = tc.Focus = new Node(tc); + return tc; + }); + } + + private static void Preparing(ThreadContext context, PreparingEventArgs preparing) { + context.Focus = context.Focus.Preparing(preparing); + context.Chain = context.Chain.Link(preparing, context.Focus); + context.Clock = MoveClock(context.Clock, context.Focus); + } + + private static void Activating(ThreadContext context, ActivatingEventArgs activating) { + context.Focus = context.Focus.Activating(activating); + } + + private static void Activated(ThreadContext context, ActivatedEventArgs activated) { + context.Clock = MoveClock(context.Clock, context.Root); + context.Chain = context.Chain.Activated(activated); + } + + private static Node MoveClock(Node currentClock, Node newClock) { + var scanEnable = newClock; + while (scanEnable.Hot == false) { + scanEnable.Hot = true; + scanEnable = scanEnable._parent; + } + + var scanDisable = currentClock; + while (scanDisable != scanEnable) { + scanDisable.Hot = false; + scanDisable = scanDisable._parent; + } + return newClock; + } + + + + + class ThreadContext { + public Node Root { get; set; } + public Node Focus { get; set; } + public Node Chain { get; set; } + public Node Clock { get; set; } + } + + class Node { + private readonly ThreadContext _threadContext; + public Node _parent; + private Node _chain; + public readonly IComponentRegistration _component; + public readonly IDictionary _children = new Dictionary(); + + public int _preparingCount; + public int _activatingCount; + public int _activatedCount; + + private bool _hot; + readonly Stopwatch _stopwatch = new Stopwatch(); + private long _time; + + public Node(ThreadContext threadContext) { + _threadContext = threadContext; + _hot = true; // meta-nodes are hot to avoid any timing + } + + public Node(Node parent, IComponentRegistration component) { + _threadContext = parent._threadContext; + _parent = parent; + _component = component; + } + + public bool Hot { + get { + return _hot; + } + set { + if (_hot == value) + return; + + _hot = value; + if (_hot) { + _stopwatch.Start(); + } + else { + _stopwatch.Stop(); + } + } + } + + public long Time { + get { return _time+ _stopwatch.ElapsedTicks * 1000000 / Stopwatch.Frequency; } + } + public void AddTime(long time) { _time += time; } + + public override string ToString() { + if (_component == null) + return "root"; + + return _component.ToString(); + } + + + private static void TraceMessage(string format, IComponentRegistration component) { + //Trace.WriteLine(Message(format, component)); + } + private static string Message(string format, IComponentRegistration component) { + return string.Format(format, component.Id, string.Join(",", component.Services), Thread.CurrentThread.ManagedThreadId); + } + + public Node Preparing(PreparingEventArgs e) { + // move focus down a level on the tree + // add a link in chain + Node child; + lock (_children) { + if (!_children.TryGetValue(e.Component.Id, out child)) { + child = new Node(this, e.Component); + _children[e.Component.Id] = child; + } + } + + TraceMessage("Preparing[{2}] {0} {1}", e.Component); + Interlocked.Increment(ref child._preparingCount); + return child; + } + + public Node Link(PreparingEventArgs e, Node focus) { + if (focus._chain != null) { + TraceMessage("REACTIVATED: Preparing[{2}] {0} {1}", e.Component); + } + focus._chain = this; + return focus; + } + + public Node Activating(ActivatingEventArgs e) { + // move focus up a level on the tree + if (_component == null) { + TraceMessage("UNMATCHED: Activating[{2}] {0} {1}", e.Component); + return this; + } + + if (_component.Id != e.Component.Id) { + TraceMessage("MISSING: Activating[{2}] {0} {1}", _component); + return _parent.Activating(e); + } + + TraceMessage("Activating[{2}] {0} {1}", e.Component); + Interlocked.Increment(ref _activatingCount); + return _parent; + } + + public Node Activated(ActivatedEventArgs e) { + // remove a link in chain + if (_component == null) { + TraceMessage("UNMATCHED: Activated[{2}] {0} {1}", e.Component); + return this; + } + + if (_component.Id != e.Component.Id) { + _chain = _chain.Activated(e); + return this; + } + + TraceMessage("Activated[{2}] {0} {1}", e.Component); + Interlocked.Increment(ref _activatedCount); + var chain = _chain; + _chain = null; + return chain; + } + + } + + class Output : IContainerSpyOutput { + private readonly ConcurrentDictionary _root; + + public Output(ConcurrentDictionary root) { + _root = root; + } + + public void Write(XElement target) { + var elts = _root.Values + .Select(entry => Write(entry.Root)) + .OrderByDescending(GetWeight) + .ToArray(); + + var merged = _root.Values.Aggregate(new Node(null), (a, n) => Merge(a, n.Root)); + + var totals = new TotalVisitor(); + totals.Visit(merged); + + target.Add(Write(merged)); + target.Add(Write(totals._totals)); + target.Add(elts); + } + + private class TotalVisitor { + public Node _totals = new Node(null); + + public void Visit(Node source) { + foreach (var child in source._children) { + Visit(child.Key, child.Value); + } + } + + public void Visit(Guid key, Node source) { + Node target; + if (!_totals._children.TryGetValue(key, out target)) { + target = new Node(_totals, source._component); + _totals._children[key] = target; + } + target._preparingCount += source._preparingCount; + target._activatingCount += source._activatingCount; + target._activatedCount += source._activatedCount; + foreach (var child in source._children) { + Visit(child.Key, child.Value); + } + } + + } + + private static Node Merge(Node target, Node source) { + target._preparingCount += source._preparingCount; + target._activatingCount += source._activatingCount; + target._activatedCount += source._activatedCount; + target.AddTime(source.Time); + foreach (var sourceChild in source._children) { + Node targetChild; + if (!target._children.TryGetValue(sourceChild.Key, out targetChild)) { + targetChild = new Node(target, sourceChild.Value._component); + target._children[sourceChild.Key] = targetChild; + } + Merge(targetChild, sourceChild.Value); + } + return target; + } + + private XElement Write(Node node) { + var elt = new XElement( + "Component", + new XAttribute("services", node._component != null ? string.Join(",", node._component.Services) : "root"), + new XAttribute("preparing", node._preparingCount), + new XAttribute("activating", node._activatingCount), + new XAttribute("activated", node._activatedCount)); + + lock (node._children) { + var elts = node._children.Values + .Select(Write) + .OrderByDescending(GetMicrosecondInclusive) + .ToArray(); + elt.Add(elts); + + var weight = elts.Aggregate(node._preparingCount, (a, e) => a + GetWeight(e)); + + elt.SetAttributeValue("weight", weight); + elt.SetAttributeValue("usinc", node.Time); + if (weight != 0) + elt.SetAttributeValue("usincper", node.Time / weight); + } + + return elt; + } + + private static long GetMicrosecondInclusive(XElement elt) { + var attr = elt.Attribute("usinc"); + return attr == null ? 0 : long.Parse(attr.Value); + } + private static int GetWeight(XElement elt) { + var attr = elt.Attribute("weight"); + return attr == null ? 0 : int.Parse(attr.Value); + } + } + } +} diff --git a/src/Orchard.Web/Modules/Orchard.Experimental/Controllers/HomeController.cs b/src/Orchard.Web/Modules/Orchard.Experimental/Controllers/HomeController.cs index 96e7eaef2..c4d0a94f3 100644 --- a/src/Orchard.Web/Modules/Orchard.Experimental/Controllers/HomeController.cs +++ b/src/Orchard.Web/Modules/Orchard.Experimental/Controllers/HomeController.cs @@ -1,6 +1,7 @@ using System; using System.Web; using System.Web.Mvc; +using System.Xml.Linq; using Orchard.Experimental.Models; using Orchard.DisplayManagement; using Orchard.Localization; @@ -13,9 +14,11 @@ namespace Orchard.Experimental.Controllers { [Themed, Admin] public class HomeController : Controller { private readonly INotifier _notifier; + private readonly IContainerSpyOutput _containerSpyOutput; - public HomeController(INotifier notifier, IShapeFactory shapeFactory) { + public HomeController(INotifier notifier, IShapeFactory shapeFactory, IContainerSpyOutput containerSpyOutput) { _notifier = notifier; + _containerSpyOutput = containerSpyOutput; T = NullLocalizer.Instance; Shape = shapeFactory; } @@ -107,6 +110,12 @@ namespace Orchard.Experimental.Controllers { public static string Break(dynamic view) { return view.Model.Box.Title; } + + public ActionResult ContainerData() { + var root = new XElement("root"); + _containerSpyOutput.Write(root); + return Content(root.ToString(), "text/xml"); + } } } diff --git a/src/Orchard.Web/Modules/Orchard.Experimental/Orchard.Experimental.csproj b/src/Orchard.Web/Modules/Orchard.Experimental/Orchard.Experimental.csproj index 199efe302..227310757 100644 --- a/src/Orchard.Web/Modules/Orchard.Experimental/Orchard.Experimental.csproj +++ b/src/Orchard.Web/Modules/Orchard.Experimental/Orchard.Experimental.csproj @@ -34,6 +34,7 @@ 4 + ..\..\..\..\lib\nhprof\HibernatingRhinos.Profiler.Appender.dll @@ -53,6 +54,7 @@ +