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

Investigate performance degradation report

    Details

    • Similar Issues:
    • Epic Link:
    • Sprint:
      1.0-beta-1, 1.0-b05/b-06

      Description

      See https://groups.google.com/forum/#!topic/jenkinsci-dev/wcoXynHvSIE

      Andreas has sent us HAR files and thread dumps out-of-band to investigate

        Attachments

          Issue Links

            Activity

            jamesdumay James Dumay created issue -
            jamesdumay James Dumay made changes -
            Field Original Value New Value
            Epic Link JENKINS-37957 [ 174099 ]
            jamesdumay James Dumay made changes -
            Rank Ranked higher
            jamesdumay James Dumay made changes -
            Sprint 1.0-beta-1 [ 96 ] 1.0-beta-1, 1.0-b05/b-06 [ 96, 111 ]
            jamesdumay James Dumay made changes -
            Rank Ranked higher
            vivek Vivek Pandey made changes -
            Status Open [ 1 ] In Progress [ 3 ]
            Hide
            vivek Vivek Pandey added a comment -

            I am summarizing here the findings, there are problems in different areas: favorites API is taking longer than usual and then SSE /configure API takes really long time. search API also takes long time, we can improve it but I am not too sure given how we want flattened/sorted list.

            Key Findings (actionable/'to be investigated' items)

            SSE

            • SSE configure call takes really long time (~10sec) for job channel subscription
              (there are two job subscriptions)
              "subscribe": [
              { "jenkins_channel": "job" }

              ,

              { "jenkins_channel": "job" }

              ],

            • SSE configure for pipeline channel is relatively less but still long time (3-4 sec)
            • Avoid redirection by appending ‘/‘. GET /js-extensions costs 61ms
            • Run details page calls SSE configure API 5 times each taking on average ~2secs.

            Favorites API (page limit 26)

            • GET takes unreasonably long time 5.56 sec and there is only one favorited item!!!
            • Favorite item is a pipeline object that includes latest Run. It also includes actions (changeset, branch details) so interacting with git (file IO, hope it doesn’t go all the way to github for that)? Needs investigation

            Search API (page limit 26)

            • Took 7 sec on average
            • To address sorting by name and exclude certain items from flattening all possible items are loaded in memory
              • jenkins.getAllItems()
              • Exclude items that are children of multi-branch and matrix project
              • Don’t see how we can avoid it unless the jobs are stored in some kind of db with indexed column to speed up sorting and only give limited records instead of all
            • new PipelineContainerImpl().getPipelines(items) should be pagination aware
              • At present it creates BluePipeline object for all possible items (ouch!)

            Static Resources

            • blueocean.js (642KB), 370 ms to load: is loaded on each page (dashboard, run details, pipeline)
            • An so are most other JS files
            • If these are cached (not fetched for each page can easily save few secs)

            Further details:

            Dashboard

            GET http://10.10.1.130:8080/sse-gateway/listen/jenkins_blueocean-1473319896763-1yloru4qt6xwe32wewmi 30.08 sec

            This should be ok as this is SSE channel to get server side events, this connection remains opened for server to send events whenever there is data.

            POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec
            GET http://10.10.1.130:8080/blue/rest/users/XXX/favorites/ 5.56 sec
            GET http://10.10.1.130:8080/blue/rest/search/ 7.10 sec

            Js-extensions
            GET http://10.10.1.130:8080/blue/js-extensions 61ms (redirect)
            GET http://10.10.1.130:8080/blue/js-extensions/ *8ms *

            append ‘/‘ in initial GET http://10.10.1.130:8080/blue/js-extensions can save 61ms.

            Project/Pipeline page

            POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec
            GET http://10.10.1.130:8080/blue/rest/users/XXX/favorites/ 5.56 sec

            GET http://10.10.1.130:8080/blue/rest/search/ 7.10 sec
            GET http://10.10.1.130:8080/blue/rest/search/ 2.16 sec (Why second call)!!!

            GET http://10.10.1.130:8080/blue/rest/organizations/jenkins/pipelines/XXXX/activities/ 18.99 sec

            append ‘/‘ in initial GET http://10.10.1.130:8080/blue/js-extensions can save 61ms.

            Run page

            http://10.10.1.130:8080/adjuncts/807c3957/io/jenkins/blueocean/blueocean.js (642.28KB) 370 ms (why is it loaded on this page)?

            GET http://10.10.1.130:8080/blue/rest/search/ 7.10 sec
            GET http://10.10.1.130:8080/blue/rest/search/ 2.16 sec (Why second call)!!!

            GET http://10.10.1.130:8080/sse-gateway/listen/jenkins_blueocean-1473319896763-1yloru4qt6xwe32wewmi 30.08 sec
            POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec
            GET http://10.10.1.130:8080/blue/rest/users/XXX/favorites/ 5.56 sec

            SSE Job Channel
            POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec

            Why 5 subscription calls to ‘pipeline’ channel?

            POST http://10.10.1.130:8080/sse-gateway/configure 3.03 sec (channel pipeline)
            POST http://10.10.1.130:8080/sse-gateway/configure 19 ms (channel pipeline)
            POST http://10.10.1.130:8080/sse-gateway/configure 2.03 sec (channel pipeline)
            POST http://10.10.1.130:8080/sse-gateway/configure 2.77 sec (channel pipeline)
            POST http://10.10.1.130:8080/sse-gateway/configure 4.45 sec (channel pipeline)

            GET http://10.10.1.130:8080/blue/rest/organizations/jenkins/pipelines/XXX/branches/XXX/runs/1/log/ 90ms

            Gives 500 as there are no log file for this job.

            Show
            vivek Vivek Pandey added a comment - I am summarizing here the findings, there are problems in different areas: favorites API is taking longer than usual and then SSE /configure API takes really long time. search API also takes long time, we can improve it but I am not too sure given how we want flattened/sorted list. Key Findings (actionable/'to be investigated' items) SSE SSE configure call takes really long time (~10sec) for job channel subscription (there are two job subscriptions) "subscribe": [ { "jenkins_channel": "job" } , { "jenkins_channel": "job" } ], SSE configure for pipeline channel is relatively less but still long time (3-4 sec) Avoid redirection by appending ‘/‘. GET /js-extensions costs 61ms Run details page calls SSE configure API 5 times each taking on average ~2secs. Favorites API (page limit 26) GET takes unreasonably long time 5.56 sec and there is only one favorited item!!! Favorite item is a pipeline object that includes latest Run. It also includes actions (changeset, branch details) so interacting with git (file IO, hope it doesn’t go all the way to github for that)? Needs investigation Search API (page limit 26) Took 7 sec on average To address sorting by name and exclude certain items from flattening all possible items are loaded in memory jenkins.getAllItems() Exclude items that are children of multi-branch and matrix project Don’t see how we can avoid it unless the jobs are stored in some kind of db with indexed column to speed up sorting and only give limited records instead of all new PipelineContainerImpl().getPipelines(items) should be pagination aware At present it creates BluePipeline object for all possible items (ouch!) Static Resources blueocean.js (642KB), 370 ms to load: is loaded on each page (dashboard, run details, pipeline) An so are most other JS files If these are cached (not fetched for each page can easily save few secs) Further details: Dashboard GET http://10.10.1.130:8080/sse-gateway/listen/jenkins_blueocean-1473319896763-1yloru4qt6xwe32wewmi 30.08 sec This should be ok as this is SSE channel to get server side events, this connection remains opened for server to send events whenever there is data. POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec GET http://10.10.1.130:8080/blue/rest/users/XXX/favorites/ 5.56 sec GET http://10.10.1.130:8080/blue/rest/search/ 7.10 sec Js-extensions GET http://10.10.1.130:8080/blue/js-extensions 61ms (redirect) GET http://10.10.1.130:8080/blue/js-extensions/ *8ms * append ‘/‘ in initial GET http://10.10.1.130:8080/blue/js-extensions can save 61ms. Project/Pipeline page POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec GET http://10.10.1.130:8080/blue/rest/users/XXX/favorites/ 5.56 sec GET http://10.10.1.130:8080/blue/rest/search/ 7.10 sec GET http://10.10.1.130:8080/blue/rest/search/ 2.16 sec (Why second call)!!! GET http://10.10.1.130:8080/blue/rest/organizations/jenkins/pipelines/XXXX/activities/ 18.99 sec append ‘/‘ in initial GET http://10.10.1.130:8080/blue/js-extensions can save 61ms. Run page http://10.10.1.130:8080/adjuncts/807c3957/io/jenkins/blueocean/blueocean.js (642.28KB) 370 ms (why is it loaded on this page)? GET http://10.10.1.130:8080/blue/rest/search/ 7.10 sec GET http://10.10.1.130:8080/blue/rest/search/ 2.16 sec (Why second call)!!! GET http://10.10.1.130:8080/sse-gateway/listen/jenkins_blueocean-1473319896763-1yloru4qt6xwe32wewmi 30.08 sec POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec GET http://10.10.1.130:8080/blue/rest/users/XXX/favorites/ 5.56 sec SSE Job Channel POST http://10.10.1.130:8080/sse-gateway/configure 9.87 sec Why 5 subscription calls to ‘pipeline’ channel? POST http://10.10.1.130:8080/sse-gateway/configure 3.03 sec (channel pipeline) POST http://10.10.1.130:8080/sse-gateway/configure 19 ms (channel pipeline) POST http://10.10.1.130:8080/sse-gateway/configure 2.03 sec (channel pipeline) POST http://10.10.1.130:8080/sse-gateway/configure 2.77 sec (channel pipeline) POST http://10.10.1.130:8080/sse-gateway/configure 4.45 sec (channel pipeline) GET http://10.10.1.130:8080/blue/rest/organizations/jenkins/pipelines/XXX/branches/XXX/runs/1/log/ 90ms Gives 500 as there are no log file for this job.
            Hide
            jamesdumay James Dumay added a comment -

            Thanks Vivek Pandey - where are you going to start?

            Show
            jamesdumay James Dumay added a comment - Thanks Vivek Pandey - where are you going to start?
            Hide
            vivek Vivek Pandey added a comment -

            James Dumay it touches several aspects of BO. See key findings above. For example UI should stop sending redundant calls costing multiple of seconds, cache JS scripts across pages, investigate why SSE configure for job subscription is expensive, Favourite and search API performance etc. you should split it in to multiple tickets and assign right people to it.

            For favorite Ivan or me should look in to. I plan to take on search for sure.

            Show
            vivek Vivek Pandey added a comment - James Dumay it touches several aspects of BO. See key findings above. For example UI should stop sending redundant calls costing multiple of seconds, cache JS scripts across pages, investigate why SSE configure for job subscription is expensive, Favourite and search API performance etc. you should split it in to multiple tickets and assign right people to it. For favorite Ivan or me should look in to. I plan to take on search for sure.
            vivek Vivek Pandey made changes -
            Status In Progress [ 3 ] Open [ 1 ]
            vivek Vivek Pandey made changes -
            Status Open [ 1 ] In Progress [ 3 ]
            Hide
            michaelneale Michael Neale added a comment - - edited

            Vivek Pandey might be worth syncing up with Tom FENNELLY so he is aware of these (perhaps the SSE and js loading could be split off to him?)

            Show
            michaelneale Michael Neale added a comment - - edited Vivek Pandey might be worth syncing up with Tom FENNELLY so he is aware of these (perhaps the SSE and js loading could be split off to him?)
            michaelneale Michael Neale made changes -
            Priority Critical [ 2 ] Blocker [ 1 ]
            darragh Darragh Sherwin made changes -
            Attachment blue-ocean-slow.har [ 33955 ]
            Hide
            darragh Darragh Sherwin added a comment -

            As discussed at Jenkins World, HAR attached. Slownews when clicking on "Show More"

            Show
            darragh Darragh Sherwin added a comment - As discussed at Jenkins World, HAR attached. Slownews when clicking on "Show More"
            Hide
            vivek Vivek Pandey added a comment -

            Thanks Darragh Sherwin. This looks like search API performance issue as noted above, I will dig in to HAR file and get back.

            Show
            vivek Vivek Pandey added a comment - Thanks Darragh Sherwin . This looks like search API performance issue as noted above, I will dig in to HAR file and get back.
            Hide
            tfennelly Tom FENNELLY added a comment -

            Yeah, this is strange for sure from an SSE configure pov because the cost of what it is doing should be constant and small i.e. it is not searching anything or moving data around.

            I will look into this too from an SSE pov, but one thing I plan for this is to make the configure process completely async + remove all locking on the request path. Of course that will only have a limited effect if it's a case that the host is starved of threads from the request thread pool because of other long-running requests.

            Show
            tfennelly Tom FENNELLY added a comment - Yeah, this is strange for sure from an SSE configure pov because the cost of what it is doing should be constant and small i.e. it is not searching anything or moving data around. I will look into this too from an SSE pov, but one thing I plan for this is to make the configure process completely async + remove all locking on the request path. Of course that will only have a limited effect if it's a case that the host is starved of threads from the request thread pool because of other long-running requests.
            Hide
            michaelneale Michael Neale added a comment -

            Tom FENNELLY this starvation of things may be what has been seen elsewhere (with github oauth in some cases?).

            Also - can I ask a dumb question - what is a "HAR" ?

            Show
            michaelneale Michael Neale added a comment - Tom FENNELLY this starvation of things may be what has been seen elsewhere (with github oauth in some cases?). Also - can I ask a dumb question - what is a "HAR" ?
            Hide
            tfennelly Tom FENNELLY added a comment -

            A har file is a file you can generate from the network log panel in the dev tools in the browser.

            Show
            tfennelly Tom FENNELLY added a comment - A har file is a file you can generate from the network log panel in the dev tools in the browser.
            Hide
            jamesdumay James Dumay added a comment -

            Tom FENNELLY you can upload the HAR to https://toolbox.googleapps.com/apps/har_analyzer/ and view the captured data and requests that occurred within the browser session.

            Show
            jamesdumay James Dumay added a comment - Tom FENNELLY you can upload the HAR to https://toolbox.googleapps.com/apps/har_analyzer/ and view the captured data and requests that occurred within the browser session.
            Hide
            vivek Vivek Pandey added a comment -

            Relates to search API performance issue.

            Show
            vivek Vivek Pandey added a comment - Relates to search API performance issue.
            vivek Vivek Pandey made changes -
            Link This issue blocks JENKINS-38087 [ JENKINS-38087 ]
            vivek Vivek Pandey made changes -
            Link This issue blocks JENKINS-38087 [ JENKINS-38087 ]
            Hide
            vivek Vivek Pandey added a comment -

            Search API performance issue

            Show
            vivek Vivek Pandey added a comment - Search API performance issue
            vivek Vivek Pandey made changes -
            Link This issue is blocked by JENKINS-38087 [ JENKINS-38087 ]
            vivek Vivek Pandey made changes -
            Link This issue is blocked by JENKINS-38251 [ JENKINS-38251 ]
            vivek Vivek Pandey made changes -
            Link This issue is blocked by JENKINS-38252 [ JENKINS-38252 ]
            vivek Vivek Pandey made changes -
            Link This issue is blocked by JENKINS-38253 [ JENKINS-38253 ]
            Hide
            vivek Vivek Pandey added a comment -

            Closing this issue. We have identified issues and opened tickets for relevant performance improvements in specific components: JENKINS-38251, JENKINS-38252, JENKINS-38253 and JENKINS-38087.

            Show
            vivek Vivek Pandey added a comment - Closing this issue. We have identified issues and opened tickets for relevant performance improvements in specific components: JENKINS-38251 , JENKINS-38252 , JENKINS-38253 and JENKINS-38087 .
            vivek Vivek Pandey made changes -
            Status In Progress [ 3 ] Closed [ 6 ]
            Resolution Fixed [ 1 ]
            Hide
            jamesdumay James Dumay added a comment -

            Thanks for filing this Andreas - fixing the performance issues above is a top priority for our team

            Show
            jamesdumay James Dumay added a comment - Thanks for filing this Andreas - fixing the performance issues above is a top priority for our team
            michaelneale Michael Neale made changes -
            Link This issue is blocked by JENKINS-38335 [ JENKINS-38335 ]
            Show
            michaelneale Michael Neale added a comment - see also: https://issues.jenkins-ci.org/browse/JENKINS-38335

              People

              • Assignee:
                vivek Vivek Pandey
                Reporter:
                jamesdumay James Dumay
              • Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: