Skip to content

Commit

Permalink
TEIID-2813 adding cpu time to source command log entries
Browse files Browse the repository at this point in the history
  • Loading branch information
shawkins committed Jul 21, 2015
1 parent ef996ff commit f2763d0
Show file tree
Hide file tree
Showing 4 changed files with 125 additions and 11 deletions.
16 changes: 15 additions & 1 deletion api/src/main/java/org/teiid/logging/CommandLogMessage.java
Expand Up @@ -63,6 +63,8 @@ public enum Event {
private String translatorName;
private ExecutionContext executionContext;
private PlanNode plan;

private Long cpuTime;

public CommandLogMessage(long timestamp,
String requestID,
Expand Down Expand Up @@ -149,7 +151,7 @@ public String toString() {
if (event == Event.NEW) {
return "\tSTART DATA SRC COMMAND:\tstartTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\tsourceCommandID="+ sourceCommandID + "\texecutionID="+ executionContext.getExecutionCountIdentifier() + "\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$ //$NON-NLS-10$
}
return "\t"+ event +" SRC COMMAND:\tendTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\tsourceCommandID="+ sourceCommandID + "\texecutionID="+ executionContext.getExecutionCountIdentifier() + "\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$ //$NON-NLS-11$
return "\t"+ event +" SRC COMMAND:\tendTime=" + new Timestamp(timestamp) + "\trequestID=" + requestID + "\tsourceCommandID="+ sourceCommandID + "\texecutionID="+ executionContext.getExecutionCountIdentifier() + "\ttxID=" + transactionID + "\tmodelName="+ modelName + "\ttranslatorName=" + translatorName + "\tsessionID=" + sessionID + "\tprincipal=" + principal + "\tfinalRowCount=" + rowCount + "\tcpuTime(ns)=" + cpuTime; //$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() {
Expand Down Expand Up @@ -228,4 +230,16 @@ public ExecutionContext getExecutionContext() {
public PlanNode getPlan() {
return plan;
}

public void setCpuTime(Long cpuTime) {
this.cpuTime = cpuTime;
}

/**
* the cpu time in nanoseconds
* @return
*/
public Long getCpuTime() {
return cpuTime;
}
}
Expand Up @@ -261,7 +261,7 @@ public void stop() {
* Add begin point to transaction monitoring table.
* @param qr Request that contains the MetaMatrix command information in the transaction.
*/
void logSRCCommand(AtomicRequestMessage qr, ExecutionContext context, Event cmdStatus, Integer finalRowCnt) {
void logSRCCommand(AtomicRequestMessage qr, ExecutionContext context, Event cmdStatus, Integer finalRowCnt, Long cpuTime) {
if (!LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING, MessageLevel.DETAIL)) {
return;
}
Expand All @@ -287,7 +287,8 @@ void logSRCCommand(AtomicRequestMessage qr, ExecutionContext context, Event cmdS
}
else {
message = new CommandLogMessage(System.currentTimeMillis(), qr.getRequestID().toString(), sid.getNodeID(), transactionID, modelName, translatorName, qr.getWorkContext().getSessionId(), principal, finalRowCnt, cmdStatus, context);
}
}
message.setCpuTime(cpuTime);
LogManager.log(MessageLevel.DETAIL, LogConstants.CTX_COMMANDLOGGING, message);
}

Expand Down
Expand Up @@ -125,8 +125,10 @@ public class ConnectorWorkItem implements ConnectorWork {
private boolean areLobsUsableAfterClose;

private TeiidException conversionError;

ConnectorWorkItem(AtomicRequestMessage message, ConnectorManager manager) throws TeiidComponentException {

private ThreadCpuTimer timer = new ThreadCpuTimer();

ConnectorWorkItem(AtomicRequestMessage message, ConnectorManager manager) throws TeiidComponentException {
this.id = message.getAtomicRequestID();
this.requestMsg = message;
this.manager = manager;
Expand Down Expand Up @@ -189,7 +191,7 @@ public void cancel() {
try {
LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Processing CANCEL request"}); //$NON-NLS-1$
if (this.isCancelled.compareAndSet(false, true)) {
this.manager.logSRCCommand(this.requestMsg, this.securityContext, Event.CANCEL, -1);
this.manager.logSRCCommand(this.requestMsg, this.securityContext, Event.CANCEL, -1, null);
if(execution != null) {
execution.cancel();
}
Expand All @@ -212,9 +214,12 @@ public synchronized AtomicResultsMessage more() throws TranslatorException {
}
LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Processing MORE request"}); //$NON-NLS-1$
try {
timer.start();
return handleBatch();
} catch (Throwable t) {
throw handleError(t);
} finally {
timer.stop();
}
}

Expand All @@ -228,10 +233,8 @@ public synchronized void close() {
return; //already closed
}
LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Processing Close :", this.requestMsg.getCommand()}); //$NON-NLS-1$
if (!error) {
manager.logSRCCommand(this.requestMsg, this.securityContext, Event.END, this.rowCount);
}
try {
timer.start();
if (execution != null) {
execution.close();
LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Closed execution"}); //$NON-NLS-1$
Expand All @@ -250,6 +253,10 @@ public synchronized void close() {
}
LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Closed connection"}); //$NON-NLS-1$
}
Long time = timer.stop();
if (!error) {
manager.logSRCCommand(this.requestMsg, this.securityContext, Event.END, this.rowCount, time);
}
}
}

Expand All @@ -261,7 +268,7 @@ private TranslatorException handleError(Throwable t) {
if (t instanceof RuntimeException && t.getCause() != null) {
t = t.getCause();
}
manager.logSRCCommand(this.requestMsg, this.securityContext, Event.ERROR, null);
manager.logSRCCommand(this.requestMsg, this.securityContext, Event.ERROR, null, null);

String msg = QueryPlugin.Util.getString("ConnectorWorker.process_failed", this.id); //$NON-NLS-1$
if (isCancelled.get()) {
Expand Down Expand Up @@ -290,6 +297,7 @@ public synchronized void execute() throws TranslatorException {
if(isCancelled()) {
throw new TranslatorException(QueryPlugin.Event.TEIID30476, QueryPlugin.Util.gs(QueryPlugin.Event.TEIID30476));
}
timer.start();
try {
if (this.execution == null) {
if (this.connection == null) {
Expand Down Expand Up @@ -335,13 +343,15 @@ public synchronized void execute() throws TranslatorException {

LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.requestMsg.getAtomicRequestID(), "Obtained execution"}); //$NON-NLS-1$
//Log the Source Command (Must be after obtaining the execution context)
manager.logSRCCommand(this.requestMsg, this.securityContext, Event.NEW, null);
manager.logSRCCommand(this.requestMsg, this.securityContext, Event.NEW, null, null);
}
// Execute query
this.execution.execute();
LogManager.logDetail(LogConstants.CTX_CONNECTOR, new Object[] {this.id, "Executed command"}); //$NON-NLS-1$
} catch (Throwable t) {
throw handleError(t);
} finally {
timer.stop();
}
}

Expand Down
@@ -0,0 +1,89 @@
/*
* JBoss, Home of Professional Open Source.
* See the COPYRIGHT.txt file distributed with this work for information
* regarding copyright ownership. Some portions may be licensed
* to Red Hat, Inc. under one or more contributor license agreements.
*
* This library is free software; you can redistribute it and/or
* modify it under the terms of the GNU Lesser General Public
* License as published by the Free Software Foundation; either
* version 2.1 of the License, or (at your option) any later version.
*
* This library is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
* Lesser General Public License for more details.
*
* You should have received a copy of the GNU Lesser General Public
* License along with this library; if not, write to the Free Software
* Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
* 02110-1301 USA.
*/

package org.teiid.dqp.internal.datamgr;

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;

import org.teiid.logging.LogConstants;
import org.teiid.logging.LogManager;
import org.teiid.logging.MessageLevel;

/**
* Timer class that uses the ThreadMXBean for CPU timing
*/
public class ThreadCpuTimer {

private static ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
private int totalTime = -1;
private long lastTime = -1;
private boolean active;

public ThreadCpuTimer() {
active = threadMXBean.isThreadCpuTimeSupported()
&& threadMXBean.isThreadCpuTimeEnabled()
&& LogManager.isMessageToBeRecorded(LogConstants.CTX_COMMANDLOGGING, MessageLevel.DETAIL);
}

public void start() {
if (!active) {
return;
}
try {
lastTime = threadMXBean.getCurrentThreadCpuTime();
} catch (UnsupportedOperationException e) {
inactivate();
}

}

private void inactivate() {
active = false;
lastTime = -1;
totalTime = -1;
}

public long stop() {
if (!active) {
return -1;
}
if (lastTime != -1) {
try {
long time = threadMXBean.getCurrentThreadCpuTime();
if (time != -1) {
if (totalTime == -1) {
totalTime = 0;
}
totalTime += (time - lastTime);
} else {
inactivate();
}
} catch (UnsupportedOperationException e) {
inactivate();
}
}
lastTime = -1;
return totalTime;
}

}

0 comments on commit f2763d0

Please sign in to comment.