EventSystem High CPU Utilization & Delay in Functionality

Question

In SDL Tridion 9.1, we suppose to write Anguilla (JS) Event Handling for Tracking all the Event Logs (like Component checkin, checkout, delete, save, Page publish, unpublish...etc).

We upgraded to Tridion 9.6, New UI is not supporting for Custom JS Event handling. if we use Classic view, we can able to trigger the Event logs. So, few logs are missing, if anyone used NewUI.

We changed approach to Handling events Using TOM.NET approach using This link.

if 10+ Users are Accessing the CMS, CPU went high and impacting the Performance and observed delay on functionality like publishing page, Publishing Component..etc.

Here is my Code Sample, Can you please help me How to capture the logs complete Asynchronously with out impact on performance.?

using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using Tridion.ContentManager;
using Tridion.ContentManager.ContentManagement;
using Tridion.ContentManager.Extensibility;
using Tridion.ContentManager.Extensibility.Events;
using Tridion.Logging;

namespace Automation.EventSystem
{
    [TcmExtension("AutomationExtension")]
    public class EventsHandler : TcmExtension, IDisposable
    {
        private readonly List<EventSubscription> eventSubscriptions = new List<EventSubscription>();
        public EventsHandler()
        {
            if (Utility.EventConfig.EnableEventLogging)
            {
                this.eventSubscriptions.Add(EventSystem.Subscribe<IdentifiableObject, TcmEventArgs>(LogStart, EventPhases.Initiated));
                this.eventSubscriptions.Add(EventSystem.SubscribeAsync<IdentifiableObject, TcmEventArgs>(LogEvent, EventPhases.TransactionCommitted | EventPhases.TransactionAborted | EventPhases.TransactionInDoubt | EventPhases.Initiated));
            }
        }
        private static void LogStart(IdentifiableObject subject, TcmEventArgs tcmEventArgs, EventPhases phase)
        {
            try
            {
                if (tcmEventArgs.ContextVariables.ContainsKey("InitiatedTicks")) return;
                tcmEventArgs.ContextVariables.Add("InitiatedTicks", DateTime.Now.Ticks);
            }
            catch (Exception e) { }
        }
        private void LogEvent(IdentifiableObject subject, TcmEventArgs tcmEventArgs, EventPhases phase)
        {
            try
            {
                var logtxt = string.Format(Constants.Common.EventLogText
                                                        , DateTime.UtcNow
                                                        , System.Threading.Thread.CurrentThread.ManagedThreadId
                                                        , eventname
                                                        , eventfamily
                                                        , subject.Id.ToString()
                                                        , subject.Title
                                                        , subject.GetType().Name
                                                        , subject.Session.User.Id.ToString()
                                                        , subject.Session.User.Title
                                                        , Environment.MachineName
                                                        , phase.ToString()
                                                        , Environment.NewLine);

                File.AppendAllText(string.Format(Utility.EventConfig.EventLogFilePath, filename), logtxt);
            }
            catch (Exception e) { }
        }
    }
    public void Dispose()
    {
        this.Dispose(true);
        GC.SuppressFinalize(this);
    }
    protected virtual void Dispose(bool disposing)
    {
        if (disposing)
        {
            foreach (EventSubscription subscription in this.eventSubscriptions)
            {
                subscription.Unsubscribe();
            }
        }
    }
}

Answer 1

This is odd. I would try to validate that events are indeed running asynchronously (a quick scan through your code suggests this is the case, but never assume anything), and probably investigate better ways to log than writing to a text file, perhaps with frameworks such as log4net or whatever the cool kids use nowadays.

Last time I worked in anything remotely like this we used MongoDB and had no (visible) performance issues (https://github.com/NunoLinhares/tridion-2011-reporting/blob/master/Tridion.Extensions.Reporting/EventSystem/TrackEverything.cs#L32)

Good luck.

Answer 2

I guess you are using a mix of synchronous and asynchronous event subscriptions because you want to keep track of time spent?

But note that you're currently setting the "InitiatedTicks" context variable, but not actually using it. Which makes sense: if you really want to keep track of time spent, you should use synchronous events, but if you want to minimize impact on performance you should use asynchronous events (and forget about tracking time spent).

For tracking time spent, you can use the TCM tracing facility (Start-TcmTracing PowerShell cmdlet).