Bug 780281 (SOA-2684)

Summary: XML_PLAN output to server log too verbose for DEBUG level logging
Product: [JBoss] JBoss Enterprise SOA Platform 5 Reporter: Paul Nittel <pnittel>
Component: EDSAssignee: Steven Hawkins <shawkins>
Status: CLOSED NEXTRELEASE QA Contact:
Severity: high Docs Contact:
Priority: high    
Version: 5.1.0.ER5   
Target Milestone: ---   
Target Release: 5.1.0.CR1   
Hardware: Unspecified   
OS: Unspecified   
URL: http://jira.jboss.org/jira/browse/SOA-2684
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
RHEL 5, SOA-P 5.1 ER5, JBDS 4.0 Beta2 (H33)
Last Closed: 2011-02-08 14:57:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Paul Nittel 2010-12-14 18:52:49 UTC 
project_key: SOA

I was executing the E2E Staging Table test script and executed a query of the XML document from Designer. It took a long time--longer than I'd anticipated--so I looked at the server log to see what had happened. Turns out the server log had grown to 1.2GB in roughly 10 minutes. Checking the log (carefully!) I found XML_PLAN entries accounted for 8,759,795 lines of the 10,267,566 line log file. A sample of the entries look like:

2010-12-14 10:01:47,612 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] currentObject: shows
2010-12-14 10:01:47,612 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] currentObject.getNillableDescriptor(): null
2010-12-14 10:01:47,612 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] workingElements: [programId, programName, rating]
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] currentParent.getParent(): ResultSet
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) Executing instruction NEXT TVDOC.TVGUIDEROOTALL.MAPPINGCLASSES.SHOWS_1
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) NEXT TVDOC.TVGUIDEROOTALL.MAPPINGCLASSES.SHOWS_1
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) Processor Environment popped program w/ recursion count 0 ; 2  programs left.
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) Executing instruction LOOP TVDOC.TVGUIDEROOTALL.MAPPINGCLASSES.SHOWS_1
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) WHILE repeating for result set: TVDOC.TVGUIDEROOTALL.MAPPINGCLASSES.SHOWS_1 , block program: PROGRAM size 7
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) Pushed non-recursive program w/ recursion count 0
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) Executing instruction ELEM shows (namespaces )
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) 
 [showState] State Vars at: addElement(2) - TOP
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] currentParent: producer
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] currentObject: shows
2010-12-14 10:01:47,613 DEBUG [org.teiid.PROCESSOR.XML_PLAN] (Worker28_QueryProcessorQueue599) [showState] currentObject.getNillableDescriptor(): null

Speaking with Ramesh, he suggests possibly moving this type of output to TRACE.
Comment 1 Van Halbert 2010-12-14 18:52:50 UTC 
Link: Added: This issue Cloned from TEIID-1396
Comment 2 Van Halbert 2010-12-14 18:53:51 UTC 
Security: Added: Public
Comment 4 Paul Nittel 2011-02-08 14:57:37 UTC 
Tested with ER9 and closed.