[users at bb.net] Performance issues in 2.10

Yngve N. Pettersen yngve at vivaldi.com
Thu Jan 14 12:22:51 UTC 2021


Hi,

Hmmm, there is a bit of a difference between a 2ms sampling interval and a  
500 ms one :P .

There isn't that much load on the machine (we actually expanded CPU count  
threefold, and more than doubled RAM trying to eliminate those potential  
issues; I am not aware of any significant load on the VM-host), and I have  
seen this freeze happen while there was no build activity.

This VM is just running the buildbot and the postgresql DB; There should  
be no disk speed issues.

What I have noticed in the netdata graphs is that the Pressure Stall  
Information graph  
<https://www.kernel.org/doc/html/latest/accounting/psi.html> also spikes,  
mostly in the some10 line, no idea why or how bad the stall really is.

I have had one colleague report that pasting the page URL into a new tab  
had the page load quickly, while the original page was still blank. I have  
not tried that yet, but I have tried to load two different pages, and both  
remained blank.


*However*, during the last case of this, I was checking the inspector  
(planning to check network traffic) and noticed that there were console  
reports from code we had added on the page I was *leaving*. It seems that  
this code continued running after I navigated away from the page, to the  
previous page in the history.

The modified code is used to load and display changelog entries for each  
build displayed on the builder page; this was developed in response to a  
feature request from our CEO, and this week was the first time it was  
deployed in production.

The current version of that code triggers a changelog retrieval for each  
build in the list in the $scope.builds.onNew function in  
www/base/src/app/builders/builder/builder.controller.js.

If this code is indeed involved in the freezes, then it appears that the  
code continues to run after the page is no longer the current page. IMO  
those calls should have been unsubscribed when the navigation started.

Further (if this is indeed what caused the issue):

   * it seems like the onNew calls for the changes entries got priority  
above what was going on on the new page

   * It also seems that the builds onNew call is triggered for builds that  
are not yet visible on the page, and perhaps are also never going to be  
displayed since they beyond the limit of what is to be displayed unless  
the user request more. If this triggers loading of 1000 builds' changelog  
entries .....

As far as the changelog info is concerned, we don't actually need it until  
the build info is rendered on the page, so an "onDisplay" call would be  
better for our purposes.



I have just backed those changes out of our deployed custom www-base  
module, so that we can see if that was involved in our issue.

BTW, I am noticing some problems with pip and this custom module. It seems  
that the requirement declaration is set such that only the 2.10.0 package  
can be loaded; this caused issues since the default version for building  
the module is 2.10.1-devX; I had to force the version to 2.10.0 to be able  
to load it, and that is causing warnings from pip, and problems installing  
an updated module. AFAICT this started becoming a problem with recent  
versions of Pip. (Note: I am not interested in building the whole buildbot  
package bundle; in fact, I'd prefer to register our customization in a  
different manner)


On Thu, 14 Jan 2021 10:07:32 +0100, Pierre Tardy <tardyp at gmail.com> wrote:

> (Back to mailing list)
>
> Thanks for this data. Here is how you would read it:
>
>
> [image: image.png]
> In the left, you get the main thread activity. You can say that because  
> the
> bottom frame(s) are about startReactor.
> In the right, you get what happens in the threads. You can say that  
> because
> we see threading.py in the last bottom frame.
>
> You can see that the reactor thread does pretty much nothing:
> [image: image.png]
> doPoll is just the reactor waiting for events (that's 1 third of the
> samples)
> then the left part is about getting sourcestams, and waiting the  
> dbthread.
> then the right part is log management, which is usually the major part  
> of a
> buildbot load.
>
> On the thread side, this is pretty similar picture. We can see that most  
> of
> the load is managing source stamps.
> [image: image.png]
> So frankly, I wouldn't say this is an obvious profile of a blocked  
> buildbot
> master.
>
> The reactor does pretty much nothing. Reading 300 sourcestamps requests  
> by
> second from the db shouldn't be that much of a problem with modern HW.
> We can see that the profiler itself has difficulties to run in time, as  
> we
> see some profiler stacks.
> BTW, I gave wrong advice last time, I told you to put 500HZ frequency  
> while
> I meant 500ms timer. we should rather put a 2HZ to have 2 sample per  
> second
> and per thread. This may avoid to disrupt too much the measurment
> (Heisenberg principle).
>
> So I thought about memory or disk starvation. Do you have any other load  
> in
> the master that would starve CPU ressources?
> I can see that there is 28GB memory free so no memory starvation. but the
> profiler do not output the loadaverage.
> Do we have db connection pool or threadpool starvation?
> Do we have disk io or network io starvation?
>
> Regards
> Pierre
>
>
> Le jeu. 14 janv. 2021 à 00:09, Yngve N. Pettersen <yngve at vivaldi.com> a
> écrit :
>
>> Hi,
>>
>> I finally got a trace of the problem area.
>>
>> I wasn't able to make sense of the profile, maybe you can? zip attached
>>
>> The area of interest is the ~400 second segment towards the end, which
>> matches the bump in the PNG.
>>
>> This happened while reloading the Build>Builders page after loading a
>> build and then returning to the previous point in the history. Loading  
>> of
>> the page took about 5 minutes of the 7 minutes of high load.
>>
>> The Python process hit ~120% CPU
>>
>>
>> On Wed, 13 Jan 2021 18:35:26 +0100, Pierre Tardy <tardyp at gmail.com>  
>> wrote:
>>
>> >> Regarding the profiler, I also had some problems running it for a  
>> longer
>> > time, so if you find a fix, please share it with me.
>> > It was a bytes versus string issue indeed in the python parts.
>> >
>> > I did struggle to build the project again as expected, but managed to
>> > hack
>> > something eventually.
>> >
>> > see https://pypi.org/project/buildbot-profiler/1.3.1/
>> >
>> > I did verify the profile duration is now working.
>> >
>> > Regards
>> > Pierre
>> >
>> >
>> > Le mer. 13 janv. 2021 à 12:49, Vlad Bogolin <vlad at mariadb.org> a  
>> écrit :
>> >
>> >> Hi,
>> >>
>> >> So the changes issue I was referring to doesn't seem to be fixed (I
>> >> checked the latest Buildbot code) and looked back over my changes.  
>> The
>> >> problem that I identified is here
>> >>
>> https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L320
>> >> because is some cases there would be an unmatched_filter or
>> >> unmatched_order. *So if this is indeed the case, you should see the
>> >> warning in the buildbot log file:*
>> >>
>> >> "Warning: limited data api query is not backed by db because of
>> >> following
>> >> filters..." as defined here
>> >>
>> https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L322
>> >>
>> >> There are two reasons why this happens. One, an incomplete  
>> definition of
>> >> the fieldMapping for the data/changes.py and this would be the fix:
>> >>
>> >> +++ b/master/buildbot/data/changes.py
>> >> @@ -42,6 +42,19 @@ class FixerMixin:
>> >>          return change
>> >>      fieldMapping = {
>> >>          'changeid': 'changes.id',
>> >> +        'author': 'changes.author',
>> >> +        'committer': 'changes.committer',
>> >> +        'comments': 'changes.comments',
>> >> +        'branch': 'changes.branch',
>> >> +        'revision': 'changes.revision',
>> >> +        'revlink': 'changes.revlink',
>> >> +        'when_timestamp': 'changes.when_timestamp',
>> >> +        'category': 'changes.category',
>> >> +        'repository': 'changes.repository',
>> >> +        'codebase': 'changes.codebase',
>> >> +        'project': 'changes.project',
>> >> +        'sourcestampid': 'changes.sourcestampid',
>> >> +        'parent_changeids': 'changes.parent_changeids',
>> >>      }
>> >>
>> >> and two not having all the columns in the select statement in order  
>> to
>> >> be
>> >> able to check for matched/unmatched filtering or ordering as it is  
>> done
>> >> here
>> >>
>> https://github.com/buildbot/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/data/resultspec.py#L269
>> .
>> >> My solution was to get all the fields from the changes table from the
>> >> database (don't know if this is the best approach) as you can see  
>> here:
>> >>
>> >> +++ b/master/buildbot/db/changes.py
>> >> @@ -249,7 +249,7 @@ class
>> >> ChangesConnectorComponent(base.DBConnectorComponent):
>> >>          def thd(conn):
>> >>              # get the changeids from the 'changes' table
>> >>              changes_tbl = self.db.model.changes
>> >> -            q = sa.select([changes_tbl.c.changeid])
>> >> +            q = changes_tbl.select()
>> >>
>> >> However, since only the changeid would be needed, don't sure if this
>> >> would
>> >> be the right approach. Also, I would suspect some missing tests
>> because
>> >> I
>> >> would expect this to be a pretty common use case.
>> >>
>> >> Regarding the profiler, I also had some problems running it for a  
>> longer
>> >> time, so if you find a fix, please share it with me.
>> >>
>> >> Cheers,
>> >> Vlad
>> >>
>> >> On Wed, Jan 13, 2021 at 1:33 PM Pierre Tardy <tardyp at gmail.com>  
>> wrote:
>> >>
>> >>>
>> >>> I am not sure why this wouldn't work. I vaguely recall there was an
>> >>> issue
>> >>> there, but can't figure it out staring at the code.
>> >>> As this is quite ancient, I am not sure the JS part will even build
>> >>> anymore :-/
>> >>>
>> >>> You can change the default values at that line in the python
>> >>>
>> >>>
>> https://github.com/tardyp/buildbot_profiler/blob/master/buildbot_profiler/api.py#L193
>> >>> I think you will be able to force them by editing this file inside  
>> your
>> >>> virtualenv..
>> >>>
>> >>>
>> >>> Regards
>> >>> Pierre
>> >>>
>> >>>
>> >>> Le mer. 13 janv. 2021 à 11:46, Yngve N. Pettersen  
>> <yngve at vivaldi.com>
>> a
>> >>> écrit :
>> >>>
>> >>>> > I insist on the buildbot profiler. What I was saying before is
>> that
>> >>>> you
>> >>>> > need to hit the record button before the problem appears, and  
>> put a
>> >>>> large
>> >>>> > enough record time to be sure to catch a spike.
>> >>>> > Then, you will be able to zoom to the cpu spike and catch the  
>> issue
>> >>>> > precisely.
>> >>>> >
>> >>>> > If the spike is in the order of minutes like you said, you can
>> >>>> configure
>> >>>> > it
>> >>>> > like this and get enough samples to get enough evidence to where  
>> the
>> >>>> code
>> >>>> > is actually spending time:
>> >>>> >
>> >>>> > ProfilerService(frequency=500, gatherperiod=60 * 60,  
>> mode='virtual',
>> >>>> > basepath=None, wantBuilds=100
>> >>>>
>> >>>> I tried configuring this with the settings dropdown in the WebGUI
>> >>>> plugin,
>> >>>> but AFAICT it is not working, it only gathers info for 30 seconds.
>> >>>>
>> >>>> I guess I must be holding it incorrectly.
>> >>>>
>> >>>> > This will record for one hour, and mitigate the memory used if  
>> you
>> >>>> worry
>> >>>> > about it.
>> >>>>
>> >>>> --
>> >>>> Sincerely,
>> >>>> Yngve N. Pettersen
>> >>>> Vivaldi Technologies AS
>> >>>>
>> >>>
>> >>
>> >> --
>> >> Vlad
>> >>
>>
>>
>> --
>> Sincerely,
>> Yngve N. Pettersen
>> Vivaldi Technologies AS


-- 
Sincerely,
Yngve N. Pettersen
Vivaldi Technologies AS


More information about the users mailing list