<div dir="ltr"><div>In the case of the UI customization, this would be hard for me to reason without the exact actual code.</div><div>Maybe, indeed, calling getChanges for builds for 1000 builds is not a good idea. For example in the grid view we couldn't do this for performance reason, and thus, we have a more global algorithm that is running inside the browser.</div><div>onNew happens for all new builds that appear, regardless of any paging.</div><div><br></div><div>Is this really custom to your company? maybe it would make sense to upstream the code and usecase in order to discuss the best implementation path together.</div><div><br></div><div>We had a few contributions this week e.g. <a href="https://github.com/buildbot/buildbot/pull/5747">https://github.com/buildbot/buildbot/pull/5747</a> which go in the direction of more information in the builder page with mouse-over.</div><div>Maybe you can go this path in order to get your sourcestamp information. </div><div><div><br></div><div><br></div><div>Another issue that could happen for your problem is a 100% cpu in the browser! That would explain a freeze of one tab and work of other tab.</div><div>If the get of the changes is done in onNew, indeed for 1000 builds, this will probably be done in parallel.</div><div>In that case if you have http only then you will get serialized by browser to 8 request in //, but if you have http2, then you will have unlimited parallelisation.</div><div>In this case those 1000 request can indeed pile-up, and starve the threadpool.</div><div><br></div><div>If you have a largeVM, and want to make the current code work, maybe you can raise the db poolsize</div><div><a href="https://github.com/tardyp/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/db/enginestrategy.py#L273">https://github.com/tardyp/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/db/enginestrategy.py#L273</a></div><div>hence, you can configure the db_url like this:</div><div><br></div><div class="gmail-highlight-python gmail-notranslate" style="box-sizing:border-box;border:1px solid rgb(225,228,229);overflow-x:auto;margin:1px 0px 24px;color:rgb(64,64,64);font-family:Lato,proxima-nova,"Helvetica Neue",Arial,sans-serif;font-size:16px;background-color:rgb(252,252,252)"><div class="gmail-highlight" style="box-sizing:border-box;background:rgb(255,255,255);border:none;overflow-x:auto;margin:0px;padding:0px"><pre style="box-sizing:border-box;font-family:SFMono-Regular,Menlo,Monaco,Consolas,"Liberation Mono","Courier New",Courier,monospace;font-size:12px;line-height:1.4;margin-top:0px;margin-bottom:0px;padding:12px;overflow:auto"><span class="gmail-s2" style="box-sizing:border-box;color:rgb(187,136,68)">"driver://[username:password@]host:port/database?pool_size=20"</span>
</pre></div></div><br class="gmail-Apple-interchange-newline"><div>Regards <br clear="all"><div><div dir="ltr" class="gmail_signature" data-smartmail="gmail_signature">Pierre</div></div><br></div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">Le jeu. 14 janv. 2021 à 13:22, Yngve N. Pettersen <<a href="mailto:yngve@vivaldi.com">yngve@vivaldi.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hi,<br>
<br>
Hmmm, there is a bit of a difference between a 2ms sampling interval and a <br>
500 ms one :P .<br>
<br>
There isn't that much load on the machine (we actually expanded CPU count <br>
threefold, and more than doubled RAM trying to eliminate those potential <br>
issues; I am not aware of any significant load on the VM-host), and I have <br>
seen this freeze happen while there was no build activity.<br>
<br>
This VM is just running the buildbot and the postgresql DB; There should <br>
be no disk speed issues.<br>
<br>
What I have noticed in the netdata graphs is that the Pressure Stall <br>
Information graph <br>
<<a href="https://www.kernel.org/doc/html/latest/accounting/psi.html" rel="noreferrer" target="_blank">https://www.kernel.org/doc/html/latest/accounting/psi.html</a>> also spikes, <br>
mostly in the some10 line, no idea why or how bad the stall really is.<br>
<br>
I have had one colleague report that pasting the page URL into a new tab <br>
had the page load quickly, while the original page was still blank. I have <br>
not tried that yet, but I have tried to load two different pages, and both <br>
remained blank.<br>
<br>
<br>
*However*, during the last case of this, I was checking the inspector <br>
(planning to check network traffic) and noticed that there were console <br>
reports from code we had added on the page I was *leaving*. It seems that <br>
this code continued running after I navigated away from the page, to the <br>
previous page in the history.<br>
<br>
The modified code is used to load and display changelog entries for each <br>
build displayed on the builder page; this was developed in response to a <br>
feature request from our CEO, and this week was the first time it was <br>
deployed in production.<br>
<br>
The current version of that code triggers a changelog retrieval for each <br>
build in the list in the $scope.builds.onNew function in <br>
www/base/src/app/builders/builder/builder.controller.js.<br>
<br>
If this code is indeed involved in the freezes, then it appears that the <br>
code continues to run after the page is no longer the current page. IMO <br>
those calls should have been unsubscribed when the navigation started.<br>
<br>
Further (if this is indeed what caused the issue):<br>
<br>
* it seems like the onNew calls for the changes entries got priority <br>
above what was going on on the new page<br>
<br>
* It also seems that the builds onNew call is triggered for builds that <br>
are not yet visible on the page, and perhaps are also never going to be <br>
displayed since they beyond the limit of what is to be displayed unless <br>
the user request more. If this triggers loading of 1000 builds' changelog <br>
entries .....<br>
<br>
As far as the changelog info is concerned, we don't actually need it until <br>
the build info is rendered on the page, so an "onDisplay" call would be <br>
better for our purposes.<br>
<br>
<br>
<br>
I have just backed those changes out of our deployed custom www-base <br>
module, so that we can see if that was involved in our issue.<br>
<br>
BTW, I am noticing some problems with pip and this custom module. It seems <br>
that the requirement declaration is set such that only the 2.10.0 package <br>
can be loaded; this caused issues since the default version for building <br>
the module is 2.10.1-devX; I had to force the version to 2.10.0 to be able <br>
to load it, and that is causing warnings from pip, and problems installing <br>
an updated module. AFAICT this started becoming a problem with recent <br>
versions of Pip. (Note: I am not interested in building the whole buildbot <br>
package bundle; in fact, I'd prefer to register our customization in a <br>
different manner)<br>
<br>
<br>
On Thu, 14 Jan 2021 10:07:32 +0100, Pierre Tardy <<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>> wrote:<br>
<br>
> (Back to mailing list)<br>
><br>
> Thanks for this data. Here is how you would read it:<br>
><br>
><br>
> [image: image.png]<br>
> In the left, you get the main thread activity. You can say that because <br>
> the<br>
> bottom frame(s) are about startReactor.<br>
> In the right, you get what happens in the threads. You can say that <br>
> because<br>
> we see threading.py in the last bottom frame.<br>
><br>
> You can see that the reactor thread does pretty much nothing:<br>
> [image: image.png]<br>
> doPoll is just the reactor waiting for events (that's 1 third of the<br>
> samples)<br>
> then the left part is about getting sourcestams, and waiting the <br>
> dbthread.<br>
> then the right part is log management, which is usually the major part <br>
> of a<br>
> buildbot load.<br>
><br>
> On the thread side, this is pretty similar picture. We can see that most <br>
> of<br>
> the load is managing source stamps.<br>
> [image: image.png]<br>
> So frankly, I wouldn't say this is an obvious profile of a blocked <br>
> buildbot<br>
> master.<br>
><br>
> The reactor does pretty much nothing. Reading 300 sourcestamps requests <br>
> by<br>
> second from the db shouldn't be that much of a problem with modern HW.<br>
> We can see that the profiler itself has difficulties to run in time, as <br>
> we<br>
> see some profiler stacks.<br>
> BTW, I gave wrong advice last time, I told you to put 500HZ frequency <br>
> while<br>
> I meant 500ms timer. we should rather put a 2HZ to have 2 sample per <br>
> second<br>
> and per thread. This may avoid to disrupt too much the measurment<br>
> (Heisenberg principle).<br>
><br>
> So I thought about memory or disk starvation. Do you have any other load <br>
> in<br>
> the master that would starve CPU ressources?<br>
> I can see that there is 28GB memory free so no memory starvation. but the<br>
> profiler do not output the loadaverage.<br>
> Do we have db connection pool or threadpool starvation?<br>
> Do we have disk io or network io starvation?<br>
><br>
> Regards<br>
> Pierre<br>
><br>
><br>
> Le jeu. 14 janv. 2021 à 00:09, Yngve N. Pettersen <<a href="mailto:yngve@vivaldi.com" target="_blank">yngve@vivaldi.com</a>> a<br>
> écrit :<br>
><br>
>> Hi,<br>
>><br>
>> I finally got a trace of the problem area.<br>
>><br>
>> I wasn't able to make sense of the profile, maybe you can? zip attached<br>
>><br>
>> The area of interest is the ~400 second segment towards the end, which<br>
>> matches the bump in the PNG.<br>
>><br>
>> This happened while reloading the Build>Builders page after loading a<br>
>> build and then returning to the previous point in the history. Loading <br>
>> of<br>
>> the page took about 5 minutes of the 7 minutes of high load.<br>
>><br>
>> The Python process hit ~120% CPU<br>
>><br>
>><br>
>> On Wed, 13 Jan 2021 18:35:26 +0100, Pierre Tardy <<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>> <br>
>> wrote:<br>
>><br>
>> >> Regarding the profiler, I also had some problems running it for a <br>
>> longer<br>
>> > time, so if you find a fix, please share it with me.<br>
>> > It was a bytes versus string issue indeed in the python parts.<br>
>> ><br>
>> > I did struggle to build the project again as expected, but managed to<br>
>> > hack<br>
>> > something eventually.<br>
>> ><br>
>> > see <a href="https://pypi.org/project/buildbot-profiler/1.3.1/" rel="noreferrer" target="_blank">https://pypi.org/project/buildbot-profiler/1.3.1/</a><br>
>> ><br>
>> > I did verify the profile duration is now working.<br>
>> ><br>
>> > Regards<br>
>> > Pierre<br>
>> ><br>
>> ><br>
>> > Le mer. 13 janv. 2021 à 12:49, Vlad Bogolin <<a href="mailto:vlad@mariadb.org" target="_blank">vlad@mariadb.org</a>> a <br>
>> écrit :<br>
>> ><br>
>> >> Hi,<br>
>> >><br>
>> >> So the changes issue I was referring to doesn't seem to be fixed (I<br>
>> >> checked the latest Buildbot code) and looked back over my changes. <br>
>> The<br>
>> >> problem that I identified is here<br>
>> >><br>
>> <a href="https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L320" rel="noreferrer" target="_blank">https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L320</a><br>
>> >> because is some cases there would be an unmatched_filter or<br>
>> >> unmatched_order. *So if this is indeed the case, you should see the<br>
>> >> warning in the buildbot log file:*<br>
>> >><br>
>> >> "Warning: limited data api query is not backed by db because of<br>
>> >> following<br>
>> >> filters..." as defined here<br>
>> >><br>
>> <a href="https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L322" rel="noreferrer" target="_blank">https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L322</a><br>
>> >><br>
>> >> There are two reasons why this happens. One, an incomplete <br>
>> definition of<br>
>> >> the fieldMapping for the data/changes.py and this would be the fix:<br>
>> >><br>
>> >> +++ b/master/buildbot/data/changes.py<br>
>> >> @@ -42,6 +42,19 @@ class FixerMixin:<br>
>> >> return change<br>
>> >> fieldMapping = {<br>
>> >> 'changeid': '<a href="http://changes.id" rel="noreferrer" target="_blank">changes.id</a>',<br>
>> >> + 'author': 'changes.author',<br>
>> >> + 'committer': 'changes.committer',<br>
>> >> + 'comments': 'changes.comments',<br>
>> >> + 'branch': 'changes.branch',<br>
>> >> + 'revision': 'changes.revision',<br>
>> >> + 'revlink': 'changes.revlink',<br>
>> >> + 'when_timestamp': 'changes.when_timestamp',<br>
>> >> + 'category': 'changes.category',<br>
>> >> + 'repository': 'changes.repository',<br>
>> >> + 'codebase': 'changes.codebase',<br>
>> >> + 'project': 'changes.project',<br>
>> >> + 'sourcestampid': 'changes.sourcestampid',<br>
>> >> + 'parent_changeids': 'changes.parent_changeids',<br>
>> >> }<br>
>> >><br>
>> >> and two not having all the columns in the select statement in order <br>
>> to<br>
>> >> be<br>
>> >> able to check for matched/unmatched filtering or ordering as it is <br>
>> done<br>
>> >> here<br>
>> >><br>
>> <a href="https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L269" rel="noreferrer" target="_blank">https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L269</a><br>
>> .<br>
>> >> My solution was to get all the fields from the changes table from the<br>
>> >> database (don't know if this is the best approach) as you can see <br>
>> here:<br>
>> >><br>
>> >> +++ b/master/buildbot/db/changes.py<br>
>> >> @@ -249,7 +249,7 @@ class<br>
>> >> ChangesConnectorComponent(base.DBConnectorComponent):<br>
>> >> def thd(conn):<br>
>> >> # get the changeids from the 'changes' table<br>
>> >> changes_tbl = self.db.model.changes<br>
>> >> - q = sa.select([changes_tbl.c.changeid])<br>
>> >> + q = changes_tbl.select()<br>
>> >><br>
>> >> However, since only the changeid would be needed, don't sure if this<br>
>> >> would<br>
>> >> be the right approach. Also, I would suspect some missing tests<br>
>> because<br>
>> >> I<br>
>> >> would expect this to be a pretty common use case.<br>
>> >><br>
>> >> Regarding the profiler, I also had some problems running it for a <br>
>> longer<br>
>> >> time, so if you find a fix, please share it with me.<br>
>> >><br>
>> >> Cheers,<br>
>> >> Vlad<br>
>> >><br>
>> >> On Wed, Jan 13, 2021 at 1:33 PM Pierre Tardy <<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>> <br>
>> wrote:<br>
>> >><br>
>> >>><br>
>> >>> I am not sure why this wouldn't work. I vaguely recall there was an<br>
>> >>> issue<br>
>> >>> there, but can't figure it out staring at the code.<br>
>> >>> As this is quite ancient, I am not sure the JS part will even build<br>
>> >>> anymore :-/<br>
>> >>><br>
>> >>> You can change the default values at that line in the python<br>
>> >>><br>
>> >>><br>
>> <a href="https://github.com/tardyp/buildbot_profiler/blob/master/buildbot_profiler/api.py#L193" rel="noreferrer" target="_blank">https://github.com/tardyp/buildbot_profiler/blob/master/buildbot_profiler/api.py#L193</a><br>
>> >>> I think you will be able to force them by editing this file inside <br>
>> your<br>
>> >>> virtualenv..<br>
>> >>><br>
>> >>><br>
>> >>> Regards<br>
>> >>> Pierre<br>
>> >>><br>
>> >>><br>
>> >>> Le mer. 13 janv. 2021 à 11:46, Yngve N. Pettersen <br>
>> <<a href="mailto:yngve@vivaldi.com" target="_blank">yngve@vivaldi.com</a>><br>
>> a<br>
>> >>> écrit :<br>
>> >>><br>
>> >>>> > I insist on the buildbot profiler. What I was saying before is<br>
>> that<br>
>> >>>> you<br>
>> >>>> > need to hit the record button before the problem appears, and <br>
>> put a<br>
>> >>>> large<br>
>> >>>> > enough record time to be sure to catch a spike.<br>
>> >>>> > Then, you will be able to zoom to the cpu spike and catch the <br>
>> issue<br>
>> >>>> > precisely.<br>
>> >>>> ><br>
>> >>>> > If the spike is in the order of minutes like you said, you can<br>
>> >>>> configure<br>
>> >>>> > it<br>
>> >>>> > like this and get enough samples to get enough evidence to where <br>
>> the<br>
>> >>>> code<br>
>> >>>> > is actually spending time:<br>
>> >>>> ><br>
>> >>>> > ProfilerService(frequency=500, gatherperiod=60 * 60, <br>
>> mode='virtual',<br>
>> >>>> > basepath=None, wantBuilds=100<br>
>> >>>><br>
>> >>>> I tried configuring this with the settings dropdown in the WebGUI<br>
>> >>>> plugin,<br>
>> >>>> but AFAICT it is not working, it only gathers info for 30 seconds.<br>
>> >>>><br>
>> >>>> I guess I must be holding it incorrectly.<br>
>> >>>><br>
>> >>>> > This will record for one hour, and mitigate the memory used if <br>
>> you<br>
>> >>>> worry<br>
>> >>>> > about it.<br>
>> >>>><br>
>> >>>> --<br>
>> >>>> Sincerely,<br>
>> >>>> Yngve N. Pettersen<br>
>> >>>> Vivaldi Technologies AS<br>
>> >>>><br>
>> >>><br>
>> >><br>
>> >> --<br>
>> >> Vlad<br>
>> >><br>
>><br>
>><br>
>> --<br>
>> Sincerely,<br>
>> Yngve N. Pettersen<br>
>> Vivaldi Technologies AS<br>
<br>
<br>
-- <br>
Sincerely,<br>
Yngve N. Pettersen<br>
Vivaldi Technologies AS<br>
</blockquote></div>