PERF: Adding various logging calls related to startup performance

--HG--
branch : 1.x
This commit is contained in:
Renaud Paquay
2011-05-12 10:47:08 -07:00
parent 03ddb80526
commit 130f9d3c80
7 changed files with 76 additions and 50 deletions

View File

@@ -72,10 +72,13 @@ namespace Orchard.Data {
NHibernate.Cfg.Environment.UseReflectionOptimizer = false;
Configuration config = GetConfiguration();
return config.BuildSessionFactory();
var result = config.BuildSessionFactory();
Logger.Debug("Done building session factory");
return result;
}
private Configuration BuildConfiguration() {
Logger.Debug("Building configuration");
var parameters = GetSessionFactoryParameters();
var config = _sessionConfigurationCache.GetConfiguration(() =>
@@ -100,6 +103,7 @@ namespace Orchard.Data {
}
#endregion
Logger.Debug("Done Building configuration");
return config;
}

View File

@@ -59,6 +59,7 @@ namespace Orchard.Environment {
void IOrchardHost.Initialize() {
Logger.Information("Initializing");
BuildCurrent();
Logger.Information("Initialized");
}
void IOrchardHost.ReloadExtensions() {
@@ -98,19 +99,26 @@ namespace Orchard.Environment {
}
IEnumerable<ShellContext> CreateAndActivate() {
Logger.Information("Start creation of shells");
IEnumerable<ShellContext> result;
var allSettings = _shellSettingsManager.LoadSettings();
if (allSettings.Any()) {
return allSettings.Select(
result = allSettings.Select(
settings => {
var context = CreateShellContext(settings);
ActivateShell(context);
return context;
});
}
else {
var setupContext = CreateSetupContext();
ActivateShell(setupContext);
result = new[] {setupContext};
}
var setupContext = CreateSetupContext();
ActivateShell(setupContext);
return new[] { setupContext };
Logger.Information("Done creating shells");
return result;
}
private void ActivateShell(ShellContext context) {

View File

@@ -299,6 +299,7 @@ namespace Orchard.Environment.Extensions {
}
public void MonitorExtensions(Action<IVolatileToken> monitor) {
Logger.Information("Start monitoring extension files...");
// Monitor add/remove of any module/theme
monitor(_virtualPathMonitor.WhenPathChanges("~/Modules"));
monitor(_virtualPathMonitor.WhenPathChanges("~/Themes"));
@@ -310,6 +311,7 @@ namespace Orchard.Environment.Extensions {
loader.Monitor(extension, monitor);
}
}
Logger.Information("Done monitoring extension files...");
}
}
}

View File

@@ -2,7 +2,6 @@ using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Text.RegularExpressions;
using Orchard.Caching;
using Orchard.Environment.Extensions.Models;
using Orchard.FileSystems.WebSite;
@@ -39,48 +38,49 @@ namespace Orchard.Environment.Extensions.Folders {
public ILogger Logger { get; set; }
public IEnumerable<ExtensionDescriptor> AvailableExtensions() {
var list = new List<ExtensionDescriptor>();
foreach (var locationPath in _paths) {
var path = locationPath;
var subList = _cacheManager.Get(locationPath, ctx => {
return _paths
.SelectMany(path => _cacheManager.Get(path, ctx => {
ctx.Monitor(_webSiteFolder.WhenPathChanges(ctx.Key));
var subfolderPaths = _webSiteFolder.ListDirectories(ctx.Key);
var localList = new List<ExtensionDescriptor>();
foreach (var subfolderPath in subfolderPaths) {
var extensionId = Path.GetFileName(subfolderPath.TrimEnd('/', '\\'));
var manifestPath = Path.Combine(subfolderPath, _manifestName);
try {
var descriptor = GetExtensionDescriptor(path, extensionId, manifestPath);
return AvailableExtensionsInFolder(ctx.Key);
}))
.ToList();
}
if (descriptor == null)
continue;
private List<ExtensionDescriptor> AvailableExtensionsInFolder(string path) {
Logger.Information("Start looking for extensions in '{0}'...", path);
var subfolderPaths = _webSiteFolder.ListDirectories(path);
var localList = new List<ExtensionDescriptor>();
foreach (var subfolderPath in subfolderPaths) {
var extensionId = Path.GetFileName(subfolderPath.TrimEnd('/', '\\'));
var manifestPath = Path.Combine(subfolderPath, _manifestName);
try {
var descriptor = GetExtensionDescriptor(path, extensionId, manifestPath);
if (descriptor.Path != null && !descriptor.Path.IsValidUrlSegment()) {
Logger.Error("The module '{0}' could not be loaded because it has an invalid Path ({1}). It was ignored. The Path if specified must be a valid URL segment. The best bet is to stick with letters and numbers with no spaces.",
extensionId,
descriptor.Path);
continue;
}
if (descriptor == null)
continue;
if (descriptor.Path == null) {
descriptor.Path = descriptor.Name.IsValidUrlSegment()
? descriptor.Name
: descriptor.Id;
}
localList.Add(descriptor);
}
catch (Exception ex) {
// Ignore invalid module manifests
Logger.Error(ex, "The module '{0}' could not be loaded. It was ignored.", extensionId);
}
if (descriptor.Path != null && !descriptor.Path.IsValidUrlSegment()) {
Logger.Error("The module '{0}' could not be loaded because it has an invalid Path ({1}). It was ignored. The Path if specified must be a valid URL segment. The best bet is to stick with letters and numbers with no spaces.",
extensionId,
descriptor.Path);
continue;
}
return localList;
});
list.AddRange(subList);
}
return list;
if (descriptor.Path == null) {
descriptor.Path = descriptor.Name.IsValidUrlSegment()
? descriptor.Name
: descriptor.Id;
}
localList.Add(descriptor);
}
catch (Exception ex) {
// Ignore invalid module manifests
Logger.Error(ex, "The module '{0}' could not be loaded. It was ignored.", extensionId);
}
}
Logger.Information("Done looking for extensions in '{0}': {1}", path, string.Join(", ", localList.Select(d => d.Id)));
return localList;
}
public static ExtensionDescriptor GetDescriptorForExtension(string locationPath, string extensionId, string extensionType, string manifestText) {

View File

@@ -74,7 +74,7 @@ namespace Orchard.Environment.Extensions.Loaders {
string projectPath = GetProjectPath(descriptor);
if (projectPath != null) {
foreach (var path in GetDependencies(projectPath)) {
Logger.Information("Monitoring virtual path \"{0}\"", path);
Logger.Debug("Monitoring virtual path \"{0}\"", path);
var token = _virtualPathMonitor.WhenPathChanges(path);
monitor(token);
@@ -91,7 +91,7 @@ namespace Orchard.Environment.Extensions.Loaders {
public override void ExtensionActivated(ExtensionLoadingContext ctx, ExtensionDescriptor extension) {
if (_reloadWorkaround.AppDomainRestartNeeded) {
Logger.Information("ExtensionActivated: Module \"{0}\" has changed, forcing AppDomain restart", extension.Id);
Logger.Debug("ExtensionActivated: Module \"{0}\" has changed, forcing AppDomain restart", extension.Id);
ctx.RestartAppDomain = _reloadWorkaround.AppDomainRestartNeeded;
}
}
@@ -128,7 +128,7 @@ namespace Orchard.Environment.Extensions.Loaders {
// We need to restart the appDomain if the assembly is loaded
if (_hostEnvironment.IsAssemblyLoaded(referenceEntry.Name)) {
Logger.Information("ReferenceActivated: Reference \"{0}\" is activated with newer file and its assembly is loaded, forcing AppDomain restart", referenceEntry.Name);
Logger.Debug("ReferenceActivated: Reference \"{0}\" is activated with newer file and its assembly is loaded, forcing AppDomain restart", referenceEntry.Name);
context.RestartAppDomain = true;
}
}
@@ -167,11 +167,13 @@ namespace Orchard.Environment.Extensions.Loaders {
if (projectPath == null)
return null;
Logger.Information("Start loading dynamic extension \"{0}\"", descriptor.Name);
var assembly = _buildManager.GetCompiledAssembly(projectPath);
if (assembly == null)
return null;
Logger.Information("Loaded dynamic extension \"{0}\": assembly name=\"{1}\"", descriptor.Name, assembly.FullName);
Logger.Information("Done loading dynamic extension \"{0}\": assembly name=\"{1}\"", descriptor.Name, assembly.FullName);
return new ExtensionEntry {
Descriptor = descriptor,

View File

@@ -128,7 +128,7 @@ namespace Orchard.Environment.Extensions.Loaders {
// If the assembly exists, monitor it
string assemblyPath = GetAssemblyPath(descriptor);
if (assemblyPath != null) {
Logger.Information("Monitoring virtual path \"{0}\"", assemblyPath);
Logger.Debug("Monitoring virtual path \"{0}\"", assemblyPath);
monitor(_virtualPathMonitor.WhenPathChanges(assemblyPath));
return;
}
@@ -138,7 +138,7 @@ namespace Orchard.Environment.Extensions.Loaders {
// detect that as a change of configuration.
var assemblyDirectory = _virtualPathProvider.Combine(descriptor.Location, descriptor.Id, "bin");
if (_virtualPathProvider.DirectoryExists(assemblyDirectory)) {
Logger.Information("Monitoring virtual path \"{0}\"", assemblyDirectory);
Logger.Debug("Monitoring virtual path \"{0}\"", assemblyDirectory);
monitor(_virtualPathMonitor.WhenPathChanges(assemblyDirectory));
}
}
@@ -196,11 +196,13 @@ namespace Orchard.Environment.Extensions.Loaders {
if (Disabled)
return null;
Logger.Information("Start loading pre-compiled extension \"{0}\"", descriptor.Name);
var assembly = _assemblyProbingFolder.LoadAssembly(descriptor.Id);
if (assembly == null)
return null;
Logger.Information("Loaded pre-compiled extension \"{0}\": assembly name=\"{1}\"", descriptor.Name, assembly.FullName);
Logger.Information("Done loading pre-compiled extension \"{0}\": assembly name=\"{1}\"", descriptor.Name, assembly.FullName);
return new ExtensionEntry {
Descriptor = descriptor,

View File

@@ -11,6 +11,7 @@ using Orchard.Environment.Descriptor.Models;
using Orchard.Environment.Extensions;
using Orchard.Environment.Extensions.Models;
using Orchard.Environment.ShellBuilders.Models;
using Orchard.Logging;
namespace Orchard.Environment.ShellBuilders {
/// <summary>
@@ -31,7 +32,11 @@ namespace Orchard.Environment.ShellBuilders {
_extensionManager = extensionManager;
}
public ILogger Logger { get; set; }
public ShellBlueprint Compose(ShellSettings settings, ShellDescriptor descriptor) {
Logger.Debug("Composing blueprint");
var enabledFeatures = _extensionManager.EnabledFeatures(descriptor);
var features = _extensionManager.LoadFeatures(enabledFeatures);
@@ -43,13 +48,16 @@ namespace Orchard.Environment.ShellBuilders {
var controllers = BuildBlueprint(features, IsController, BuildController);
var records = BuildBlueprint(features, IsRecord, (t, f) => BuildRecord(t, f, settings));
return new ShellBlueprint {
var result = new ShellBlueprint {
Settings = settings,
Descriptor = descriptor,
Dependencies = dependencies.Concat(modules).ToArray(),
Controllers = controllers,
Records = records,
};
Logger.Debug("Done composing blueprint");
return result;
}
private static IEnumerable<Feature> BuiltinFeatures() {