One of our clients uses Tridion 2013 SP1, and has strict audit requirements for their publishing. We need to know what is on the site at any particular point in time. The auditors might ask, for example, what the user saw if they viewed the site two weeks ago last Tuesday at 3am.
We have to track what gets published, and make sure that we have no significant performance degradation while we’re doing that. Publishing for our releases already take several hours, and we can’t extend that by any significant amount of time.
These tests let us look at different options for this timing. Once the tests have been run, we will then have a better idea of which one to implement.
All of the component changes are managed with fairly strict workflow control, but we don’t know when those components (or the pages that they are on) were published.
Tridion stores the most recent successful publish or a page, but in doing so erases any previous publish success or failure. If the page is published now then we don’t know when it was published last. It might have been 10 minutes ago, or it might have been two years ago. We certainly can’t answer the “two weeks ago last Tuesday at 3am” question.
The Requirements
What we needed was a way to track the publishing history. This should at least track the publishing successes and failures, and we could also look at the timing of the stages that the publishing moved through. (Tridion 2013 doesn’t store how long rendering took, for instance. One of the questions that we are regularly asked is how long a particular page takes to render — we have no way of knowing. By tracking the different stages, we could answer this and also determine other potential bottlenecks.)
We looked at a number of different options to test, from simple to complex, and came up with a set of items that we wanted to test for:
- No event system code whatsoever (our first baseline test)
- Event system code enabled, but no logging (our second baseline test)
- Logging to log4net
- Logging to a text file
- Logging to the Windows Event Viewer
We wanted to publish the same set of information for every test. We chose 10 pages within a single structure group, published for 290 child publications. With those 2,900 pages, and no event system code in place, a test run would take about 1/2 hour.
We needed a way to make sure that we had accurate timing. We made sure that we were the only ones using this system, and once publishing finished we looked at the first publish completion time and the last completion time.
We also restarted the tests if there were issues, like pages being stuck in a particular state for an extended period of time, to ensure that that didn’t impact the results.
We needed a way to make sure that any particular set of tests was repeatable. We decided to have all of the source code contained within the file, and used boolean variables to enable and disable sets of code. We could then re-run any test by setting a few flags, compiling, and deploying. It was easy, and it was repeatable.
Setting the configuration was as simple as:
private static bool logOnlySuccessAndFailure = false;
private static int logPropertySet = 1; // 1 = full; 2 = some; 3 = few; 4 = recent publishes
private static bool useEventSystem = true;
private static bool useLog4Net = false;
private static bool useLog4NetDebugging = false;
private static bool useLogToTextFile = true;
private static bool useLogToEventSystem = false;
private static bool debugToEventSystem = true;
private static string eventSystemSource = "PublishHistoryLogger";
private static string filePath = @"D:\PublishingHistory.txt";
private static string fileDebugPath = @"D:\Debug.log";With all of that set, we ran the code and came up with the following results:
| Event Code | log4net | Text File | Event Viewer | All Events | Elapsed Time (mins) |
| Â Yes | Â Yes | Â Yes | Â Yes | Yes | 32 |
| Â Yes | Yes | Yes | 22 | ||
| Yes | Yes | 27 | |||
| No | 19 |
Result Table Details
The “Event Code” column indicates whether or not the event system code was enabled. The most basic test determined the time difference between having an empty event handler vs. having no event handler.
The “log4net”, “Text File”, and “Event Viewer” column indicates where the results were logged to.
The “All Events” column indicates if only the publish Success and Failure events were logged, or were all publish events logged.
The “Elapsed Time” shows the number of minutes for the test. We determined that the number of minutes was a good enough resolution.
Let’s look at one more thing
The initial timing seemed really strange — the event system caused a 50% decrease in the performance. This had to be checked further. Our normal release requires several hours of publishing, with tens of thousands of pages, and had to be completed at a particular time. We couldn’t increase that by 50% without knowing more.
We restarted the servers and ran one of the tests, but this time ran it a few different times in a row and came up with:
| Event Code | log4net | Text File | Event Viewer | All Events | Elapsed Time (mins) |
| Â Yes | Â Yes | Yes | 27 | ||
| Â Yes | Yes | Yes | 17 | ||
| Yes | Yes | Yes | 17 |
We came away with a new requirement: Repeated tests. We acknowledged the first test, but seeing successive test results meant that we could basically ignore the first test. The first run, we surmised, was so that the cache could be populated. After that things used the cache and went faster.
The full set of results
Now we could look at results across all of the tests. These took a number of days to generate, when you consider how long each test took, and then resetting the environment between code changes, so through it all we made sure that we were the only people using this environment.
| Event Code | log4net | Text File | Event Viewer | All Events | Elapsed Time (mins) |
| Yes | Yes | Yes | Yes | Yes | 32 |
| Yes | Yes | Yes | 27 | ||
| Yes | Yes | 27 | |||
| No | 19 | ||||
| Yes | Yes | Yes | Yes | Yes | 26 |
| Yes | Yes | Yes | Yes | Yes | 27 |
| We standardized the configuration change method and code updates here | |||||
| Yes | Yes | 27 | |||
| Yes | Yes | 27 | |||
| Yes | Yes | 17 | |||
| Yes | Yes | 17 | |||
| Yes | Yes | Yes | 27 | ||
| Yes | Yes | Yes | 17 | ||
| Yes | Yes | Yes | 16 | ||
| No | 26 | ||||
| No | 17 | ||||
| No | 17 | ||||
| No | 17 | ||||
| No | 16 | ||||
| Yes | Yes | Yes | 27 | ||
| Yes | Yes | Yes | 17 | ||
| Yes | Yes | Yes | 17 | ||
| Yes | Yes | Yes | 16 | ||
It took some time, but we developed a repeatable process that showed the impact of the logging the events with the publishing system. We had repeated tests, with known configurations, and documented results.
Now that we have run various cycles of this publishing, we are able to draw some conclusions. We have a repeatable test, we can show the code, and others can run the tests.
We have shown that there is no significant degradation to the publishing, whether or not we log the publishing events.
We have also shown that there is no significant difference between logging one type of publish event (success or failure) vs. logging all types of publish events.
With this we are able to declare this experiment a success, and move ahead with the rest of the project to get this implemented.
The code that we used is included here:
namespace ContentBloom.Tridion.EventSystem.PublishHistoryLogger
{
[TcmExtension("Publish Transaction Events")]
public class PublishHistoryLogger : TcmExtension
{
private static readonly ILog log = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
private static bool logOnlySuccessAndFailure = false;
private static int logPropertySet = 1; // 1 = full; 2 = some; 3 = few
private static bool useEventSystem = true;
private static bool useLog4Net = false;
private static bool useLogToTextFile = true;
private static bool useLogToEventSystem = false;
private static bool debugToEventSystem = true;
private static string eventSystemSource = "PublishHistoryLogger";
private static string filePath = @"D:\PublishingHistory.txt";
private static string fileDebugPath = @"D:\Debug.log";
private static PublishTransactionsFilter pf;
public PublishHistoryLogger()
{
if (debugToEventSystem)
{
// Write to the Windows Event System
}
// Set up using log4net
if (useLog4Net)
{
if (debugToEventSystem)
{
// Write to the Windows Event System
}
// Initialize log4net
}
// Set up logging to the text file
if (useLogToTextFile)
{
if (debugToEventSystem)
{
// Write to the Windows Event System
}
// Initialize writing to the text file
}
// Set up logging to the event system
if (useLogToEventSystem)
{
if (debugToEventSystem)
{
// Write to the Windows Event System
}
}
// Attach the event handler to the CMS
if (useEventSystem)
{
EventSystem.Subscribe<PublishTransaction, SaveEventArgs>(HandlerForPublishTransaction, EventPhases.TransactionCommitted);
}
}
public void HandlerForPublishTransaction(PublishTransaction transaction, SaveEventArgs args, EventPhases phase)
{
// The Success and Failure states should be logged in every case
// Determine if the other states should be logged as well
if ((!logOnlySuccessAndFailure) || (transaction.State.ToString() == "Success") || (transaction.State.ToString() == "Failed"))
{
switch (logPropertySet)
{
case 1: // Log Full Properties
{
// Logging a full set of properties to a text file
foreach (IdentifiableObject id in transaction.Items)
{
// Retrieve the properties to write
if (debugToEventSystem)
{
// Write to the event system
}
// Log the information
if (useLog4Net)
{
// Write to log4net
}
if (useLogToTextFile)
{
// Write to the text file
}
if (useLogToEventSystem)
{
// Write to the Windows event system
}
}
}
break;
case 2: // Some Properties
{
// Get some of the publishing transaction details
try
{
foreach (IdentifiableObject id in transaction.Items)
{
// Retrieve the properties to write
if (debugToEventSystem)
{
// Write to the event system
}
// Log the information
if (useLog4Net)
{
// Write to log4net
}
if (useLogToTextFile)
{
// Write to the text file
}
if (useLogToEventSystem)
{
// Write to the event system
}
}
}
catch (Exception ex)
{
if (debugToEventSystem)
{
// Write to the event system
}
}
}
break;
case 3: // Few properties
{
try
{
foreach (IdentifiableObject id in transaction.Items)
{
// Determine the properties to write
if (debugToEventSystem)
{
// Write to the event system
}
// Log the information
if (useLog4Net)
{
// Write to log4net
}
if (useLogToTextFile)
{
// Write to the text file
}
if (useLogToEventSystem)
{
// Write to the event system
}
}
}
catch (Exception ex)
{
if (debugToEventSystem)
{
// Write to the event system
}
}
}
break;
}
}
}
}