Gocd: Delay in scheduling between pipelines

[arvindsv]

This shows a delay in scheduling, dependent on MDU.

Logs are broken up, with some notes, below. Raw logs and config are also shown below:

============ START ============
2015-06-23 12:01:04,234  INFO [89@MessageListener for MaterialUpdateListener] ScmMaterialUpdater:62 - [Material Update] Found '1' modifications for material 'GitMaterial{url=/tmp/test.git, branch='master', submoduleFolder='null'}' with flyweight 'f0ca7d2cb50afd6d409a5fa857400f10ca4e629ad1850c4784cbcfaba3d14249' using working directory '/Users/aravindsv/projects/go/gocd/target/go-server-15.2.0/pipelines/flyweight/66e5b44d-9c5a-4791-8d88-d9624b92d5ed'

MDU finds a commit.
============  END  ============


============ START ============
2015-06-23 12:01:14,188  INFO [consumeBuildCausesThread] ScheduleService:156 - [Pipeline Schedule] Scheduling pipeline Test1 with build cause [ModificationBuildCause: modified by Aravind SV <[email protected]>]
2015-06-23 12:01:14,200  INFO [consumeBuildCausesThread] PipelineRepository:84 - Start updating pipeline timeline
2015-06-23 12:01:14,206  INFO [consumeBuildCausesThread] PipelineRepository:88 - Pipeline timeline updated

Scheduler schedules pipeline Test1.
============  END  ============


============ START ============
2015-06-23 12:01:14,212  INFO [consumeBuildCausesThread] ScheduleService:156 - [Pipeline Schedule] Scheduling pipeline Test2 with build cause [ModificationBuildCause: modified by Aravind SV <[email protected]>]
2015-06-23 12:01:14,218  INFO [consumeBuildCausesThread] PipelineRepository:84 - Start updating pipeline timeline
2015-06-23 12:01:14,220  INFO [consumeBuildCausesThread] PipelineRepository:88 - Pipeline timeline updated

Scheduler schedules pipeline Test2.
============  END  ============


============ START ============
2015-06-23 12:01:19,978  INFO [72@MessageListener for WorkFinder] BuildAssignmentService:110 - [Agent Assignment] Assigned job [JobIdentifier[Test1, 6, 6, defaultStage, 1, defaultJob, 15]] to agent [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d]]
2015-06-23 12:01:20,042  INFO [72@MessageListener for WorkFinder] BuildAssignmentService:110 - [Agent Assignment] Assigned job [JobIdentifier[Test2, 6, 6, defaultStage, 1, defaultJob, 16]] to agent [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85]]

Jobs are assigned to agents (two, in this case).
============  END  ============


============ START ============
2015-06-23 12:01:29,998  INFO [qtp239360649-32] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Preparing] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,491  INFO [qtp239360649-20] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Building] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,615  INFO [qtp239360649-28] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting result [Passed] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,634  INFO [qtp239360649-29] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Completing] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,645  INFO [qtp239360649-24] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status and result [Completed, Passed] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,661  INFO [qtp239360649-24] Stage:218 - Stage is being completed by transition id: 94

Agent 1 starts and finishes pipeline Test1 (has only one stage) at 12:01:30,661.
============  END  ============


============ START ============
2015-06-23 12:01:30,061  INFO [qtp239360649-30] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status [Preparing] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,562  INFO [qtp239360649-27] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status [Building] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,701  INFO [qtp239360649-33] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting result [Passed] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,717  INFO [qtp239360649-26] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status [Completing] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,726  INFO [qtp239360649-14] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status and result [Completed, Passed] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,746  INFO [qtp239360649-14] Stage:218 - Stage is being completed by transition id: 96

Agent 2 starts and finishes pipeline Test2 (has only one stage) at 12:01:30,746.
============  END  ============


============ START ============
2015-06-23 12:02:33,918  INFO [93@MessageListener for MaterialUpdateListener] MaterialRepository:468 - Saving revision [DependencyMaterial{pipelineName='Test2', stageName='defaultStage'}, DependencyMaterialRevision[Test2/6/defaultStage/1] [pipelineLabel = 6];[Last Modified: 2015/06/23 12:01:30
Revision: Test2/6/defaultStage/1
UserName: Unknown
EmailAddress: null
Comment: Unknown
PipelineLabel: 6
]]
2015-06-23 12:02:33,918  INFO [91@MessageListener for MaterialUpdateListener] MaterialRepository:468 - Saving revision [DependencyMaterial{pipelineName='Test1', stageName='defaultStage'}, DependencyMaterialRevision[Test1/6/defaultStage/1] [pipelineLabel = 6];[Last Modified: 2015/06/23 12:01:30
Revision: Test1/6/defaultStage/1
UserName: Unknown
EmailAddress: null
Comment: Unknown
PipelineLabel: 6
]]

Big delay waiting for next run of MDU. In this case, 63 seconds. That run of MDU
"sees" the two stages which finished.
============  END  ============


============ START ============
2015-06-23 12:02:34,434  INFO [consumeBuildCausesThread] ScheduleService:156 - [Pipeline Schedule] Scheduling pipeline Test-Down with build cause [ModificationBuildCause: triggered by Test1/6/defaultStage/1]
2015-06-23 12:02:34,446  INFO [consumeBuildCausesThread] PipelineRepository:84 - Start updating pipeline timeline
2015-06-23 12:02:34,451  INFO [consumeBuildCausesThread] PipelineRepository:88 - Pipeline timeline updated
2015-06-23 12:02:40,001  INFO [72@MessageListener for WorkFinder] BuildAssignmentService:110 - [Agent Assignment] Assigned job [JobIdentifier[Test-Down, 5, 5, defaultStage, 1, defaultJob, 17]] to agent [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d]]
2015-06-23 12:02:50,010  INFO [qtp239360649-24] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Preparing] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,025  INFO [qtp239360649-20] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Building] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,152  INFO [qtp239360649-28] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting result [Passed] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,172  INFO [qtp239360649-32] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Completing] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,181  INFO [qtp239360649-33] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status and result [Completed, Passed] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,201  INFO [qtp239360649-33] Stage:218 - Stage is being completed by transition id: 102

Pipeline Test-Down (the downstream of Test1 and Test2) is scheduled, finally,
at 12:02:34,434 and gets assigned 6 seconds later and finishes quickly.
============  END  ============

The config used for this is:

<?xml version="1.0" encoding="utf-8"?>
<cruise xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="cruise-config.xsd" schemaVersion="75">
  <server artifactsdir="artifacts" commandRepositoryLocation="default" serverId="0bbe24a1-a5ed-436e-a7a3-67fde4be24aa" />
  <pipelines group="defaultGroup">
    <pipeline name="Test1">
      <materials>
        <git url="/tmp/test.git" />
      </materials>
      <stage name="defaultStage">
        <jobs>
          <job name="defaultJob">
            <tasks>
              <exec command="date" />
            </tasks>
          </job>
        </jobs>
      </stage>
    </pipeline>
    <pipeline name="Test2">
      <materials>
        <git url="/tmp/test.git" />
      </materials>
      <stage name="defaultStage">
        <jobs>
          <job name="defaultJob">
            <tasks>
              <exec command="date" />
            </tasks>
          </job>
        </jobs>
      </stage>
    </pipeline>
    <pipeline name="Test-Down">
      <materials>
        <pipeline pipelineName="Test1" stageName="defaultStage" materialName="Test1" />
        <pipeline pipelineName="Test2" stageName="defaultStage" materialName="Test2" />
      </materials>
      <stage name="defaultStage">
        <jobs>
          <job name="defaultJob">
            <tasks>
              <exec command="date" />
            </tasks>
          </job>
        </jobs>
      </stage>
    </pipeline>
  </pipelines>
</cruise>

Raw logs:

2015-06-23 12:01:04,234  INFO [89@MessageListener for MaterialUpdateListener] ScmMaterialUpdater:62 - [Material Update] Found '1' modifications for material 'GitMaterial{url=/tmp/test.git, branch='master', submoduleFolder='null'}' with flyweight 'f0ca7d2cb50afd6d409a5fa857400f10ca4e629ad1850c4784cbcfaba3d14249' using working directory '/Users/aravindsv/projects/go/gocd/target/go-server-15.2.0/pipelines/flyweight/66e5b44d-9c5a-4791-8d88-d9624b92d5ed'
2015-06-23 12:01:14,188  INFO [consumeBuildCausesThread] ScheduleService:156 - [Pipeline Schedule] Scheduling pipeline Test1 with build cause [ModificationBuildCause: modified by Aravind SV <[email protected]>]
2015-06-23 12:01:14,200  INFO [consumeBuildCausesThread] PipelineRepository:84 - Start updating pipeline timeline
2015-06-23 12:01:14,206  INFO [consumeBuildCausesThread] PipelineRepository:88 - Pipeline timeline updated
2015-06-23 12:01:14,212  INFO [consumeBuildCausesThread] ScheduleService:156 - [Pipeline Schedule] Scheduling pipeline Test2 with build cause [ModificationBuildCause: modified by Aravind SV <[email protected]>]
2015-06-23 12:01:14,218  INFO [consumeBuildCausesThread] PipelineRepository:84 - Start updating pipeline timeline
2015-06-23 12:01:14,220  INFO [consumeBuildCausesThread] PipelineRepository:88 - Pipeline timeline updated
2015-06-23 12:01:19,978  INFO [72@MessageListener for WorkFinder] BuildAssignmentService:110 - [Agent Assignment] Assigned job [JobIdentifier[Test1, 6, 6, defaultStage, 1, defaultJob, 15]] to agent [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d]]
2015-06-23 12:01:20,042  INFO [72@MessageListener for WorkFinder] BuildAssignmentService:110 - [Agent Assignment] Assigned job [JobIdentifier[Test2, 6, 6, defaultStage, 1, defaultJob, 16]] to agent [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85]]
2015-06-23 12:01:29,998  INFO [qtp239360649-32] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Preparing] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,061  INFO [qtp239360649-30] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status [Preparing] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,491  INFO [qtp239360649-20] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Building] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,562  INFO [qtp239360649-27] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status [Building] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,615  INFO [qtp239360649-28] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting result [Passed] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,634  INFO [qtp239360649-29] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Completing] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,645  INFO [qtp239360649-24] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status and result [Completed, Passed] for [Build [Test1/6/defaultStage/1/defaultJob/15]]
2015-06-23 12:01:30,661  INFO [qtp239360649-24] Stage:218 - Stage is being completed by transition id: 94
2015-06-23 12:01:30,701  INFO [qtp239360649-33] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting result [Passed] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,717  INFO [qtp239360649-26] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status [Completing] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,726  INFO [qtp239360649-14] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, d9843a88-90d5-4b9b-baf9-78126537ef85, 4027c531-ae9f-4879-a37f-a52667cd949a]] is reporting status and result [Completed, Passed] for [Build [Test2/6/defaultStage/1/defaultJob/16]]
2015-06-23 12:01:30,746  INFO [qtp239360649-14] Stage:218 - Stage is being completed by transition id: 96
2015-06-23 12:02:33,918  INFO [93@MessageListener for MaterialUpdateListener] MaterialRepository:468 - Saving revision [DependencyMaterial{pipelineName='Test2', stageName='defaultStage'}, DependencyMaterialRevision[Test2/6/defaultStage/1] [pipelineLabel = 6];[Last Modified: 2015/06/23 12:01:30
Revision: Test2/6/defaultStage/1
UserName: Unknown
EmailAddress: null
Comment: Unknown
PipelineLabel: 6
]]
2015-06-23 12:02:33,918  INFO [91@MessageListener for MaterialUpdateListener] MaterialRepository:468 - Saving revision [DependencyMaterial{pipelineName='Test1', stageName='defaultStage'}, DependencyMaterialRevision[Test1/6/defaultStage/1] [pipelineLabel = 6];[Last Modified: 2015/06/23 12:01:30
Revision: Test1/6/defaultStage/1
UserName: Unknown
EmailAddress: null
Comment: Unknown
PipelineLabel: 6
]]
2015-06-23 12:02:34,434  INFO [consumeBuildCausesThread] ScheduleService:156 - [Pipeline Schedule] Scheduling pipeline Test-Down with build cause [ModificationBuildCause: triggered by Test1/6/defaultStage/1]
2015-06-23 12:02:34,446  INFO [consumeBuildCausesThread] PipelineRepository:84 - Start updating pipeline timeline
2015-06-23 12:02:34,451  INFO [consumeBuildCausesThread] PipelineRepository:88 - Pipeline timeline updated
2015-06-23 12:02:40,001  INFO [72@MessageListener for WorkFinder] BuildAssignmentService:110 - [Agent Assignment] Assigned job [JobIdentifier[Test-Down, 5, 5, defaultStage, 1, defaultJob, 17]] to agent [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d]]
2015-06-23 12:02:50,010  INFO [qtp239360649-24] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Preparing] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,025  INFO [qtp239360649-20] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Building] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,152  INFO [qtp239360649-28] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting result [Passed] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,172  INFO [qtp239360649-32] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status [Completing] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,181  INFO [qtp239360649-33] BuildRepositoryRemoteImpl:114 - [Agent [aravindsv.local, 192.168.0.104, 645965c9-13de-430f-a8f3-8ffa5b880a7d, 19c52e54-a635-4191-b664-f471ac37cd55]] is reporting status and result [Completed, Passed] for [Build [Test-Down/5/defaultStage/1/defaultJob/17]]
2015-06-23 12:02:50,201  INFO [qtp239360649-33] Stage:218 - Stage is being completed by transition id: 102

Ideally, stage completion of Test1 should have run a full schedule check. That would not have gone ahead, because Test2 is not complete. Then, stage completion of Test2 should have run a full schedule check, and should have found that Test-Down is schedulable.

[arvindsv]

@jyotisingh and I had a conversation about this. I've reproduced it below:

@jyotisingh said:

Its basically the doing of hasUpdateIntervalElapsedForScmMaterial in MaterialUpdateService ie. a material cannot be checked for update if a check on it was done within last min.

@arvindsv said:

Right. But, I think that the delay should not exist. A stage completion should cause a DependencyMaterial to be checked immediately. Why should MDU really keep checking DependencyMaterials? We know that they can be useful for MDU only after a successful stage completion, right?

@jyotisingh said:

Why should MDU really keep checking DependencyMaterials? We know that they can be useful for MDU only after a successful stage completion, right?

Makes sense.

[FredrikWendt]

@ketan Won't fix?

[maheshp]

@FredrikWendt this has been fixed, MDU for Dependency Materials are event based and changes are available in 16.12. You can refer #2787 for the changes.