Beware: Watchdog is a Hog

image

A neat monitoring agent that will run inside your Drupal PHP engine is New Relic.   With New Relic we can monitor the PHP application performance as well as the overall health of the Drupal site in terms of under-the-hood metrics: database performance, error rate, response time, sluggish modules/APIs (it can locate these down to the line of code causing the site to spin at a zillion CPU cycle a second.  So, it is a handy tool to have under our sleeves when hosting a Drupal site running on top of a LAMP stack; or any other software stack outside the Drupal world since we can always embed New Relic in JVMs and .Net framework.

Now back to Drupal.  Among the most utilized Drupal tables is watchdog (in Drupal 7 watchdog has been deprecated and replaced by the Database logging and Syslog modules, but the underlying table is still referenced as watchdog).  The Syslog module enables the integration of Drupal logging with the Linux server syslog facility.  The watchdog function logs errors and warnings, or if you need to, all messages. The functionality is pretty neat as the function logs the URL that triggered the error as well as the referring URL and in the blob field we can view the PHP module that raised the exception and the line number as in:

 a:6:{s:5:"%type";s:6:"Notice";s:8:"!message";s:21:"Undefined index: type";s:9:"%function";s:27:"somePhpFunction()";s:5:"%file";s:98:"/<fullPathToModule/mySite/sites/all/modules/custom/ somePhpFunction.module";s:5:"%line";i:34;s:14:"severity_level";i:5;} and we can always reference and utilize the watchdog function in our own PHP custom modules as in: <?php watchdog('The error title goes here', 'The error message goes here'); ?> As far as configuring Drupal error logging, for my own sanity (call me meticulous, paranoid, or both if you want to) I prefer to log all messages.  The problem is that a database transaction is an expensive transaction that consumes valuable CPU cycles and New Relic actually confirms that watchdog inserts are the most time consuming database transactions (hence the New Relic intro above) followed by selects to the url_alias table.

Moreover, that New Relic bar chart captured these metrics while I had “Logging and Errors” flagged to track “Errors and Warnings” only.  Raising the logging threshold to include “All messages” raised the New Relic percentage bar and generated an astronomical row count in-between the cron maintenance tasks that trimmed the watchdog table down to the max row count defined in “Database log messages to keep”; which defaults to 1000 rows.  Remember, that row count isn’t the maximum number of rows that watchdog will grow to, but rather the row count it will be set to after triggering the cron job every X hours.  So technically speaking, the watchdog row count can grow to be in the thousands between cron cycles and is acceptable because it isn’t good design to check the watchdog table’s row count before each insert transaction.  As it is, watchdog inserts are consuming extensive CPU cycles, let alone a select to check the row count before each insert or every so many X inserts; so just let it grow and do the inserts and trim it every X hours; that works better. So for a development environment, the common practice among seasoned Drupal developers is to use all the logging facilities. In the development environment, you will need to first raise the drupal "error threshold" setting while enabling both database and syslog logging.   To set the error threshold, browse to the drupal Logging and Errors configuration , and set the Error messages to display option to “all messages”.  With a production environment, completely shutdown watchdog (the database logging module) and instead just keep the Syslog module enabled.  That seems to be the perfect world scenario: logging all messages to appease my sanity while not consuming expensive CPU cycles for database inserts. Thanks. Hani

Subscribe to Our Newsletter

Stay In Touch