Fix issue with big logs, causing the browser to freeze (JENKINS-56377) #164
Conversation
|
I feel like there is an issue with the build process, as a higher version of Jenkins is required to run the tests (the POM states 2.176.4 as the minimum Jenkins version, while the tests ran at 2.164.1). I've ran the tests locally and they all pass, |
|
Thanks for the PR!
Yeah there is, I just filed #165 to hopefully fix the issue. |
src/main/resources/org/jenkinsci/plugins/workflow/job/console/NewNodeConsoleNote/script.js
Outdated
Show resolved
Hide resolved
src/main/resources/org/jenkinsci/plugins/workflow/job/console/NewNodeConsoleNote/script.js
Outdated
Show resolved
Hide resolved
| if (id == null) { | ||
| break | ||
|
|
||
| // The CSS rule for branch names only needs to be added once per node, so we |
There was a problem hiding this comment.
BTW https://github.com/jenkinsci/workflow-job-plugin/pull/164/files?diff=unified&w=1 improves reviewability due to indentation changes.
| var startId = e.getAttribute('startId') | ||
| if (startId == null || startId == nodeId) { | ||
| e.innerHTML = e.innerHTML.replace(/.+/, '$&<span class="pipeline-show-hide"> (<a href="#" onclick="showHidePipelineSection(this); return false">hide</a>)</span>') | ||
| // TODO automatically hide second and subsequent branches: namely, in case a node has the same parent as an earlier one |
There was a problem hiding this comment.
I think this is already filed in JIRA somewhere.
There was a problem hiding this comment.
I removed this part, because it would probably make more sense to generate this inside the back-end.
EDIT: upon further inspection, I will leave it as it was before due to its performance impact being way smaller than I thought (almost not noticeable).
There was a problem hiding this comment.
I should have clarified that my review comment was in reference to the removal of the one-line code comment, which is properly an RFE that should be tracked in Jira, not to behavioral changes in your patch.
…move redundant documentation
There was a problem hiding this comment.
@zhekoff316 Thanks for the PR! I am requesting changes to fix the issue I noted with parallel branch labels, but I would really like to see this merged once that is fixed!
I've tested it on a pipeline, which has 5-10 thousand steps
Is that a real Pipeline, or just one you created for testing?
| var nodes = $$('.pipeline-new-node') | ||
| var enclosings = new Map() // id → enclosingId | ||
| var labels = new Map() // id → label | ||
| for (var i = 0; i < nodes.length; i++) { | ||
| var node = nodes[i] | ||
| var oid = node.getAttribute('nodeId') | ||
| enclosings.set(oid, node.getAttribute('enclosingId')) | ||
| labels.set(oid, node.getAttribute('label')) | ||
| } |
There was a problem hiding this comment.
Removing this loop causes branch names to no longer be shown when log output changes from one branch to another in many cases.
The problem is that in the while loop right after this, we need to walk through all of this node's parents to find what parallel branch it is a part of. Because the loop is gone, now we only walk through the immediate parents of each node, so if there is any nesting inside of the parallel branch, for example because of a block-scope step, we never find the enclosing parallel branch, and so the while loop exits before finding a label.
The old code is not optimal because we create a fresh enclosings and labels map for every node even though most of the content will be the same. I would try to come up with a good way to store those as page-level state so that you can keep the approach you have now of only updating enclosings and labels once per node, and then split the while loop below out somehow and only run it after the enclosings and labels have data for every node (not sure of a good way to do that).
Here is a Pipeline you can run to compare the behavior with and without this PR to see what I mean:
stage('Outer') {
parallel(branchOne: {
stage('Stage One') {
node() {
sh 'echo "from one"'
sleep(time: 1)
echo 'from one again'
}
}
}, branchTwo: {
stage('Stage Two') {
node() {
sh 'echo "from two"'
sleep(time: 1)
echo 'from two again'
}
}
})
}
There was a problem hiding this comment.
I see. I will try to find a solution to this problem.
| break | ||
| } | ||
| } | ||
| }, 5000) |
There was a problem hiding this comment.
5 seconds is a long time to wait. Is 1 second (or maybe even less) not good enough just to get it out of the critical path for the main page load?
|
Hello again, thanks for the feedback. First of all, sorry about the delay. I have done some big changes in the latest commit. They resolve the issue with parallel pipelines (branch names are shown), and also greatly improve the performance with big logs.
|
| } | ||
| var isParallel = false | ||
| var nodes = $$('.pipeline-new-node') | ||
| var pipelineElements = document.getElementsByClassName("pipeline-new-node") |
There was a problem hiding this comment.
Correct, those two variables are left-over after I made some changes to the code. Will remove them.
| isParallelBuild($$('.pipeline-new-node')); | ||
| generatePipelineLinks($$('.pipeline-new-node')); |
There was a problem hiding this comment.
Doing this only once on page load seems like it will have issues if someone opens the log for an in-progress build, leaves it open while the build continues, and then comes back and looks at the logs. For example, there may not be a parallel step when the page is opened initially, but one may execute later on. I think that in-progress builds are supported today by Behaviour.specify and the old code, but I haven't specifically tested it.
There was a problem hiding this comment.
I will test this use case with the current code and will let you know. It is also a variant to remove the parallel check all-together - the performance impact will be minimal, as the main performance issue was fixed.
|
Added it to my review queue. Thanks to @zhekoff316 for this pull request, it is a very important improvement! |
There was a problem hiding this comment.
I took a quick look, and the logic seems a little off; I added some comments. Have you checked to see whether we can count on Behaviour.specify processing the nodes in any particular order? That could help us figure out a consistent way to build up the enclosings and labels maps without having to recreate them for every node.
| var enclosings = new Map() // id → enclosingId | ||
| var labels = new Map() // id → label |
There was a problem hiding this comment.
Did you mean to create a local version of enclosings and labels here, or were you wanting to reuse and modify the global variables and use them as a kind of cache or something?
The way things are now, it doesn't look like generateEnclosing (no s) actually does anything because the global variables aren't used.
| var enclosings = new Map() // id → enclosingId | ||
| var labels = new Map() // id → label |
There was a problem hiding this comment.
I'm not sure if scripts like this are encapsulated by Jenkins beyond standard JavaScript behavior, but having global vars like this seems like a bad idea. I would probably find the <pre> element with class console-output and attach these objects to that element instead, but I'm not a JavaScript expert, so I'm not sure what the preferred approach is for this kind of thing.
There was a problem hiding this comment.
I think it'd be easier to simply wrap the whole script in an IIFE
(function() {
// ...
})();This way those variables are not in the global scope but easily accessible from anywhere in this script.
| enclosings.set(oid, node.getAttribute('enclosingId')) | ||
| labels.set(oid, node.getAttribute('label')) | ||
| appendBranchNames(oid, enclosings, labels) |
There was a problem hiding this comment.
It looks like this is the only place where appendBranchNames is called, which seems wrong, since this method is only called for the parallel step itself. What if we start executing the first branch in a parallel step, and then that branch stops and we start executing the other branch? The first branch might get labelled correctly, but I think that the second branch wouldn't be labeled (unless later on in the Pipeline there was another parallel step).
|
Hi! Is there any update regarding this PR? We hit this bug as well :( |
|
@ngg |
|
I've been on a vacation, but I will take a look at the latest review comments as soon as I can, and will let you know if I can fix it. |
|
Hello :) , sorry for taking so much time to come back to this. I've noticed that @jglick has made a change (#112) that is mentioned in this PR. I haven't looked it in detail yet, but I can confirm that the problem does not appear anymore on big console logs on our Jenkins server (no browser crashes or freezes, it takes much faster for the logs to load). Do you still have this problem on your side, as it seems the main issues have been fixed? |
|
That change was made 3 years ago, I don't see how that can be relevant. The issue is still not fixed, it's still horribly slow to open the console log. An 1mb log file takes several minutes to load and the browser stays unresponsive until then. |
My bad on this one. I thought it was a newer change, as I can no longer re-produce the problem on our Jenkins server and I am talking about a 7mb log, which loads for 5-6 seconds maximum. The 1mb logs are loading almost instantly. The hardware or general configuration has not been changed. Edit: I found some of the older jobs (they have a lot of steps) I used for testing this issue. I can still re-produce it, so I will start work on this again. |
|
Hello, I've tried to address the latest comments from before I stopped working on this PR. (1) The global variables were indeed useless there, so I removed them and replaced them with variables in the function scope
Could you please give me an example pipeline where I can test this for example, because I can not reproduce anything wrong currently with the parallel builds. This function is only called if a parallel stage exists in the whole pipeline, and will go through all elements (from what I can see). Maybe I am doing something wrong, so it would be very helpful if you can provide me a very short example :) If there is something wrong there, I will fix it. Overall, I tested again with a job with a lot of Pipeline Steps and the log would open very fast. Parallel builds with multiple stages also looked okay, and the show/hide buttons are working. I am ready to provide examples if you need them. Will be happy if you can review this, as it's quite an important improvement. |
| var enclosings = new Map() // id → enclosingId | ||
| var labels = new Map() // id → label | ||
| var nodes = $$(".pipeline-new-node") |
There was a problem hiding this comment.
in general, document.querySelectorAll will be much faster than $$ as one is a native browser API, and the other would be a prototypes scanner. its not a drop in replacement, but it doesn't seem like there's any prototype specific apis being used for this, so should work.
|
I've also been hitting this issue as part of testing upgrading our old Jenkins server ( I just tested the changes in this PR with a build log from an example pipeline in the ticket I mentioned above which is simply generating a log from parallel branches: def genText(lines){
(1..lines).each{
println "Lorem ipsum dolor sit amet, consectetur adipiscing elit. Curabitur interdum fringilla interdum"
}
return true
}
parallel firstBranch: {
genText(20000)
}, secondBranch: {
genText(20000)
}I wanted to give some benchmarks of trying to load the different consoles for the the result of a build of the above pipeline, which winds up being a ~16MB
The changes in this PR are definitely an improvement over the more current versions, but still not as efficient as our old Jenkins server |
|
The difference between 1145.v7f2433caa07f and 2.36 is that prior to #150 (landed in 2.37), the relevant Javascript essentially never executes on So in 2.28, there is no Javascript that tries to show branch names in the log, which is why things are fast. |
|
Possibly we could just detect a large log file and disable the JS (compared to |
|
After spending the week discussing this in the Jenkins Gitter, it seems like most large log files do not hit this issue (or I suspect there'd be a lot more complaints). The magic ingredient seems to be the multiple parallel branches logging (could detect that instead?). IMO the biggest issue is that even |
|
I hit this problem with large console logs quite often with version 2.293. Haven't complained but that does not means it's not a problem. |
See JENKINS-56377.
We've had this issue for a couple of months, where big logs would freeze the browser and the whole thing would load for ~2-3 minutes. I've addressed this issue and optimized the code in several places:
I've tested it on a pipeline, which has 5-10 thousand steps, and my load time has been in the span of 2-5 seconds, compared to 90-150s before (including a browser crash/freeze). Also, this has been tested on Chrome and Mozilla.