Understanding Sitecore logs – Part 2: Caches and XML configuration load

Continuing with my series of blogs describing what each line in the Sitecore logs mean, today I want to talk about Caches and XML Configuration load.

In this post, we are still examining the log file. In future posts, we will explore Client, Crawling, Eds, Exm, Fxm, Search, Publishing, Aggregation and WebDAV logs. Phew… sounds like a lot of work.

If you missed the first part of my series, please take a look at Understanding Sitecore logs – Part 1: xDB, Tracking, License, Path Analyzer and Memory Monitor.

Cache creation

The next block we are going to explore is related to cache. But first, let’s review some concepts:

  • Caching makes a copy of data from the original source (e.g. a database) to the server’s memory (RAM) so that information can be retrieved faster in the next requests. Caching can significantly improve the performance of a site and works best with data that does not change frequently.
  • Native ASP.NET caching provide in-memory caching on the Web server. Sitecore does not use native ASP.NET caching. Sitecore caches consist of named ASP.NET collections containing various types of data in memory (RAM) on the Web server.
  • Sitecore caches are managed by the Sitecore.Caching.CacheManager, Sitecore.Kernel class.
  • Each cache serves as a key/value collection, associating each unique key with a cached value.
  • The name of each cache identifies its purpose. For example, the ‘web[paths]’ cache maps URL paths to items. Sitecore does not pre-populate database path caches.
  • You can configure a size limit for each Sitecore memory cache. When a cache reaches its size limit, Sitecore evicts one or more entries from the cache at random before adding a new entry.
  • Sitecore caches media using one or more file systems rather than RAM. Also, cache size limits do not apply to media caches.

You can learn more about Sitecore cache by reading the Cache Configuration Reference.

Now, let’s examine the caching logs:

19504 19:52:53 INFO  Cache created: 'rules' (max size: 4MB, running total: 4MB)
19504 19:52:53 INFO  Cache created: 'DeviceItemsCache' (max size: 50MB, running total: 54MB)
19504 19:52:53 INFO  Cache created: 'core[data]' (max size: 100MB, running total: 154MB)

... more caching logs ...

19504 19:52:53 INFO  Cache created: 'filesystem[blobIDs]' (max size: 5MB, running total: 899MB)

The entries above are logged by the class Sitecore.Caching.DefaultCacheManager, Sitecore.Kernel.

The primary source of these logs come from classes that derive from Sitecore.Caching.CustomCache.CustomCache, Sitecore.Kernel. The cache registration is defined in the constructor of these classes. In other words, once any of these classes is instantiated for the first time, the cache is created.

Take for instance Sitecore.Caching.RuleCache, Sitecore.Kernel. This class derives from Sitecore.Caching.CustomCache.CustomCache, Sitecore.Kernel and is responsible for caching Sitecore rules. It also corresponds to the entry in the log Cache created: 'rules' (max size: 4MB, running total: 4MB).

Let’s breakdown the information contained in these log entries:

  • cache created ‘[cache name]’: shows the name of the cache.
  • max size: shows the amount in megabytes of max size for that specific cache.
  • running total: the total amount of max size registered up to that log entry. Notice that the amount always increases and is basically a sum of the current max size with the previous running total. If you look at the log information in the beginning of this post you will notice the tendency in the running total:
  • max size: 4MB, running total: 4MB ...
  • max size: 50MB, running total: 54MB (50MB + 4MB from previous running total) …
  • max size: 100MB, running total: 154MB (100MB + 54mb from previous running total).
  • It is basically accumulating the amount of “max size” registered and saving it to the “running total”.

Note: The running total does not indicate how much memory is being used. It just shows how much it can be used (max size). You can see the actual memory usage in the cache.aspx page that I mention further.

You find below a compact list of classes that implement CustomCache:

The following logs repeat for each database (core, master, web, filesystem):

The following logs repeat for each site (e.g. shell, website, scheduler, etc.):

The secondary source of caches comes from cache containers configuration. Cache containers register caches from configuration files.

If you don’t want to create a class that derives from the base class CustomCache, but wants to register a cache and manage it through configuration file, then you should use cache containers configuration. You can find an example in the file \App_Config\Include\Examples\CacheContainers.config.example.

Finally, you can see what caches are registered in your website, as well as the max size and the current memory usage, by navigating to [hostname]/sitecore/admin/cache.aspx.

Let’s understand the cache.aspx page:

  • In the Totals section, we have Entries that shows us the total amount of items ( key/value pairs) in all Sitecore caches registered. It is basically a sum of all items in the “Count” column. Also we have the Size that shows the estimated total memory consumed by those entries in bytes.
  • Next, we have the “Caches (149)” that shows us the total number of Sitecore caches.. You reach to this number by counting how many caches are listed in this table.
  • Finally, in the cache table we have the unique string that identifies a cache collection (Name), how many items (key/value pairs) are added to that cache (Count), the current size of the cache (Size), the change in the size of the cache since the last refresh of the cache.aspx page (Delta) and the limit to the size of the cache (Max Size).

Load XML configuration

ManagedPoolThread #10 20:29:43 INFO  Trying to load XML configuration /App_Config/Security/Domains.config
26728 15:37:41 INFO  Trying to load XML configuration /App_Config/Security/GlobalRoles.config

The next block is logged by the Sitecore.Configuration.XmlConfigStore, Sitecore.Kernel class. What is happening here is that Sitecore is caching configuration stores defined in the Sitecore.config file. More precisely, in the section /sitecore/configStores.

Configuration stores are cached configurations that don’t cause the Application Pool to recycle when these files are changed. Also, they auto refresh whenever the content changes.

You can do a simple test. Add a new domain to the \Security\Domains.config file and refresh the page /sitecore/shell/Applications/Security/Domain%20Manager.aspx?sc_bw=1. You’ll notice that your domain is loaded right after refreshing the page and the Application Pool is not recycled.

Also, once you change the \Security\Domains.config file, you will see an entry in the log notifying you that this file was changed:

7632 15:41:55 INFO  Config file modified: C:\inetpub\wwwroot\sitecore911.sc\App_Config\Security\Domains.config

That was it for today.

Credits

Photo by Mildly Useful on Unsplash.

comments powered by Disqus