Skip to content

Commit

Permalink
Add ci.queue_time for pipeline/stage/job traces (#159)
Browse files Browse the repository at this point in the history
* Send ci.queue_time in Jenkins Build/Pipelines

* Remove unnecesary empty lines

* Add docs

* Remove unnecesary imports

* Propagate queue time

* Add tests queue time

* BuildData queue time

* Remove unnecesary system.out

* Propagate queue time only in Start Pipeline or Stages nodes
  • Loading branch information
drodriguezhdez committed Dec 15, 2020
1 parent 285f3ba commit bf8eb41
Show file tree
Hide file tree
Showing 15 changed files with 539 additions and 31 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,6 @@ of this software and associated documentation files (the "Software"), to deal
import org.datadog.jenkins.plugins.datadog.events.BuildFinishedEventImpl;
import org.datadog.jenkins.plugins.datadog.events.BuildStartedEventImpl;
import org.datadog.jenkins.plugins.datadog.model.BuildData;
import org.datadog.jenkins.plugins.datadog.model.TimeInQueueAction;
import org.datadog.jenkins.plugins.datadog.traces.BuildSpanAction;
import org.jenkinsci.plugins.workflow.job.WorkflowRun;

Expand Down Expand Up @@ -195,7 +194,11 @@ public void onStarted(Run run, TaskListener listener) {
try {
long waiting = (DatadogUtilities.currentTimeMillis() - item.getInQueueSince()) / 1000;
client.gauge("jenkins.job.waiting", waiting, hostname, tags);
run.addAction(new TimeInQueueAction(waiting));

final BuildSpanAction buildSpanAction = run.getAction(BuildSpanAction.class);
if(buildSpanAction != null && buildSpanAction.getBuildData() != null) {
buildSpanAction.getBuildData().setSecondsInQueue(waiting);
}
} catch (NullPointerException e) {
logger.warning("Unable to compute 'waiting' metric. " +
"item.getInQueueSince() unavailable, possibly due to worker instance provisioning");
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,133 @@
package org.datadog.jenkins.plugins.datadog.listeners;

import hudson.Extension;
import hudson.model.Queue;
import hudson.model.Run;
import hudson.model.queue.QueueListener;
import org.datadog.jenkins.plugins.datadog.model.FlowNodeQueueData;
import org.datadog.jenkins.plugins.datadog.model.PipelineQueueInfoAction;
import org.jenkinsci.plugins.workflow.flow.FlowExecution;
import org.jenkinsci.plugins.workflow.graph.FlowNode;
import org.jenkinsci.plugins.workflow.support.steps.ExecutorStepExecution;

import javax.annotation.CheckForNull;
import java.io.IOException;
import java.util.logging.Logger;

@Extension
public class DatadogQueueListener extends QueueListener {

private static final Logger logger = Logger.getLogger(DatadogQueueListener.class.getName());

@Override
public void onEnterBuildable(Queue.BuildableItem item) {
try {
final Queue.Task task = item.task;
if(task == null) {
logger.fine("onEnterBuildable: item: " + item + ", task is null");
return;
}

if(!(task instanceof ExecutorStepExecution.PlaceholderTask)) {
logger.fine("onEnterBuildable: item: " + item + ", task:" + task + " is not ExecutorStepExecution.PlaceholderTask: " + task.getClass() );
return;
}

final ExecutorStepExecution.PlaceholderTask placeholderTask = (ExecutorStepExecution.PlaceholderTask) task;
final FlowNode flowNode = placeholderTask.getNode();

if(flowNode == null) {
logger.fine("onEnterBuildable PlaceholderTask: " + placeholderTask + ", FlowNode: is null");
return;
}

final Run<?,?> run = runFor(flowNode.getExecution());
if(run == null) {
logger.fine("onEnterBuildable FlowNode: " + flowNode + ", run is null.");
return;
}

final PipelineQueueInfoAction queueAction = run.getAction(PipelineQueueInfoAction.class);
if(queueAction == null){
logger.fine("onEnterBuildable: queueAction: is null");
return;
}

final FlowNodeQueueData flowNodeData = queueAction.get(flowNode.getId());
if(flowNodeData != null) {
flowNodeData.setEnterBuildable(System.currentTimeMillis());
} else {
final FlowNodeQueueData data = new FlowNodeQueueData(flowNode.getId());
data.setEnterBuildable(System.currentTimeMillis());
queueAction.put(flowNode.getId(), data);
}

} catch (Exception e){
logger.severe("Error onEnterBuildable: item:" + item + ", exception: " + e);
}

}

@Override
public void onLeaveBuildable(Queue.BuildableItem item) {
try {
final Queue.Task task = item.task;
if(task == null) {
logger.fine("onLeaveBuildable: item: " + item + ", task is null");
return;
}

if(!(task instanceof ExecutorStepExecution.PlaceholderTask)) {
logger.fine("onLeaveBuildable: item: " + item + ", task:" + task + " is not ExecutorStepExecution.PlaceholderTask: " + task.getClass() );
return;
}

final ExecutorStepExecution.PlaceholderTask placeholderTask = (ExecutorStepExecution.PlaceholderTask) task;
final FlowNode flowNode = placeholderTask.getNode();
if(flowNode == null) {
logger.fine("onLeaveBuildable PlaceholderTask: " + placeholderTask + ", FlowNode: is null");
return;
}

Run<?,?> run = runFor(flowNode.getExecution());
if(run == null) {
logger.fine("onLeaveBuildable FlowNode: " + flowNode + ", run is null.");
return;
}

PipelineQueueInfoAction queueAction = run.getAction(PipelineQueueInfoAction.class);
if(queueAction == null){
logger.fine("onLeaveBuildable: queueAction: is null");
return;
}

final FlowNodeQueueData flowNodeData = queueAction.get(flowNode.getId());
if(flowNodeData != null) {
flowNodeData.setLeaveBuildable(System.currentTimeMillis());
}
} catch (Exception e){
logger.severe("Error onLeaveBuildable: item:" + item + ", exception: " + e);
}
}

/**
* Gets the jenkins run object of the specified executing workflow.
*
* @param exec execution of a workflow
* @return jenkins run object of a job
*/
private static @CheckForNull
Run<?, ?> runFor(FlowExecution exec) {
Queue.Executable executable;
try {
executable = exec.getOwner().getExecutable();
} catch (IOException x) {
return null;
}
if (executable instanceof Run) {
return (Run<?, ?>) executable;
} else {
return null;
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -100,6 +100,8 @@ public class BuildData implements Serializable {
private Long startTime;
private Long endTime;
private Long duration;
private Long secondsInQueue;
private Long propagatedSecondsInQueue;

private String traceId;
private String spanId;
Expand Down Expand Up @@ -382,6 +384,22 @@ public void setStartTime(Long startTime) {
this.startTime = startTime;
}

public Long getSecondsInQueue(Long value) {
return defaultIfNull(secondsInQueue, value);
}

public void setSecondsInQueue(Long secondsInQueue) {
this.secondsInQueue = secondsInQueue;
}

public Long getPropagatedSecondsInQueue(Long value) {
return defaultIfNull(propagatedSecondsInQueue, value);
}

public void setPropagatedSecondsInQueue(Long propagatedSecondsInQueue) {
this.propagatedSecondsInQueue = propagatedSecondsInQueue;
}

public String getBuildId(String value) {
return defaultIfNull(buildId, value);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -114,6 +114,18 @@ private void completeInformation(final List<BuildPipelineNode> nodes, final Buil
}
}

// Propagate queue time from "Allocate node" child:
// If the node is the initial (Start of Pipeline) or is a Stage,
// we need to propagate the queue time stored in its child node ("Allocate node").
// This is necessary because the stage/pipeline node does not have the queue time itself,
// but it's stored in the "Allocate node" which is its child.
if((node.isInitial() || BuildPipelineNode.NodeType.STAGE.equals(node.getType())) && node.getChildren().size() == 1){
BuildPipelineNode child = node.getChildren().get(0);
if(child.getName().contains("Allocate node")) {
node.setPropagatedSecondsInQueue(child.getSecondsInQueue());
}
}

completeInformation(node.getChildren(), node);
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -64,6 +64,7 @@ public String getBuildLevel() {

private NodeType type;
private boolean internal;
private boolean initial;
private Map<String, Object> args = new HashMap<>();
private Map<String, String> envVars = new HashMap<>();
private String workspace;
Expand All @@ -74,6 +75,8 @@ public String getBuildLevel() {
private long startTimeMicros;
private long endTime;
private long endTimeMicros;
private long secondsInQueue = -1L;
private long propagatedSecondsInQueue = -1L;
private String result;

// Flag that indicates if the node must be marked as error.
Expand Down Expand Up @@ -114,6 +117,7 @@ public BuildPipelineNode(final BlockEndNode endNode) {
// the pipeline node span is a child of the build span.
this.type = NodeType.STEP;
this.internal = true;
this.initial = true;
} else if(DatadogUtilities.isStageNode(startNode)){
this.type = NodeType.STAGE;
this.internal = false;
Expand All @@ -133,7 +137,11 @@ public BuildPipelineNode(final BlockEndNode endNode) {
this.nodeHostname = stepData.getNodeHostname();
this.generatedSpanId = getGeneratedSpanId(endNode);
}
}

final FlowNodeQueueData queueData = getQueueData(startNode);
if(queueData != null) {
this.secondsInQueue = queueData.getSecondsInQueue();
}

this.logText = getLogText(endNode);
Expand All @@ -148,6 +156,8 @@ public BuildPipelineNode(final BlockEndNode endNode) {
}
}



private DDId getGeneratedSpanId(final FlowNode node) {
GeneratedSpanIdAction action = node.getAction(GeneratedSpanIdAction.class);
if(action == null && node instanceof BlockEndNode) {
Expand Down Expand Up @@ -176,6 +186,11 @@ public BuildPipelineNode(final StepAtomNode stepNode) {
this.generatedSpanId = getGeneratedSpanId(stepNode);
}

final FlowNodeQueueData queueData = getQueueData(stepNode);
if(queueData != null) {
this.secondsInQueue = queueData.getSecondsInQueue();
}

this.logText = getLogText(stepNode);
this.startTime = getTime(stepNode);
this.startTimeMicros = this.startTime * 1000;
Expand All @@ -188,6 +203,7 @@ public BuildPipelineNode(final StepAtomNode stepNode) {
}
}


public BuildPipelineNodeKey getKey() {
return key;
}
Expand All @@ -212,6 +228,10 @@ public boolean isInternal() {
return internal;
}

public boolean isInitial() {
return initial;
}

public Map<String, Object> getArgs() {
return args;
}
Expand Down Expand Up @@ -252,11 +272,27 @@ public long getEndTimeMicros() {
return endTimeMicros;
}

public long getSecondsInQueue() {
return secondsInQueue;
}

public void setEndTime(long endTime) {
this.endTime = endTime;
this.endTimeMicros = this.endTime * 1000;
}

public void setSecondsInQueue(long secondsInQueue) {
this.secondsInQueue = secondsInQueue;
}

public long getPropagatedSecondsInQueue() {
return propagatedSecondsInQueue;
}

public void setPropagatedSecondsInQueue(long propagatedSecondsInQueue) {
this.propagatedSecondsInQueue = propagatedSecondsInQueue;
}

public String getResult() {
return result;
}
Expand Down Expand Up @@ -302,6 +338,7 @@ public void updateData(final BuildPipelineNode buildNode) {
this.stageName = buildNode.stageName;
this.type = buildNode.type;
this.internal = buildNode.internal;
this.initial = buildNode.initial;
this.args = buildNode.args;
this.envVars = buildNode.envVars;
this.workspace = buildNode.workspace;
Expand All @@ -312,6 +349,7 @@ public void updateData(final BuildPipelineNode buildNode) {
this.startTimeMicros = buildNode.startTimeMicros;
this.endTime = buildNode.endTime;
this.endTimeMicros = buildNode.endTimeMicros;
this.secondsInQueue = buildNode.secondsInQueue;
this.result = buildNode.result;
this.error = buildNode.error;
this.errorObj = buildNode.errorObj;
Expand Down Expand Up @@ -392,6 +430,22 @@ private StepData getStepData(final FlowNode node) {
return stepDataAction.get(((StepNode) node).getDescriptor());
}

private FlowNodeQueueData getQueueData(FlowNode node) {
final Run<?, ?> run = getRun(node);
if(run == null) {
logger.fine("Unable to get QueueData from node '"+node.getDisplayName()+"'. Run is null");
return null;
}

PipelineQueueInfoAction pipelineQueueInfoAction = run.getAction(PipelineQueueInfoAction.class);
if (pipelineQueueInfoAction == null) {
logger.fine("Unable to get QueueInfoAction from node '"+node.getDisplayName()+"'. QueueInfoAction is null");
return null;
}

return pipelineQueueInfoAction.get(node.getId());
}

private Run<?, ?> getRun(final FlowNode node) {
if(node == null || node.getExecution() == null || node.getExecution().getOwner() == null) {
return null;
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
package org.datadog.jenkins.plugins.datadog.model;

import java.io.Serializable;
import java.util.concurrent.TimeUnit;

/**
* Keeps the timestamps of a certain FlowNode based on the onEnterBuildable and onLeaveBuildable callbacks.
*/
public class FlowNodeQueueData implements Serializable {

private static final long serialVersionUID = 1L;

private final String nodeId;
private long enterBuildable;
private long leaveBuildable;

public FlowNodeQueueData(final String nodeId) {
this.nodeId = nodeId;
}

public void setEnterBuildable(long timestamp) {
this.enterBuildable = timestamp;
}

public void setLeaveBuildable(long timestamp) {
this.leaveBuildable = timestamp;
}

public long getSecondsInQueue() {
return TimeUnit.MILLISECONDS.toSeconds(this.leaveBuildable - enterBuildable);
}

@Override
public String toString() {
final StringBuilder sb = new StringBuilder("FlowNodeQueueData{");
sb.append("nodeId=").append(nodeId);
sb.append(", enterBuildable=").append(enterBuildable);
sb.append(", leaveBuildable=").append(leaveBuildable);
sb.append('}');
return sb.toString();
}
}
Loading

0 comments on commit bf8eb41

Please sign in to comment.