[users at bb.net] Performance issues in 2.10
Pierre Tardy
tardyp at gmail.com
Thu Jan 14 14:21:24 UTC 2021
In the case of the UI customization, this would be hard for me to reason
without the exact actual code.
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.
onNew happens for all new builds that appear, regardless of any paging.
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.
We had a few contributions this week e.g.
https://github.com/buildbot/buildbot/pull/5747 which go in the direction of
more information in the builder page with mouse-over.
Maybe you can go this path in order to get your sourcestamp information.
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.
If the get of the changes is done in onNew, indeed for 1000 builds, this
will probably be done in parallel.
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.
In this case those 1000 request can indeed pile-up, and starve the
threadpool.
If you have a largeVM, and want to make the current code work, maybe you
can raise the db poolsize
https://github.com/tardyp/buildbot/blob/9f1cac1d3bb61baa0b6c836cc18812a64cfa9c2b/master/buildbot/db/enginestrategy.py#L273
hence, you can configure the db_url like this:
"driver://[username:password@]host:port/database?pool_size=20"
Regards
Pierre
Le jeu. 14 janv. 2021 à 13:22, Yngve N. Pettersen <yngve at vivaldi.com> a
écrit :
> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.buildbot.net/pipermail/users/attachments/20210114/fcf29dfb/attachment-0001.html>
More information about the users
mailing list