[JBoss JIRA] (DROOLS-1262) Logging level DEBUG should be less verbose: "Fire Loop" & "State was" should be trace
8:46 a.m.
[
https://issues.jboss.org/browse/DROOLS-1262?page=com.atlassian.jira.plugi...
]
Geoffrey De Smet updated DROOLS-1262:
-------------------------------------
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:
{code}
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
(0), 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
(1), 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/2), picked move (CloudProcess-104 {CloudComputer-89}
<-> CloudProcess-295 {CloudComputer-26}).
{code}
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.
was:
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:
{code}
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was INACTIVE is now
FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is
now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now
INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (0), 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] DEBUG State was INACTIVE is now
FIRING_ALL_RULES
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG Fire Loop
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was FIRING_ALL_RULES is
now HALTING
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] DEBUG State was HALTING is now
INACTIVE
2016-08-29 15:20:57,338 [SwingWorker-pool-2-thread-1] TRACE Move index (1), 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] DEBUG LS step (6730), time spent
(3432), score (0hard/-128070soft), best score (0hard/-126690soft), accepted/selected
move count (1/2), picked move (CloudProcess-104 {CloudComputer-89} <->
CloudProcess-295 {CloudComputer-26}).
{code}
but without the optaplanner TRACE lines.
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.
Logging level DEBUG should be less verbose: "Fire Loop"
& "State was" should be trace
-------------------------------------------------------------------------------------
Key: DROOLS-1262
URL: https://issues.jboss.org/browse/DROOLS-1262
Project: Drools
Issue Type: Bug
Components: core engine
Affects Versions: 6.4.0.Final, 6.5.0.CR1, 7.0.0.Beta1
Reporter: Geoffrey De Smet
Assignee: Mario Fusco
Priority: Critical
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:
{code}
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 (0), 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 (1), 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/2), picked move (CloudProcess-104 {CloudComputer-89}
<-> CloudProcess-295 {CloudComputer-26}).
{code}
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.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
2992
days inactive
2992
days old
0 comments
1 participants
participants (1)
-
Geoffrey De Smet (JIRA)