Journaling OpenBD CFML
OpenBD has a powerful profiling and code coverage tool built in that is called the Journal. The Journal can be enabled on a per-request basis that will record each file, tag and expression line executed and dump that into an easy to consume CSV file for analysis.
If you are running automated or unit testing this will give you the details as to how much code your tests are reaching. In addition, you can determine the most hit files, tags and functions and the average execution time for blocks of code. All the raw data is produced by the journal to be consumed.
The journal is not enabled by default, you must edit the bluedragon.xml file adding in the line to the server system XML component and restart.
<journal>password1234</journal> <journalmb>50</journalmb> <journalignoreuri>/journal</journalignoreuri>
The value here is the password/token that will be used to enable the journaling of a given request. This allows you to control the security of the journal request, easily allowing to be added into testing environments. The journalmb is the maximum size that this directory will become. This ensures you don't fill up the disk. It will delete the oldest files until the space allocation is down to 90% of the value specified. Defaults to 50MB. The journalignoreuri lets you specify a URI path to which the journal will not happen, even if a cookie/uri/header exists. This stops you from having to journal the journal app itself.
Once enabled you can enable a request to be journaled in one of three ways:
- URI Param: _openbdjournal=value-you-had-in-the-bluedragon.xml
- HTTP header: _openbdjournal: value-you-had-in-the-bluedragon.xml
- Cookie: _openbdjournal=value-you-had-in-the-bluedragon.xml
Should any of these be detected, then the request will be journaled, which will result in a file be written in the [OpenBD working directory]/journal/ directory. This will be a text file dated the time of the request as per the server clock, for example "2015-01-19_13.29.29-0.txt". A directory structure mirroring the request path, will be created underneath this folder.
Journal has a powerful feature which can be enabled with each request. That is, it can take a snapshot of the state of the variables at the time when a file is entered/left and function started/exited. This is saved in a file along side the journal with the .session extension. Each session state is saved one after another and you can read it back using JournalReadSession(). You enable this by add "-1" to the end of the password passed in via the uri/header/cookie.
<cfset jDir = GetJournalDirectory()>
You can get a handle to this directory using the GetJournalDirectory() function.
Journal File Format
The first line of the journal file is a JSON encoded structure that has a variety of keys about the request. Any key that is prefixed with an underscore (_) is a system key. An example of this includes: _uri (the original request), _bytes (the number of bytes sent), _timems (time for request), _querycount (number of queries ran), _querytime (time the queries took), _method (the HTTP method of the request). All the other keys are the full path names of the files that this particular request read. This includes all CFC's, include's, template's etc. The key is pointed to a unique number that is referenced in the remaining lines.
The remaining lines of the journal are the execution trace of the request.
142,TE,4,3,3,CFCOMPONENT,423,-397 142,TT,3,3,4,CFSET,39,2 142,MS,3,3,5,CFFUNCTION,52,-52,initProperties 142,TT,3,3,6,CFPARAM,44,3 142,TT,3,3,6,CFPARAM,45,3 146,TT,3,3,6,CFPARAM,46,3 174,TS,6,3,7,CFCOMPONENT,1,1 174,FS,6,4,7 174,TS,5,4,8,CFCOMPONENT,1,1 174,FS,5,5,8 174,FE,5,4,8 174,TE,5,4,7,CFCOMPONENT,3,1 174,TT,6,4,8,CFPARAM,2,2 175,TT,6,4,8,CFPARAM,3,2 175,TT,6,4,8,CFPARAM,4,2 175,TT,6,4,8,CFPARAM,5,2 175,TT,6,4,8,CFPARAM,6,2 175,TT,6,4,8,CFPARAM,7,2 176,TT,6,4,8,CFPARAM,8,2 176,TT,6,4,8,CFPARAM,9,2 176,TT,6,4,8,CFPARAM,10,2 176,TT,6,4,8,CFPARAM,11,2 177,TT,6,4,8,CFPARAM,12,2 ...
The table below shows the possible values for each line type.
|File Start||time||FS||File ID||Session||File Depth||Tag Depth|
|File End||time||FE||File ID||Session||File Depth||Tag Depth|
|Tag Start||time||TS||File ID||Session||File Depth||Tag Depth||Tag Name||Line Number||Column Number|
|Tag (with no end tag)||time||TT||File ID||Session||File Depth||Tag Depth||Tag Name||Line Number||Column Number|
|Tag End||time||TE||File ID||Session||File Depth||Tag Depth||Tag Name||Line Number||Column Number|
|cfFunction start||time||MS||File ID||Session||File Depth||Tag Depth||Tag Name||Line Number||Column Number||cfFunction name|
|cfFunction End||time||ME||File ID||Session||File Depth||Tag Depth||Tag Name||Line Number||Column Number||cfFunction name|
|Script Statement||time||SS||File ID||Session||File Depth||Tag Depth||reserved||Line Number||Column Number||Line Number from CFSCRIPT tag|
|Script Function Start||time||SF||File ID||Session||File Depth||Tag Depth||function name|
|Script Function End||time||SE||File ID||Session||File Depth||Tag Depth||function name|
|Expression Run||time||HE||File ID||Session||File Depth||Tag Depth||expression|
|Runtime Exception||time||ER||Error message|
|BadFile Exception||time||EF||Error message|
The third column is the file index that this operation happened in. Refer to the structure from the first line to determine the precise file it was in.
The 'session' column is a numeric page number of the state of the variables if the session tracking was enabled with the request. You get at this JournalReadSession() function, passing in the page you want to read. This will return a struct that represents the state of the variables at that time.
The purpose of this feature is to collect the raw data for later processing. Future releases of OpenBD will see tooling around the analysis of Journal files.