Author: shawkins Date: 2012-04-05 14:31:17 -0400 (Thu, 05 Apr 2012) New Revision: 3975 Modified: branches/7.7.x/api/src/main/java/org/teiid/logging/CommandLogMessage.java branches/7.7.x/client/src/main/java/org/teiid/adminapi/impl/DQPManagement.java branches/7.7.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java branches/7.7.x/engine/src/main/java/org/teiid/query/analysis/AnalysisRecord.java branches/7.7.x/engine/src/main/java/org/teiid/query/processor/DdlPlan.java branches/7.7.x/engine/src/main/java/org/teiid/query/processor/proc/ForEachRowPlan.java branches/7.7.x/jboss-integration/src/main/java/org/teiid/jboss/deployers/RuntimeEngineDeployer.java Log: TEIID-1985 adding an admin method to get plans and adding plan information to the comand log at a trace level Modified: branches/7.7.x/api/src/main/java/org/teiid/logging/CommandLogMessage.java =================================================================== --- branches/7.7.x/api/src/main/java/org/teiid/logging/CommandLogMessage.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/api/src/main/java/org/teiid/logging/CommandLogMessage.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -24,6 +24,7 @@ import java.sql.Timestamp; +import org.teiid.client.plan.PlanNode; import org.teiid.translator.ExecutionContext; /** @@ -33,6 +34,7 @@ public enum Event { NEW, + PLAN, END, CANCEL, ERROR @@ -60,6 +62,7 @@ private String modelName; private String translatorName; private ExecutionContext executionContext; + private PlanNode plan; public CommandLogMessage(long timestamp, String requestID, @@ -71,7 +74,7 @@ int vdbVersion, String sql) { // userCommandStart - this(timestamp, requestID, transactionID, sessionID, principal, vdbName, vdbVersion, null, Event.NEW); + this(timestamp, requestID, transactionID, sessionID, principal, vdbName, vdbVersion, null, Event.NEW, null); this.applicationName = applicationName; this.sql = sql; } @@ -83,7 +86,7 @@ String vdbName, int vdbVersion, Integer finalRowCount, - Event event) { + Event event, PlanNode plan) { // userCommandEnd this.event = event; this.timestamp = timestamp; @@ -94,6 +97,7 @@ this.vdbName = vdbName; this.vdbVersion = vdbVersion; this.rowCount = finalRowCount; + this.plan = plan; } public CommandLogMessage(long timestamp, String requestID, @@ -136,16 +140,16 @@ } public String toString() { - if (!source && event == Event.NEW) { - return "\tSTART USER COMMAND:\tstartTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\ttxID=" + transactionID + "\tsessionID=" + sessionID + "\tapplicationName=" + applicationName + "\tprincipal=" + principal + "\tvdbName=" + vdbName + "\tvdbVersion=" + vdbVersion + "\tsql=" + sql; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$//$NON-NLS-5$ //$NON-NLS-6$ //$NON-NLS-7$ //$NON-NLS-8$ //$NON-NLS-9$ - } if (!source) { + if (event == Event.NEW) { + return "\tSTART USER COMMAND:\tstartTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\ttxID=" + transactionID + "\tsessionID=" + sessionID + "\tapplicationName=" + applicationName + "\tprincipal=" + principal + "\tvdbName=" + vdbName + "\tvdbVersion=" + vdbVersion + "\tsql=" + sql; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$//$NON-NLS-5$ //$NON-NLS-6$ //$NON-NLS-7$ //$NON-NLS-8$ //$NON-NLS-9$ + } return "\t"+ event +" USER COMMAND:\tendTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\ttxID=" + transactionID + "\tsessionID=" + sessionID + "\tprincipal=" + principal + "\tvdbName=" + vdbName + "\tvdbVersion=" + vdbVersion + "\tfinalRowCount=" + rowCount; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$//$NON-NLS-5$ //$NON-NLS-6$ //$NON-NLS-7$ //$NON-NLS-8$ //$NON-NLS-9$ } if (event == Event.NEW) { return "\tSTART DATA SRC COMMAND:\tstartTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\tsourceCommandID="+ sourceCommandID + "\ttxID=" + transactionID + "\tmodelName="+ modelName + "\ttranslatorName=" + translatorName + "\tsessionID=" + sessionID + "\tprincipal=" + principal + "\tsql=" + sql; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$//$NON-NLS-5$ //$NON-NLS-6$ //$NON-NLS-7$ //$NON-NLS-8$ //$NON-NLS-9$ } - return "\t"+ event +" SRC COMMAND:\tendTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\tsourceCommandID="+ sourceCommandID + "\ttxID=" + transactionID + "\tmodelName="+ modelName + "\ttranslatorName=" + translatorName + "\tsessionID=" + sessionID + "\tprincipal=" + principal + "\tfinalRowCount=" + rowCount; //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$//$NON-NLS-5$ //$NON-NLS-6$ //$NON-NLS-7$ //$NON-NLS-8$ //$NON-NLS-9$ //$NON-NLS-10$ + return "\t"+ event +" SRC COMMAND:\tendTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\tsourceCommandID="+ sourceCommandID + "\ttxID=" + transactionID + "\tmodelName="+ modelName + "\ttranslatorName=" + translatorName + "\tsessionID=" + sessionID + "\tprincipal=" + principal + "\tfinalRowCount=" + rowCount + (plan!=null?"\tplan=" + plan:""); //$NON-NLS-1$ //$NON-NLS-2$ //$NON-NLS-3$ //$NON-NLS-4$//$NON-NLS-5$ //$NON-NLS-6$ //$NON-NLS-7$ //$NON-NLS-8$ //$NON-NLS-9$ //$NON-NLS-10$ //$NON-NLS-11$ //$NON-NLS-12$ } public long getTimestamp() { @@ -216,5 +220,12 @@ */ public ExecutionContext getExecutionContext() { return executionContext; - } + } + /** + * Only available for user commands after the NEW event + * @return + */ + public PlanNode getPlan() { + return plan; + } } Modified: branches/7.7.x/client/src/main/java/org/teiid/adminapi/impl/DQPManagement.java =================================================================== --- branches/7.7.x/client/src/main/java/org/teiid/adminapi/impl/DQPManagement.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/client/src/main/java/org/teiid/adminapi/impl/DQPManagement.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -25,6 +25,7 @@ import java.util.List; import org.teiid.adminapi.AdminException; +import org.teiid.client.plan.PlanNode; public interface DQPManagement { @@ -45,4 +46,12 @@ List<RequestMetadata> getRequestsUsingVDB(String vdbName, int vdbVersion) throws AdminException; CacheStatisticsMetadata getCacheStatistics(String cacheType); List<List> executeQuery(String vdbName, int version, String command, long timoutInMilli) throws AdminException; + /** + * + * @param sessionId + * @param requestId + * @return the plan or null if the request does not exist + * @throws AdminException + */ + PlanNode getPlan(String sessionId, long requestId) throws AdminException; } Modified: branches/7.7.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml =================================================================== --- branches/7.7.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml 2012-04-05 18:31:17 UTC (rev 3975) @@ -35,7 +35,9 @@ If you want to build a custom appender for command logging that will have access to log4j "LoggingEvents" to the "COMMAND_LOG" context, the appender will receive a message that is an instance of <code>org.teiid.logging.CommandLogMessage</code>. The relevant Teiid classes are defined in the <code>teiid-api-&versionNumber;.jar</code>. - The CommmdLogMessage includes information about vdb, session, command sql, etc. CommandLogMessages are logged at the DEBUG level. + The CommmdLogMessage includes information about vdb, session, command sql, etc. CommandLogMessages are logged at the DEBUG level. If the COMMAND_LOG is at the TRACE level, + then CommandLogMessages will also contain the query plan for user queries after the NEW event. A typical event sequence is user query NEW, optional user query PLAN, some number of source query NEW/END, then the user query END. + CANCEL and ERROR events are also captured. </para> <example> <title>Sample CommandLogMessage Usage</title> Modified: branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/DQPCore.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -54,6 +54,7 @@ import org.teiid.client.ResultsMessage; import org.teiid.client.lob.LobChunk; import org.teiid.client.metadata.MetadataResult; +import org.teiid.client.plan.PlanNode; import org.teiid.client.util.ResultsFuture; import org.teiid.client.util.ResultsReceiver; import org.teiid.client.xa.XATransactionException; @@ -80,6 +81,7 @@ import org.teiid.logging.CommandLogMessage.Event; import org.teiid.metadata.MetadataRepository; import org.teiid.query.QueryPlugin; +import org.teiid.query.processor.QueryProcessor; import org.teiid.query.tempdata.TempTableDataManager; import org.teiid.query.tempdata.TempTableStore; import org.teiid.query.tempdata.TempTableStore.TransactionMode; @@ -545,6 +547,22 @@ return cancelRequest(requestID); } + public PlanNode getPlan(String sessionId, long executionId) { + RequestID requestID = new RequestID(sessionId, executionId); + if (LogManager.isMessageToBeRecorded(LogConstants.CTX_DQP, MessageLevel.DETAIL)) { + LogManager.logDetail(LogConstants.CTX_DQP, "getPlan for requestID=" + requestID); //$NON-NLS-1$ + } + RequestWorkItem workItem = safeGetWorkItem(requestID); + if (workItem == null) { + return null; + } + QueryProcessor qp = workItem.getProcessor(); + if (qp == null) { + return null; + } + return qp.getProcessorPlan().getDescriptionProperties(); + } + private boolean cancelRequest(RequestID requestID) throws TeiidComponentException { if (LogManager.isMessageToBeRecorded(LogConstants.CTX_DQP, MessageLevel.DETAIL)) { LogManager.logDetail(LogConstants.CTX_DQP, "cancelQuery for requestID=" + requestID); //$NON-NLS-1$ @@ -672,13 +690,14 @@ } void logMMCommand(RequestWorkItem workItem, Event status, Integer rowCount) { - if (!LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING, MessageLevel.DETAIL)) { + if ((status != Event.PLAN && !LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING, MessageLevel.DETAIL)) + || !LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING, MessageLevel.TRACE)) { return; } RequestMessage msg = workItem.requestMsg; DQPWorkContext workContext = DQPWorkContext.getWorkContext(); - RequestID rID = new RequestID(workContext.getSessionId(), msg.getExecutionId()); + RequestID rID = workItem.requestID; String txnID = null; TransactionContext tc = workItem.getTransactionContext(); if (tc != null && tc.getTransactionType() != Scope.NONE) { @@ -690,7 +709,12 @@ if (status == Event.NEW) { message = new CommandLogMessage(System.currentTimeMillis(), rID.toString(), txnID, workContext.getSessionId(), appName, workContext.getUserName(), workContext.getVdbName(), workContext.getVdbVersion(), msg.getCommandString()); } else { - message = new CommandLogMessage(System.currentTimeMillis(), rID.toString(), txnID, workContext.getSessionId(), workContext.getUserName(), workContext.getVdbName(), workContext.getVdbVersion(), rowCount, status); + QueryProcessor qp = workItem.getProcessor(); + PlanNode plan = null; + if (LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING, MessageLevel.TRACE) && qp != null) { + plan = qp.getProcessorPlan().getDescriptionProperties(); + } + message = new CommandLogMessage(System.currentTimeMillis(), rID.toString(), txnID, workContext.getSessionId(), workContext.getUserName(), workContext.getVdbName(), workContext.getVdbVersion(), rowCount, status, plan); } LogManager.log(MessageLevel.DETAIL, LogConstants.CTX_COMMANDLOGGING, message); } Modified: branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -521,6 +521,7 @@ request.processor.getContext().setDataObjects(new HashSet<Object>(4)); } processor = request.processor; + this.dqpCore.logMMCommand(this, Event.PLAN, null); collector = new BatchCollector(processor, processor.getBufferManager(), this.request.context, isForwardOnly()) { protected void flushBatchDirect(TupleBatch batch, boolean add) throws TeiidComponentException,TeiidProcessingException { resultsBuffer = getTupleBuffer(); @@ -709,11 +710,12 @@ } response.setPlanDescription(analysisRecord.getQueryPlan()); response.setAnnotations(analysisRecord.getAnnotations()); + analysisRecord.getAnnotations().clear(); } if (requestMsg.getShowPlan() == ShowPlan.DEBUG) { response.setDebugLog(analysisRecord.getDebugLog()); + analysisRecord.stopDebugLog(); } - this.analysisRecord = null; } } @@ -974,5 +976,9 @@ public void setCancelTask(Task cancelTask) { this.cancelTask = cancelTask; } + + public QueryProcessor getProcessor() { + return processor; + } } \ No newline at end of file Modified: branches/7.7.x/engine/src/main/java/org/teiid/query/analysis/AnalysisRecord.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/query/analysis/AnalysisRecord.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/engine/src/main/java/org/teiid/query/analysis/AnalysisRecord.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -201,6 +201,11 @@ } return null; } + + public void stopDebugLog() { + this.stringWriter = null; + this.recordDebug = false; + } /** * Helper method to turn a list of projected symbols into a suitable list of Modified: branches/7.7.x/engine/src/main/java/org/teiid/query/processor/DdlPlan.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/query/processor/DdlPlan.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/engine/src/main/java/org/teiid/query/processor/DdlPlan.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -225,4 +225,9 @@ return props; } + @Override + public String toString() { + return command.toString(); + } + } Modified: branches/7.7.x/engine/src/main/java/org/teiid/query/processor/proc/ForEachRowPlan.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/query/processor/proc/ForEachRowPlan.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/engine/src/main/java/org/teiid/query/processor/proc/ForEachRowPlan.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -162,4 +162,13 @@ return true; } + @Override + public String toString() { + StringBuilder val = new StringBuilder("ForEach "); //$NON-NLS-1$ + val.append(this.queryPlan).append("\n{\n"); //$NON-NLS-1$ + val.append(this.rowProcedure); + val.append("}\n"); //$NON-NLS-1$ + return val.toString(); + } + } Modified: branches/7.7.x/jboss-integration/src/main/java/org/teiid/jboss/deployers/RuntimeEngineDeployer.java =================================================================== --- branches/7.7.x/jboss-integration/src/main/java/org/teiid/jboss/deployers/RuntimeEngineDeployer.java 2012-04-05 14:47:26 UTC (rev 3974) +++ branches/7.7.x/jboss-integration/src/main/java/org/teiid/jboss/deployers/RuntimeEngineDeployer.java 2012-04-05 18:31:17 UTC (rev 3975) @@ -75,6 +75,7 @@ import org.teiid.client.DQP; import org.teiid.client.RequestMessage; import org.teiid.client.ResultsMessage; +import org.teiid.client.plan.PlanNode; import org.teiid.client.security.ILogon; import org.teiid.client.security.InvalidSessionException; import org.teiid.client.util.ExceptionUtil; @@ -512,6 +513,12 @@ throw new AdminComponentException(e); } } + + @Override + @ManagementOperation(description="Get a plan for the request",params={@ManagementParameter(name="sessionId",description="The session Identifier"), @ManagementParameter(name="executionId",description="The Execution Identifier")}) + public PlanNode getPlan(String sessionId, long executionId) throws AdminException { + return this.dqpCore.getPlan(sessionId, executionId); + } @Override @ManagementOperation(description="Get Cache types in the system", impact=Impact.ReadOnly)