watchdog() (in includes/bootstrap.inc, not watchdog.module since we no longer have such a module) should be able to avoid invoking hook_watchdog() implementations when the level of the event is lower than a system-defined logging level, i.e. with a WATCHDOG_* constant higher than this level, due to the actual values of these constants.

This would reduce some long-standing performance issues with useless logging. Without going into per-source or per-implementation settings, and without defining a UI, it could be made 100% compatible with the current situation while still fixing this bug:

- define a watchdog_minimum_level variable in settings.php, defaulting to WATCHDOG_DEBUG to keep all events by default
- only invoke the hook for events above that level

That way existing code would not be affected, but sites with watchdog chatter issues could reduce the "noise" and increase performance.

Files: 
CommentFileSizeAuthor
#21 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch5.76 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 40,632 pass(es). View
#19 watchdog_reporting_level-1268636-19.patch7.7 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 35,393 pass(es). View
#19 interdiff.txt1.85 KBfgm
#16 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch8.91 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 35,398 pass(es). View
#14 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch8.93 KBfgm
FAILED: [[SimpleTest]]: [MySQL] 33,362 pass(es), 45 fail(s), and 45 exception(s). View
#13 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch9.11 KBfgm
FAILED: [[SimpleTest]]: [MySQL] 33,355 pass(es), 45 fail(s), and 45 exception(s). View
#12 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch9.11 KBfgm
FAILED: [[SimpleTest]]: [MySQL] 33,350 pass(es), 45 fail(s), and 45 exception(s). View
#9 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch7.42 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 35,365 pass(es). View
#7 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch6.55 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 35,420 pass(es). View
#3 watchdog_limit-1268636-4.patch5.73 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 32,920 pass(es). View
#1 watchdog_limit-1268636-1.patch2 KBfgm
PASSED: [[SimpleTest]]: [MySQL] 35,922 pass(es). View

Comments

fgm’s picture

Status: Active » Needs review
FileSize
2 KB
PASSED: [[SimpleTest]]: [MySQL] 35,922 pass(es). View

Patch fixes this.

The test for the severity level is not at the first line as could be expected, to prevent errors in variable_get() from occurring outside the loop detection.

Damien Tournoud’s picture

Version: 7.x-dev » 8.x-dev
Component: watchdog.module » base system
Category: bug » feature
Issue tags: +Needs tests, +needs backport to D7

I can see this being useful, but there is no bug to fix in there :)

If we could add a test to it (by extending the existing DBLog tests), I can see this getting in, and eventually backported.

fgm’s picture

FileSize
5.73 KB
PASSED: [[SimpleTest]]: [MySQL] 32,920 pass(es). View

Rerolled for d8 with a dblog-independent test.

fgm’s picture

Also consider that RFC 3164 §1.1 third paragraph implies that some way to configure such reporting is indeed required

Devices MUST be configured with rules for displaying and/or forwarding the event messages.

Since which we do not currently really honor this, it is a RFC-compliance bug, IMHO.

sun’s picture

IMHO, this is application-level logic.

Since that may sound ambiguous: In this case, dblog.module is one of the possible logging applications. So if dblog is too slow or whatever to cope with these messages, then it should expose such a configuration option.

Compared to that, I'm pretty sure that you can inject a watchdog() call into every single function that Drupal invokes, and while only having syslog.module enabled, you won't see a measurable difference in performance. (at the very least, that's how syslog is supposed to work...)

fgm’s picture

Obviously any watchdog implementation can, and probably should, filter ; and some, like syslog on a properly setup configuration, will not add excessive load to a system.

However, this still means a round of module_iimplements()/module_invoke() within core, plus the extra pre-filtering logic in any implementation, in addition to the likely variability in implementations of filtering by all such modules, while bringing the feature to core can both :

- "cut the flow" higher up and avoid running this code,
- offer a unified way of filtering based on an existing standard we already chose to apply - for better or worse - when RFC3164 was chosen for the Drupal 4.6 watchdog severity levels.

fgm’s picture

FileSize
6.55 KB
PASSED: [[SimpleTest]]: [MySQL] 35,420 pass(es). View

Rerolled against today's dev version.

fgm’s picture

Status: Needs review » Needs work

Should use config now that it's landed, not variables.

fgm’s picture

Status: Needs work » Needs review
FileSize
7.42 KB
PASSED: [[SimpleTest]]: [MySQL] 35,365 pass(es). View

Rerolled to use config, and added UI on logging settings.

Lars Toomre’s picture

Status: Needs review » Needs work
+++ b/core/includes/bootstrap.incundefined
@@ -1592,6 +1593,10 @@ function watchdog($type, $message, $variables = array(), $severity = WATCHDOG_NO
   if (!$in_error_state && function_exists('module_implements')) {
+    if ($severity > variable_get('watchdog_limit', WATCHDOG_DEBUG)) {
+      return;
+    }

Shouldn't this also be converted to use new config system?

fgm’s picture

Indeed. And this also needs

  • to be changed in core/modules/system/system.test
  • to include the default value in core/modules/system/config/system.logging.xml
fgm’s picture

FileSize
9.11 KB
FAILED: [[SimpleTest]]: [MySQL] 33,350 pass(es), 45 fail(s), and 45 exception(s). View

Rerolled accordingly. test module is still using a variable for its state information, but the config info is now using config.

fgm’s picture

Status: Needs work » Needs review
FileSize
9.11 KB
FAILED: [[SimpleTest]]: [MySQL] 33,355 pass(es), 45 fail(s), and 45 exception(s). View

Rerolled accordingly. test module is still using a variable for its state information, but the config info is now using config.

fgm’s picture

FileSize
8.93 KB
FAILED: [[SimpleTest]]: [MySQL] 33,362 pass(es), 45 fail(s), and 45 exception(s). View

No idea why default.settings.php is set to 0755 in core, but this patch should not be touching it.

Lars Toomre’s picture

Status: Needs review » Needs work
+++ b/core/modules/system/system.admin.incundefined
@@ -1631,14 +1631,41 @@ function system_logging_settings() {
+    '#default_value' => $config->get('watchdog_limit') ?: WATCHDOG_DEBUG,

This looks like you are missing something...

+++ b/core/modules/system/system.testundefined
@@ -2903,3 +2903,107 @@ class SystemIndexPhpTest extends DrupalWebTestCase {
+  /**
+   * watchdog_test_watchdog() stores is state in a variable.

Should be 'its' instead of 'is'.

+++ b/core/modules/system/system.testundefined
@@ -2903,3 +2903,107 @@ class SystemIndexPhpTest extends DrupalWebTestCase {
+  /**
+   * Test the default and non-default behaviours

Should be 'behaviors.' (American english and a period). There is another patch that recently corrected the spelling of behavior throughout core.

fgm’s picture

Status: Needs work » Needs review
FileSize
8.91 KB
PASSED: [[SimpleTest]]: [MySQL] 35,398 pass(es). View

Good catches. I thought I had fixed them all.

Status: Needs review » Needs work
Issue tags: -Performance, -Needs tests, -needs backport to D7

The last submitted patch, 0001-Issue-1268636-by-fgm-Ignore-watchdog-calls-below-the.patch, failed testing.

fgm’s picture

Status: Needs work » Needs review
Issue tags: +Performance, +Needs tests, +needs backport to D7
fgm’s picture

FileSize
1.85 KB
7.7 KB
PASSED: [[SimpleTest]]: [MySQL] 35,393 pass(es). View

Minor changes:
- moved comment about WATCHDOG_DEBUG to config file, not settings form
- added missing EOF new line
- do not include a final dot removal in a @see in system_performance_settings() which is outside the scope of the patch.

nod_’s picture

Status: Needs review » Needs work

not XML anymore :p

fgm’s picture

Status: Needs work » Needs review
FileSize
5.76 KB
PASSED: [[SimpleTest]]: [MySQL] 40,632 pass(es). View

Rerolled for the new config format.

ZenDoodles’s picture

Status: Needs review » Needs work

I've reviewed this twice now. Unfortunately due to stupidity far exceeding even *my* norms, those reviews have not actually been posted. I'm sorry I don't have time to do over it again.

The short version:

  1. This is a feature request. Backporting to D7 seems dubious.
  2. I'd like to see sun's comment addressed.
  3. Beware premature optimization. Is there data to support that this really is an issue (in core)?
  4. The comments and description strings need work. I had suggestions. They are gone.
  5. There is a new test module here, but there are no tests. (Also, I think we already have hook_watchdog in a watchdog test module).

Okay, 2 and 3 are either closely related or the same. On the other hand, I think you might be able to make a case for this as a feature w/o performance as the primary argument.

Also, any thoughts on a follow-up issue for making watchdog level a bitmask like php error levels?

ZenDoodles’s picture

Status: Needs work » Needs review
Issue tags: -needs backport to D7 +API change

Also, this impacts hook_watchdog() and should be documented as such.

ZenDoodles’s picture

Status: Needs review » Needs work

Bah

fgm’s picture

I'll answer in more detail when I can, but for now, performance is indeed the primary motivation for this, based on actual sites in production. DBLog is a known source of DB load, and many not-so-large sites do not want to deploy tools around syslog, or mongodb_watchdog/redis_watchdog, so such a setting provides them with an easy way to keep using DBLog and its built-in reports, while still not suffering too much load from it.

This type of problem may not be adequately by performance tests on a normal core distribution because most of the issues making this a necessity arise because of poorly developed contrib or, worse, custom modules and themes, which cause far more watchdog entries than core ever will. But if others used to working on site load can chime in, I am pretty sure they will confirm having observed this.

Version: 8.0.x-dev » 8.1.x-dev

Drupal 8.0.6 was released on April 6 and is the final bugfix release for the Drupal 8.0.x series. Drupal 8.0.x will not receive any further development aside from security fixes. Drupal 8.1.0-rc1 is now available and sites should prepare to update to 8.1.0.

Bug reports should be targeted against the 8.1.x-dev branch from now on, and new development or disruptive changes should be targeted against the 8.2.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

fgm’s picture

Version: 8.1.x-dev » 8.2.x-dev
Issue summary: View changes

Bumping to current version.

MongoDB now implements it on its own in mongodb_watchdog 8.x-2.x, but I maintain we should have a standard way to do this in core.

ndobromirov’s picture

+1 on #27.

Version: 8.2.x-dev » 8.3.x-dev

Drupal 8.2.0-beta1 was released on August 3, 2016, which means new developments and disruptive changes should now be targeted against the 8.3.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

Version: 8.3.x-dev » 8.4.x-dev

Drupal 8.3.0-alpha1 will be released the week of January 30, 2017, which means new developments and disruptive changes should now be targeted against the 8.4.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.