1:31 p.m.
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)