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

p4-plugin keeps opening connection during the build. Causing long delays

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Critical
    • Resolution: Fixed
    • Component/s: p4-plugin
    • Labels:
    • Environment:
      Pipeline scripted
      p4 plugin v 1.9.2 (latest)
      Both on Jenkins 2.107.3 and 2.138.2.
      Also on clean installed Jenkins server
    • Similar Issues:

      Description

      After using the p4 plugin, and after it finished its task, the p4 plugin keeps opening connection and closing it. Each such action takes 1-2 seconds. So during the rest of the build, there is a delay of 5-20 seconds between the commands.

      How to reproduce:

      1. Go to <jenkins url>/log/ and add a new logger called "p4"
        Logger = "org.jenkinsci.plugins.p4" ; Log level = "ALL"
      2. Create a pipeline job with this script:
      node() {
          // library retriever: legacySCM(perforce( // fill your data here.
          // p4sync // fill your data here.
          stage('run') {
              3.times {
                  sh 'date'
              }
          }
      }
      1. Build the Job
      2. Now remove one of the commented lines (library with perforce or p4sync), fill the needed data. You can use the "Pipeline Syntax".
      3. Build the Job again
      4. Compare the time that the 'run' stage took:
        1. in step 3 it took ~350 ms
        2. in step 5 it took 53 seconds
          and this time diff is only for 3 "sh" calls. For longer jobs it increases.
      5. Pay attention that this time is only for the 3 calls to "sh", and not including the p4 stage.
      6. Open the log you created at stage 1 (<jenkins url>/log/p4).
        You can see there a loop of
            P4: opened connection OK
            P4: closed connection OK
        Each "open" takes 1-2 seconds, and during this time the build can't proceed.

        Attachments

          Activity

          erez_arbell Erez Arbell created issue -
          Hide
          p4paul Paul Allen added a comment -

          The 'p4-plugin' runs extra commands 'p4 reconcile', 'p4 revert', etc... to cleanup and prep the workspace.  This was designed to help larger code bases, but does add an overhead.  Which mode are you using with 'p4sync' -  'autoClean', 'forceClean', etc... 

          I have added some additional logging to P4Logging.java, so I can see each command and its compute time. It probably makes sense to add this to aid with debugging.

          Unfortunately I can't share the P4 connection across Jenkins as it spawns multiple threads.  In addition the plugin requires connections for the master and slave nodes.  There are a few extra 'p4 info' and 'p4 login -s' commands that are used to test long running commands; they could be optimised, but with great care.

           

          Show
          p4paul Paul Allen added a comment - The 'p4-plugin' runs extra commands 'p4 reconcile', 'p4 revert', etc... to cleanup and prep the workspace.  This was designed to help larger code bases, but does add an overhead.  Which mode are you using with 'p4sync' -  'autoClean', 'forceClean', etc...  I have added some additional logging to P4Logging.java, so I can see each command and its compute time. It probably makes sense to add this to aid with debugging. Unfortunately I can't share the P4 connection across Jenkins as it spawns multiple threads.  In addition the plugin requires connections for the master and slave nodes.  There are a few extra 'p4 info' and 'p4 login -s' commands that are used to test long running commands; they could be optimised, but with great care.  
          Hide
          erez_arbell Erez Arbell added a comment -

          Thank you Paul Allen for the quick reply.

          I tried "autoClean", "forceClean" and "syncOnly". The behavior is he same.
          How can I use the new logging feature you added?

          The issue here is that the p4-pluging continue to do a loop of open and close p4 connections long after it finished its task. Can you please explain the need for this?
          I fail to see the need for it. If there will be need to do another use of p4, then it can open the connection then.
          I have jobs with duration of hours and days, and I keep see this slowness. You can see it yourself, in the pipeline code in steps to reproduce above, add long sleep between the p4 command and the "stage('run')". You will see that the plugin keep connecting to the p4 server and add long time to the build duration.

          This is not some overhead but a big issue.

          I apologize. I am not familiar with the internals of Jenkins so I do not understand the last paragraph you wrote.

          Anyway, as you can see be the simple steps to reproduce above,  when using the p4-plugin, it makes the whole run of the build to be much slower. I am talking about a constant delay of 1-10 seconds between each two command in the Jenkinsfile. We had this slowness for long time but did not know why. Now that we discovered the reason we discussed it today in the team and due to this we consider moving to git.

          Show
          erez_arbell Erez Arbell added a comment - Thank you Paul Allen for the quick reply. I tried "autoClean", "forceClean" and "syncOnly". The behavior is he same. How can I use the new logging feature you added? The issue here is that the p4-pluging continue to do a loop of open and close p4 connections long after it finished its task . Can you please explain the need for this? I fail to see the need for it. If there will be need to do another use of p4, then it can open the connection then. I have jobs with duration of hours and days, and I keep see this slowness. You can see it yourself, in the pipeline code in steps to reproduce above, add long sleep between the p4 command and the "stage('run')". You will see that the plugin keep connecting to the p4 server and add long time to the build duration. This is not some overhead but a big issue. I apologize. I am not familiar with the internals of Jenkins so I do not understand the last paragraph you wrote. Anyway, as you can see be the simple steps to reproduce above,  when using the p4-plugin, it makes the whole run of the build to be much slower. I am talking about a constant delay of 1-10 seconds between each two command in the Jenkinsfile. We had this slowness for long time but did not know why. Now that we discovered the reason we discussed it today in the team and due to this we consider moving to git.
          Hide
          p4paul Paul Allen added a comment -

          The extra logging is a code change; I have checked it in and you can access the latest build and 'p4.hpi' file on Jenkins CI server:

           

             https://ci.jenkins.io/job/Plugins/job/p4-plugin/job/master

          It will go out in the next release, or you can download the hpi file and install the plugin manually.

          Show
          p4paul Paul Allen added a comment - The extra logging is a code change; I have checked it in and you can access the latest build and 'p4.hpi' file on Jenkins CI server:       https://ci.jenkins.io/job/Plugins/job/p4-plugin/job/master It will go out in the next release, or you can download the hpi file and install the plugin manually.
          Hide
          erez_arbell Erez Arbell added a comment -

          Thank you Paul.
          What about the original issue. Did you try to reproduce it using the steps I provided? Do you see the issue and the large time difference in the remaining of the build run, after the p4 stage has finished?
          If it is not a bug, can you suggest how to overcome the issue?

          Show
          erez_arbell Erez Arbell added a comment - Thank you Paul. What about the original issue. Did you try to reproduce it using the steps I provided? Do you see the issue and the large time difference in the remaining of the build run, after the p4 stage has finished? If it is not a bug, can you suggest how to overcome the issue?
          Hide
          p4paul Paul Allen added a comment -

          Yes I did try you example; I do see additional commands after the sync.  Some of these will be related to change reporting and saving the build state, there did seem to be a few more than I was expecting and that may need investigating.  However, the overhead was at most a second not the 53 seconds you reported.

          Show
          p4paul Paul Allen added a comment - Yes I did try you example; I do see additional commands after the sync.  Some of these will be related to change reporting and saving the build state, there did seem to be a few more than I was expecting and that may need investigating.  However, the overhead was at most a second not the 53 seconds you reported.
          Hide
          erez_arbell Erez Arbell added a comment -

          So you do not see that the p4 connections keep opening and closing without stop?
          I tried to do "p4 login" manually and I see that it always take little more than a second. So maybe my Perforce server is slower than the one you have, and this is why the effect on me is bigger?

          Can you suggest how can I investigate the issue, or how to tell the p4 plugin to stop to connect to the p4 server once it finished its task?

          Show
          erez_arbell Erez Arbell added a comment - So you do not see that the p4 connections keep opening and closing without stop? I tried to do "p4 login" manually and I see that it always take little more than a second. So maybe my Perforce server is slower than the one you have, and this is why the effect on me is bigger? Can you suggest how can I investigate the issue, or how to tell the p4 plugin to stop to connect to the p4 server once it finished its task?
          Hide
          p4paul Paul Allen added a comment -

          It looks like buildEnvironment(Run<?, ?> run, Map<String, String> env) is getting called many times by Jenkins.  Normally this would not be a problem, however there is an environment variable P4_TICKET which was cached in the XML config, but now looked up on demand.  I have cached this in a transient variable which will reduce the number of calls to P4D.

          https://ci.jenkins.io/job/Plugins/job/p4-plugin/job/master/287/ (assuming the build passes)

          Jenkins > Manage Jenkins > Manage Plugins > Advanced tab > Upload Plugin > Select HPI file > Upload > Restart

          Show
          p4paul Paul Allen added a comment - It looks like buildEnvironment(Run<?, ?> run, Map<String, String> env)  is getting called many times by Jenkins.  Normally this would not be a problem, however there is an environment variable P4_TICKET which was cached in the XML config, but now looked up on demand.  I have cached this in a transient variable which will reduce the number of calls to P4D. https://ci.jenkins.io/job/Plugins/job/p4-plugin/job/master/287/  (assuming the build passes) Jenkins > Manage Jenkins > Manage Plugins > Advanced tab > Upload Plugin > Select HPI file > Upload > Restart
          Hide
          erez_arbell Erez Arbell added a comment -

          Awesome! It fixed the issue. Now the stage takes the same time as without using p4, and the redundant open connections stopped.

          My pipeline is much faster now. Also, the duration of the "p4 sync" itself reduced to 60% than it was before.

          Thank you.

          Show
          erez_arbell Erez Arbell added a comment - Awesome! It fixed the issue. Now the stage takes the same time as without using p4, and the redundant open connections stopped. My pipeline is much faster now. Also, the duration of the "p4 sync" itself reduced to 60% than it was before. Thank you.
          p4paul Paul Allen made changes -
          Field Original Value New Value
          Status Open [ 1 ] In Progress [ 3 ]
          p4paul Paul Allen made changes -
          Labels p4-plugin P4_A p4-plugin
          Hide
          p4paul Paul Allen added a comment -

          Ready for release.

          Show
          p4paul Paul Allen added a comment - Ready for release.
          p4paul Paul Allen made changes -
          Status In Progress [ 3 ] Fixed but Unreleased [ 10203 ]
          Assignee Paul Allen [ p4paul ]
          Resolution Fixed [ 1 ]
          Hide
          p4paul Paul Allen added a comment -

          Thank you for trying this out, I'm pleased it resolved your issue.  I have marked this 'ready for release' and it should be officially available in the next few days.

          Show
          p4paul Paul Allen added a comment - Thank you for trying this out, I'm pleased it resolved your issue.  I have marked this 'ready for release' and it should be officially available in the next few days.
          Hide
          p4paul Paul Allen added a comment -

          Released in 1.9.3

          Show
          p4paul Paul Allen added a comment - Released in 1.9.3
          p4paul Paul Allen made changes -
          Status Fixed but Unreleased [ 10203 ] Closed [ 6 ]

            People

            • Assignee:
              p4paul Paul Allen
              Reporter:
              erez_arbell Erez Arbell
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: