Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-42636

During pipeline step duration reported incorrectly

    Details

    • Similar Issues:
    • Sprint:
      1.0, Blue Ocean 1.0-rc3, Blue Ocean - 1.1-beta-1

      Description

      I noticed that during a pipeline stage the build time was reporting an impossible time.  After the stage finished, the time corrected itself.  Screenshots attached.  

        Attachments

        1. 12.xml
          0.7 kB
        2. Capture.PNG
          Capture.PNG
          5 kB
        3. Capture2.PNG
          Capture2.PNG
          7 kB
        4. jenkins-42636-build-dirs.zip
          78 kB
        5. localhost.har
          1.07 MB
        6. Mar-13-2017 14-00-57.gif
          Mar-13-2017 14-00-57.gif
          84 kB

          Issue Links

            Activity

            Hide
            jamesdumay James Dumay added a comment -

            Andrew Bayer not on hand sorry

            Show
            jamesdumay James Dumay added a comment - Andrew Bayer not on hand sorry
            Hide
            abayer Andrew Bayer added a comment -

            s'alright, s'alright - I'll try to get one myself now.

            Show
            abayer Andrew Bayer added a comment - s'alright, s'alright - I'll try to get one myself now.
            Hide
            abayer Andrew Bayer added a comment -

            Ok, I've finally reproduced it. For what it's worth, it's not even the duration of the step, let alone the stage, that the TimingAction is missing - it's <2 seconds total. I was copying the build directory aside every second. One copy, before 12.xml was written (i.e., before the docker pull started), all was fine. Next copy, one second later, 12.xml was there, 12.log was completely empty, and 12.xml didn't have a TimingAction. And one second after that, 12.xml was still the latest, 12.log had some output in it, and 12.xml did have a TimingAction. So the shell step calling docker pull was still running but the node now had a proper TimingAction. While the time-since-epoch duration seems to stick around in the UI after that, that's something in the UI not refreshing it from the API, because a reload of the page gets the right duration at that point.

            I'll defer to Sam Van Oort if he's got a better sense of what might be happening here, but I'd guess it's just that there's a tiny tiny tiny window between when the FlowNode is created and first saved and when CpsFlowExecution.notifyListeners gets called, which leads to the actual adding of the TimingAction

            So frankly? I think Blue Ocean should just be a little smarter and either not display a duration at all if it's expecting a TimingAction but gets null, or it should somehow decide what an appropriate analogue for the start time would be. This tiny gap between the FlowNode being initially written and the TimingAction being added is, IMO, entirely reasonable.

            Show
            abayer Andrew Bayer added a comment - Ok, I've finally reproduced it. For what it's worth, it's not even the duration of the step, let alone the stage, that the TimingAction is missing - it's <2 seconds total. I was copying the build directory aside every second. One copy, before 12.xml was written (i.e., before the docker pull started), all was fine. Next copy, one second later, 12.xml was there, 12.log was completely empty, and 12.xml didn't have a TimingAction . And one second after that, 12.xml was still the latest, 12.log had some output in it, and 12.xml did have a TimingAction . So the shell step calling docker pull was still running but the node now had a proper TimingAction . While the time-since-epoch duration seems to stick around in the UI after that, that's something in the UI not refreshing it from the API, because a reload of the page gets the right duration at that point. I'll defer to Sam Van Oort if he's got a better sense of what might be happening here, but I'd guess it's just that there's a tiny tiny tiny window between when the FlowNode is created and first saved and when CpsFlowExecution.notifyListeners  gets called, which leads to the actual adding of the TimingAction .  So frankly? I think Blue Ocean should just be a little smarter and either not display a duration at all if it's expecting a TimingAction but gets null, or it should somehow decide what an appropriate analogue for the start time would be. This tiny gap between the FlowNode being initially written and the TimingAction being added is, IMO, entirely reasonable.
            Hide
            abayer Andrew Bayer added a comment -

            fwiw, added jenkins-42636-build-dirs.zip as an attachment. It's got the three separated-by-1-second copies of the build directory I mentioned in the above comment.

            Show
            abayer Andrew Bayer added a comment - fwiw, added  jenkins-42636-build-dirs.zip  as an attachment. It's got the three separated-by-1-second copies of the build directory I mentioned in the above comment.
            Hide
            abayer Andrew Bayer added a comment -

            PR up at https://github.com/jenkinsci/blueocean-plugin/pull/947 - not sure off the top of my head the right way to test it, since reproducing the issue is inconsistent and timing-based anyway.

            Show
            abayer Andrew Bayer added a comment - PR up at https://github.com/jenkinsci/blueocean-plugin/pull/947  - not sure off the top of my head the right way to test it, since reproducing the issue is inconsistent and timing-based anyway.

              People

              • Assignee:
                abayer Andrew Bayer
                Reporter:
                scatt Stephen Catt
              • Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: