KBEC-00232 - CloudBees CD (CloudBees Flow) timestamps with additional interpretation

Article ID:360033192191
2 minute readKnowledge base
On this page


Some timestamps need interpretation.

Step start time

The start time of the step is the server time when the server reads the packet from the agent saying the step has started - not the time the Server asks the agent to start the step nor the agent time when it starts the step.

Knowing this information, there are several reasons the agent step could be running before the step start time is recorded.

  1. The agent thread doesn’t get time immediately to send the network message because of a busy agent.

  2. Delays in network packets

  3. The CloudBees CD (CloudBees Flow) Server is busy and doesn’t get to the packet immediately - for example, during java (JRE) garbage collection.

  4. In CloudBees CD (CloudBees Flow) v3.10, the CloudBees CD (CloudBees Flow) server was changed to retry steps that open the workspace directory and fail. The retry change affected when the CloudBees CD (CloudBees Flow) Server records the step start times.

Calculating time it takes to start a job

Use the first step "start" (/myParent/start) property and subtract the job "createTime" (/myJob/createTime) property.

Job Total Wait time is the sum of Resource and Workspace wait time for all steps

The total job wait time, totalWaitTime, is a sum of each of the step wait times.

If you drill down, you’ll see the "true" wait times for individual steps.

There are two parts of a step wait time, the resource wait and the workspace wait.

When you run parallel steps, their wait times are be summarized as well.

Job step duration and wait time trend report in SQL

Here is a SQL query (for Mysql) that will give the number of jobs, job steps, duration of job steps, and job step wait time by month.

First, it goes through the whole job step table and rolls up all the job step data by job ID. This is necessary for accurate counting because job steps and/or jobs may cross a month boundary and we don’t want to count them in more than one month. Then its just a matter of rolling all that job-level data by month.

SELECT    job_step_start_year_month AS job_step_start_year_month,    COUNT(job_id) AS num_jobs,    SUM(num_job_steps) AS num_job_steps,    SUM(job_step_duration_millis) AS job_step_duration_millis,    SUM(job_step_wait_millis) AS job_step_wait_millisFROM(SELECT    job_id,    MIN(EXTRACT(YEAR_MONTH FROM start_time)) AS job_step_start_year_month,    MIN(start_time) AS job_step_start_time,    MAX(finish_time) AS job_step_finish_time,    COUNT(0) AS num_job_steps,    SUM(finish_millis-start_millis) AS job_step_duration_millis,    SUM(start_millis-runnable_millis) AS job_step_wait_millis    FROM ec_job_step    WHERE parent_id IS NOT NULL    GROUP BY job_id) job_stepsWHERE job_step_start_time BETWEEN '2009-01-01' AND '2009-12-31'GROUP BY job_step_start_year_monthORDER BY job_step_start_year_month;

Sample results

job_step_start_year_month     num_jobs    num_job_steps     job_step_duration_millis      job_step_wait_millis200910      48    48    905255      208722200911      47    47    4068123     49971200912      17    46    281313      460393