Uploaded image for project: 'Drools'
  1. Drools
  2. DROOLS-1262

Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace

    Details

    • Docs QE Status:
      NEW
    • QE Status:
      NEW

      Description

      In the latest 6.4 product patches, I am seeing customers that are up to 10 times slower due to drools in their optaplanner cases. It turns out that they have no logging configuration and many systems - such as WildFly use DEBUG logging by default (often to a file so no one notices it).

      Meanwhile the log fills up with this:

      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE         Move index (100), score (-10hard/-128070soft), accepted (false), move (CloudProcess-67 {CloudComputer-45} <-> CloudProcess-147 {CloudComputer-18}).
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was INACTIVE is now FIRING_ALL_RULES
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG Fire Loop
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was FIRING_ALL_RULES is now HALTING
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] drools DEBUG State was HALTING is now INACTIVE
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner TRACE         Move index (101), score (0hard/-128070soft), accepted (true), move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
      2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] optaplanner DEBUG     LS step (6730), time spent (3432), score (0hard/-128070soft),     best score (0hard/-126690soft), accepted/selected move count (1/102), picked move (CloudProcess-104 {CloudComputer-89} <-> CloudProcess-295 {CloudComputer-26}).
      

      but without the optaplanner TRACE lines (they are just here to show that drools debug is 7 times as verbose as optaplanner trace here).

      Solution proposal A): remove the line "Fire Loop" and put "State was" on trace logging.

      Solution proposal B): collapse the 5 lines "Fire Loop" into "5 fire loops" and put "State was" on trace logging.

      Solution proposal C): put the line "Fire Loop" and "State was" on trace logging.
      I personally dislike this one - even trace logging should still be useful and not more verbose that it needs to be (although it should log in high detail).

      This should be fixed for 7.0, 6.5.x and I 'll ask QA to consider adding it for 6.4.x.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  mfusco Mario Fusco
                  Reporter:
                  ge0ffrey Geoffrey De Smet
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: