In the first of the 10 blog postings we will put out here, we looked at the first of 10 Steps To A Stable and Performant Web Application.  As mentioned, we always want to know what is happening in production and this initially involves looking at existing logs that are no more than 1 week old.  In this blog posting, we will look at adding Metrics Logging and also enhanced log splitting out using log.level.

Irrespective of whether we have or use ColdFusion Server Monitor, SeeFusion or Fusion Reactor; we always recommend the turning on of Metrics Logging and leaving it on in production.  The overhead is insignificant and the help we can get at times of server stress is priceless in some cases.  All the settings in this article can be used whether this is a Stand Alone install of ColdFusion or an Enterprise install, the configuration files are simply in different places. One very important point I want to make here, if you purchased the Enterprise license please ensure you install ColdFusion in the Multiple Instance mode, even if you will only have one instance at first, otherwise you are miising out on one of the most powerful features of the Enterprice license, the ability to create Multiple Instances.  We will edit the jrun.xml file to enable metrics logging and it is located, as follows, depending on the install of ColdFusion you have (assuming CF8 although, the only difference on MX6.1 and MX7 is the CF install directory name on the Standard install.

On a Standard install - {drive}Coldfusion8\runtime\servers\coldfusion\SERVER-INF

On an Enterprise Multiple Instance install - {drive}\JRun4\servers\coldfusion\SERVER-INF

In the jrun.xml file, locate this entry (it will somewhere around line 129)

<!-- This Service provides metrics information  -->

<!-- ================================================================== -->

<!--  To enable metrics: uncomment this service and in LoggerService set metricsEnabled to true -->

<!--<service class="jrunx.metrics.MetricsService" name="MetricsService">   

<attribute name="bindToJNDI">true</attribute>

</service>

-->

Uncomment this section if it is commented out, after that it will look like this...

<!-- This Service provides metrics information  -->

<!-- ================================================================== -->

<!--  To enable metrics: uncomment this service

      and in LoggerService set metricsEnabled to true -->

<!-- -->

<service class="jrunx.metrics.MetricsService" name="MetricsService">

  <attribute name="bindToJNDI">true</attribute>

</service>

Around line 159 locate this entry, if this is set as shown here "false", change this to "true".

<!-- You may also need to uncomment MetricsService if you want metrics enabled -->

<attribute name="metricsEnabled">false</attribute>

The next section has various items that can be set to different values.

<attribute name="metricsLogFrequency">60</attribute> - This entry sets the frequency of metrics logging to 60 second intervals which I have found to be a good number.

<attribute name="metricsFormat">Web threads (busy/total): {jrpp.busyTh}/{jrpp.totalTh} Sessions: {sessions} Total Memory={totalMemory} Free={freeMemory}</attribute> - This line contains a number of very important settings.  One important point before going any further is that in a non Enterprise Stand-Alone install we need to remove the "jrpp" from the metric variable declaration, so jrpp.busyTh needs to to be changed to busyTh and so on.  If this is an Enterprise multiple instance install, jrpp.busyTh is fine.  Here is an explanation of each element in this line.

Web threads - In the default version of this file there are two web threads that will be shown, (busy/total): {jrpp.busyTh}/{jrpp.totalTh}, however there are more, here is a rundown of each.

jrpp.listenTh - This is available threads that have not yet been used for anything, or were used but cyled back through different thread states to become idle again.

jrpp.idleTh - This is the state a thread returns to after being used or busy.

*jrpp.delayTh - Threads in this state are handling an incoming request but they cannot run because all available threads are busy.  This is not a good thing and usually causes degradations in performance of the server overall.

*jrpp.busyTh - This is all threads that are currently actively serving incoming requests.  In a well tuned server this number will stay low and continually cycle up and down.

*jrpp.totalTh - This is the total of all threads in every state.

jrpp.droppedRq - This shows the number of requests that were dropped because of some occurrence or other, perhaps a request time-out setting for instance.

jrpp.handledRq - This is the number of requests successfully handled.

jrpp.handledMS - This is the total amount of time spent successfully handing requests.

jrpp.delayMs - This is the total amount of time spent by threads in a delayed state.

jrpp.bytesIn - This is the total amount of data from requests coming in.

jrpp.bytesOut - This is the total amount of data sent out in response to incoming requests.

*freeMemory - This is the amount of free memory in the heap at the time of the metrics snapshot.

*totalMemory - This is the total amount of memory in the heap at the time of the metrics snapshot.

*sessions - Number of active jsessions at the time of the metrics snapshot.  This is Java sessions and not standard ColdFusion sessions.

sessionsInMem - This is the total number on jsessions in memory, including those that are not in use any more but have not yet timed out.

The ones we tend to use most often are *.

Please bear in mind that all of these metrics relate to what happened in the last 60 seconds, as defined by this setting <attribute name="metricsLogFrequency">60</attribute>.  Also, if you have a Standard non-Enterprise install, leave off the "jrpp." suffix.

At this point the metrics would end up in the {drive}Coldfusion8\runtime\coldfusion-out.log on a Standard install or in the JRun4\logs\{instance}-out.log on an Enterprise multiple instance install.  This is very useful as if there is some sort of problem the metrics will be in the -out.log at the exact time of any-all problems logged there, however it is also good to split out that log into discreet parts, in our experience.  For instance, creating a separate log for metrics only can be very useful for trending.  to identify possible memory leaks, for instance.  In order to do this we make one last change to the jrun.xml file as follows...

Around line 166 is this entry <attribute name="filename">{jrun.rootdir}/logs/{jrun.server.name}-event.log</attribute>.

We add a log.level command as follows...<attribute name="filename">{jrun.rootdir}/logs/{jrun.server.name}-{log.level}-event.log</attribute>

The net result of all of this are log entries which look like this...

29/04 23:29:04 metrics Web threads (busy/total/wait): 1/24/0 Sessions: 0 Total Memory=1012800 Free=943151
29/04 23:30:04 metrics Web threads (busy/total/wait): 2/24/0 Sessions: 0 Total Memory=1012800 Free=928446
29/04 23:31:04 metrics Web threads (busy/total/wait): 3/25/0 Sessions: 0 Total Memory=1012800 Free=919736
29/04 23:32:04 metrics Web threads (busy/total/wait): 1/26/0 Sessions: 0 Total Memory=1015104 Free=963036

This is just after a ColdFusion restart and all looks OK at this point.

01/05 12:17:09 metrics Web threads (busy/total/wait): 1/28/0 Sessions: 1 Total Memory=690048 Free=158060
01/05 12:18:09 metrics Web threads (busy/total/wait): 1/28/0 Sessions: 1 Total Memory=690432 Free=215408
01/05 12:19:09 metrics Web threads (busy/total/wait): 1/28/0 Sessions: 1 Total Memory=689984 Free=164688
01/05 12:20:09 metrics Web threads (busy/total/wait): 1/27/0 Sessions: 1 Total Memory=688000 Free=93655
01/05 12:21:09 metrics Web threads (busy/total/wait): 1/27/0 Sessions: 1 Total Memory=688832 Free=58571
01/05 12:22:09 metrics Web threads (busy/total/wait): 1/27/0 Sessions: 1 Total Memory=689792 Free=83309
01/05 12:23:09 metrics Web threads (busy/total/wait): 1/27/0 Sessions: 1 Total Memory=690496 Free=105955

This is around 12-13 hours later during busier times and we can see a good amount of memory is in use and total memory has decreased.

So Metrics logging is a very useful tool overall for getting started in the right direction with troubleshooting, in our next post we will look at Verbose Garbage Collection logging.