[users at bb.net] buildbot CPU usage
Francesco Di Mizio
francescodimizio at gmail.com
Fri Aug 12 12:21:16 UTC 2016
Sure thing. it's attached.
Please note the sampe count has been stuck at 51 for over 1 hour even if
the master is running.
On Fri, Aug 12, 2016 at 12:38 PM, Pierre Tardy <tardyp at gmail.com> wrote:
> The first lines are the important ones. Can you send the full file?
>
> Le ven. 12 août 2016 12:23, Francesco Di Mizio <francescodimizio at gmail.com>
> a écrit :
>
>> It does work but statprof seems to stop getting samples. Last few lines
>> from it:
>>
>> 2016-08-12 10:19:43+0000 [-] 0.00 0.06 0.00
>> banana.py:167:gotItem
>> 2016-08-12 10:19:43+0000 [-] 0.00 0.01 0.00
>> policies.py:718:setTimeout
>> 2016-08-12 10:19:43+0000 [-] 0.00 0.01 0.00
>> encoder.py:434:_iterencode
>> 2016-08-12 10:19:43+0000 [-] ---
>> 2016-08-12 10:19:43+0000 [-] Sample count: 51
>> 2016-08-12 10:19:43+0000 [-] Total time: 0.510000 seconds
>>
>> The server is running.
>>
>> On Thu, Aug 11, 2016 at 10:46 AM, Francesco Di Mizio <
>> francescodimizio at gmail.com> wrote:
>>
>>> Pierre many thanks for that. I do not remember why the force scheduler
>>> api didnt suite my needs, that was my first approach.
>>> I will try the new snippet when I get to work in a few hours.
>>>
>>> On Wed, Aug 10, 2016 at 11:18 PM, Pierre Tardy <tardyp at gmail.com> wrote:
>>>
>>>> Hi,
>>>>
>>>> After carefully looking at your code, it does not look to have obvious
>>>> performance flaw.
>>>> I think it would have been cheaper for you to just use the
>>>> forcescheduler REST api, but if that code works for you this is totally
>>>> fine.
>>>>
>>>> I saw that you did not manage to get sample in your prod as well, so I
>>>> did look at my code again, and now I am able to see the samples.
>>>>
>>>> statprof does not like to stop before start
>>>>
>>>> Please try again with this code:
>>>>
>>>>
>>>> import statprof
>>>> from twisted.application.internet import TimerService
>>>> from buildbot.util.service import BuildbotService
>>>> class BuildbotTimerService(TimerService, BuildbotService):
>>>> name = "timer"
>>>> def __init__(self):
>>>> BuildbotService.__init__(self)
>>>> TimerService.__init__(self, 10, self.dump_stats)
>>>> self.started = False
>>>> def dump_stats(self):
>>>> if not self.started:
>>>> statprof.start()
>>>> self.started = True
>>>> return
>>>> statprof.stop()
>>>> with open("profile.txt", "w") as f:
>>>> statprof.display(f)
>>>> statprof.display()
>>>> statprof.start()
>>>>
>>>> c['services'] = [ BuildbotTimerService() ]
>>>>
>>>>
>>>>
>>>> Le mer. 10 août 2016 à 14:14, Francesco Di Mizio <
>>>> francescodimizio at gmail.com> a écrit :
>>>>
>>>>> Many thanks. Find it attached.
>>>>>
>>>>> It's a tiny http server. People use a web page to send an HTTP request
>>>>> to it to kick off builds.
>>>>>
>>>>>
>>>>> On Wed, Aug 10, 2016 at 1:55 PM, Pierre Tardy <tardyp at gmail.com>
>>>>> wrote:
>>>>>
>>>>>> I'll take a look.
>>>>>>
>>>>>> Le mer. 10 août 2016 12:45, Francesco Di Mizio <
>>>>>> francescodimizio at gmail.com> a écrit :
>>>>>>
>>>>>>> I am starting to think it may be due to my own custom scheduler. If
>>>>>>> I uploaded the code somewhere could anybody take a look? it's a 150 lines
>>>>>>> py script.
>>>>>>>
>>>>>>> On Wed, Aug 10, 2016 at 12:10 PM, Francesco Di Mizio <
>>>>>>> francescodimizio at gmail.com> wrote:
>>>>>>>
>>>>>>>> Thanks for that Pierre. I have it on on production and the
>>>>>>>> performances do not degrade indeed.
>>>>>>>>
>>>>>>>> buildbot at e2123a50d1fb:~$ cat profile.txt
>>>>>>>> No samples recorded.
>>>>>>>>
>>>>>>>> I need to study statprof a bit now ;)
>>>>>>>>
>>>>>>>> On Wed, Aug 10, 2016 at 11:20 AM, Vasily <vassnlit at gmail.com>
>>>>>>>> wrote:
>>>>>>>>
>>>>>>>>> One can also use Intel® VTune™, you know... :-)
>>>>>>>>>
>>>>>>>>> Thanks,
>>>>>>>>> Vasily
>>>>>>>>> 09 авг. 2016 г. 23:56 пользователь "Pierre Tardy" <
>>>>>>>>> tardyp at gmail.com> написал:
>>>>>>>>>
>>>>>>>>>> You can add following snippet to your master.cfg. It looks
>>>>>>>>>> statprof does not work on osx, so I cannot test it to the end, but I know
>>>>>>>>>> similar did work on my prod
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> import statprof
>>>>>>>>>> from twisted.application.internet import TimerService
>>>>>>>>>> from buildbot.util.service import BuildbotService
>>>>>>>>>> class BuildbotTimerService(TimerService, BuildbotService):
>>>>>>>>>> name = "timer"
>>>>>>>>>> def __init__(self):
>>>>>>>>>> BuildbotService.__init__(self)
>>>>>>>>>> TimerService.__init__(self, 10, self.dump_stats)
>>>>>>>>>> def dump_stats(self):
>>>>>>>>>> statprof.stop()
>>>>>>>>>> with open("profile.txt", "w") as f:
>>>>>>>>>> statprof.display(f)
>>>>>>>>>> statprof.start()
>>>>>>>>>>
>>>>>>>>>> c['services'] = [ BuildbotTimerService() ]
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Le mar. 9 août 2016 à 21:44, Francesco Di Mizio <
>>>>>>>>>> francescodimizio at gmail.com> a écrit :
>>>>>>>>>>
>>>>>>>>>>> Pierre,
>>>>>>>>>>>
>>>>>>>>>>> if you can enlighten on how you intend to use statprof, I will
>>>>>>>>>>> be happy to give it a try.
>>>>>>>>>>> This problem here is on top of my list right now as it's making
>>>>>>>>>>> my prod env unusable.
>>>>>>>>>>>
>>>>>>>>>>> On Tue, Aug 9, 2016 at 8:25 PM, Pierre Tardy <tardyp at gmail.com>
>>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Please note that cprofile is very intrusive and will lead to
>>>>>>>>>>>> about 3x slower code.
>>>>>>>>>>>>
>>>>>>>>>>>> So I would not run that in prod. This is why I prefer statprof
>>>>>>>>>>>> which is using a non intrusive method to get the stats
>>>>>>>>>>>>
>>>>>>>>>>>> Le mar. 9 août 2016 19:15, Francesco Di Mizio <
>>>>>>>>>>>> francescodimizio at gmail.com> a écrit :
>>>>>>>>>>>>
>>>>>>>>>>>>> On a side note I have managed to get twistd to dump a blob I
>>>>>>>>>>>>> can then load and analyze. Got to see if I can run this in production.
>>>>>>>>>>>>> If anybody is curious the following worked for me:
>>>>>>>>>>>>> twistd --savestats -n --profiler=cprofile --profile=/crcdata/
>>>>>>>>>>>>> profile.stats -y ./buildbot.tac
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Tue, Aug 9, 2016 at 5:21 PM, Francesco Di Mizio <
>>>>>>>>>>>>> francescodimizio at gmail.com> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> Well that's expected to an extent - p4 poller is running 'p4
>>>>>>>>>>>>>> changes' every pollinterval seconds.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Anyway just as a test I've tried to disable the poller and
>>>>>>>>>>>>>> still at times I am seeing the CPU spiking up to above 100%. I believe I
>>>>>>>>>>>>>> really need to profile this somehow.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On Tue, Aug 9, 2016 at 5:08 PM, Dan Kegel <dank at kegel.com>
>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Also watch 'top' and see if poller processes are hogging
>>>>>>>>>>>>>>> resources.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>> _______________________________________________
>>>>>>>>>> users mailing list
>>>>>>>>>> users at buildbot.net
>>>>>>>>>> https://lists.buildbot.net/mailman/listinfo/users
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>
>>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.buildbot.net/pipermail/users/attachments/20160812/ef0c504a/attachment.html>
-------------- next part --------------
% cumulative self
time seconds seconds name
33.33 0.17 0.17 epollreactor.py:379:doPoll
3.92 0.03 0.02 util.py:713:untilConcludes
3.92 0.02 0.02 logfile.py:112:write
1.96 0.01 0.01 type_api.py:63:operate
1.96 0.01 0.01 pathmatch.py:83:_compile
1.96 0.01 0.01 sre_parse.py:397:_parse
1.96 0.01 0.01 pb.py:378:__init__
1.96 0.01 0.01 pprint.py:262:_safe_repr
1.96 0.01 0.01 abc.py:132:__instancecheck__
1.96 0.01 0.01 service.py:393:reconfigServiceWithBuildbotConfig
1.96 0.01 0.01 buildrequests.py:120:get
1.96 0.01 0.01 service.py:229:reconfigSite
1.96 0.01 0.01 log.py:526:formatTime
1.96 0.01 0.01 base.py:737:_cancelCallLater
1.96 0.01 0.01 _team.py:169:_coordinateThisTask
1.96 0.01 0.01 defer.py:484:_startRunCallbacks
1.96 0.01 0.01 _threadworker.py:106:do
1.96 0.01 0.01 static.py:589:render_GET
1.96 0.01 0.01 service.py:61:master
1.96 0.01 0.01 logfile.py:105:write
1.96 0.01 0.01 interface.py:519:__hash__
1.96 0.01 0.01 resource.py:116:__init__
1.96 0.01 0.01 base.py:148:__init__
1.96 0.03 0.01 _team.py:166:<lambda>
1.96 0.01 0.01 compiler.py:765:visit_Template
1.96 0.01 0.01 pb.py:910:_recvMessage
1.96 0.01 0.01 encoder.py:316:_iterencode_list
1.96 0.01 0.01 jelly.py:730:unjellyInto
1.96 0.01 0.01 ro.py:42:_mergeOrderings
1.96 0.01 0.01 loaders.py:177:get_source
1.96 0.01 0.01 defer.py:565:_runCallbacks
1.96 0.01 0.01 declarations.py:140:implementedByFallback
1.96 0.01 0.01 base.py:42:__init__
0.00 0.51 0.00 twistd.py:29:run
0.00 0.01 0.00 workerforbuilder.py:202:attached
0.00 0.02 0.00 _observer.py:131:__call__
0.00 0.01 0.00 service.py:290:_callbackStartServiceDeferred
0.00 0.19 0.00 epollreactor.py:396:doPoll
0.00 0.01 0.00 jelly.py:577:_jellyIterable
0.00 0.01 0.00 builders.py:42:toTagid
0.00 0.08 0.00 http.py:832:requestReceived
0.00 0.01 0.00 compiler.py:62:generate
0.00 0.01 0.00 interface.py:233:changed
0.00 0.01 0.00 builders.py:45:updateBuilderInfo
0.00 0.01 0.00 base.py:208:_getWorkerInfo
0.00 0.12 0.00 defer.py:1274:unwindGenerator
0.00 0.01 0.00 visitor.py:38:visit
0.00 0.02 0.00 defer.py:306:addCallbacks
0.00 0.01 0.00 parser.py:31:__init__
0.00 0.01 0.00 tcp.py:1074:doRead
0.00 0.01 0.00 __init__.py:250:dumps
0.00 0.08 0.00 defer.py:1131:_inlineCallbacks
0.00 0.01 0.00 workers.py:60:get
0.00 0.01 0.00 pathmatch.py:47:__getitem__
0.00 0.06 0.00 banana.py:243:dataReceived
0.00 0.01 0.00 pprint.py:63:pformat
0.00 0.01 0.00 builder.py:129:reconfigServiceWithBuildbotConfig
0.00 0.01 0.00 flavors.py:127:jellyFor
0.00 0.01 0.00 jelly.py:525:jelly
0.00 0.02 0.00 tcp.py:241:writeSomeData
0.00 0.01 0.00 server.py:178:process
0.00 0.01 0.00 buildrequestdistributor.py:84:_fetchUnclaimedBrdicts
0.00 0.02 0.00 botmaster.py:282:maybeStartBuildsForAllBuilders
0.00 0.01 0.00 protocol.py:966:_connectionMade
0.00 0.02 0.00 buildrequestdistributor.py:348:maybeStartBuildsOn
0.00 0.03 0.00 threads.py:53:deferToThreadPool
0.00 0.01 0.00 lexer.py:533:__init__
0.00 0.02 0.00 buildrequestdistributor.py:376:resetPendingBuildersList
0.00 0.02 0.00 connector.py:125:get
0.00 0.01 0.00 pprint.py:238:format
0.00 0.19 0.00 log.py:84:callWithContext
0.00 0.01 0.00 jelly.py:820:_unjelly_dictionary
0.00 0.01 0.00 http.py:1796:allContentReceived
0.00 0.51 0.00 _twistd_unix.py:222:postApplication
0.00 0.01 0.00 pprint.py:122:pformat
0.00 0.51 0.00 twistd:18:<module>
0.00 0.02 0.00 _legacy.py:93:__call__
0.00 0.01 0.00 environment.py:502:_tokenize
0.00 0.01 0.00 workerforbuilder.py:106:attached
0.00 0.02 0.00 service.py:99:addService
0.00 0.02 0.00 server.py:224:finish
0.00 0.51 0.00 base.py:1194:run
0.00 0.01 0.00 policies.py:723:setTimeout
0.00 0.02 0.00 pb.py:875:proto_message
0.00 0.19 0.00 context.py:118:callWithContext
0.00 0.01 0.00 pprint.py:140:_format
0.00 0.01 0.00 server.py:732:getResourceFor
0.00 0.01 0.00 elements.py:683:operate
0.00 0.01 0.00 pb.py:1324:_cbLogin
0.00 0.01 0.00 environment.py:470:_parse
0.00 0.01 0.00 resource.py:140:render
0.00 0.05 0.00 server.py:234:render
0.00 0.01 0.00 tcp.py:782:__init__
0.00 0.01 0.00 re.py:194:compile
0.00 0.03 0.00 config.py:143:renderIndex
0.00 0.06 0.00 server.py:183:process
0.00 0.01 0.00 buildrequestdistributor.py:184:popNextBuild
0.00 0.02 0.00 http.py:2133:log
0.00 0.01 0.00 static.py:628:createSimilarFile
0.00 0.01 0.00 ro.py:64:ro
0.00 0.01 0.00 flavors.py:118:remoteMessageReceived
0.00 0.03 0.00 logfile.py:201:write
0.00 0.06 0.00 pb.py:563:expressionReceived
0.00 0.03 0.00 connector.py:123:get
0.00 0.36 0.00 base.py:1206:mainLoop
0.00 0.01 0.00 declarations.py:200:implementedByFallback
0.00 0.01 0.00 base.py:601:_sent
0.00 0.01 0.00 <string>:1:<lambda>
0.00 0.02 0.00 http.py:951:finish
0.00 0.02 0.00 protocol.py:494:makeConnection
0.00 0.02 0.00 posixbase.py:602:_doReadOrWrite
0.00 0.19 0.00 context.py:81:callWithContext
0.00 0.01 0.00 buildrequests.py:117:getBuildRequests
0.00 0.02 0.00 buildrequestdistributor.py:439:_sortBuilders
0.00 0.01 0.00 protocol.py:2416:_connectionMade
0.00 0.01 0.00 log.py:557:emit
0.00 0.02 0.00 buildrequestdistributor.py:398:<lambda>
0.00 0.02 0.00 service.py:45:reconfigServiceWithBuildbotConfig
0.00 0.01 0.00 jelly.py:1137:unjelly
0.00 0.02 0.00 defer.py:859:_cbDeferred
0.00 0.01 0.00 server.py:309:render
0.00 0.01 0.00 log.py:550:emit
0.00 0.01 0.00 jelly.py:658:unjelly
0.00 0.09 0.00 http.py:1720:lineReceived
0.00 0.01 0.00 connector.py:122:get
0.00 0.08 0.00 defer.py:1171:_inlineCallbacks
0.00 0.51 0.00 app.py:285:runReactorWithLogging
0.00 0.01 0.00 workers.py:119:getWorker
0.00 0.01 0.00 service.py:336:_activityPoll
0.00 0.01 0.00 environment.py:774:_load_template
0.00 0.01 0.00 environment.py:551:compile
0.00 0.01 0.00 websocket.py:95:connectionMade
0.00 0.02 0.00 service.py:58:setServiceParent
0.00 0.15 0.00 base.py:798:runUntilCurrent
0.00 0.01 0.00 sre_parse.py:716:parse
0.00 0.02 0.00 defer.py:1313:execute
0.00 0.01 0.00 pprint.py:226:_repr
0.00 0.01 0.00 sre_parse.py:324:_parse_sub
0.00 0.01 0.00 operators.py:303:__eq__
0.00 0.01 0.00 measured_service.py:29:reconfigServiceWithBuildbotConfig
0.00 0.01 0.00 base.py:222:startService
0.00 0.01 0.00 buildrequests.py:125:get
0.00 0.03 0.00 pool.py:207:do
0.00 0.02 0.00 log.py:282:msg
0.00 0.02 0.00 service.py:408:reconfigServiceWithBuildbotConfig
0.00 0.01 0.00 encoder.py:332:_iterencode_list
0.00 0.01 0.00 workers.py:198:getWorkers
0.00 0.01 0.00 tcp.py:1073:doRead
0.00 0.06 0.00 banana.py:130:callExpressionReceived
0.00 0.02 0.00 abstract.py:256:doWrite
0.00 0.02 0.00 base.py:216:setServiceParent
0.00 0.01 0.00 base.py:223:startService
0.00 0.01 0.00 resultspec.py:233:apply
0.00 0.01 0.00 server.py:179:process
0.00 0.01 0.00 interface.py:190:__init__
0.00 0.01 0.00 lexer.py:397:get_lexer
0.00 0.01 0.00 _threadworker.py:109:do
0.00 0.01 0.00 jelly.py:1123:jelly
0.00 0.01 0.00 environment.py:515:_generate
0.00 0.17 0.00 defer.py:588:_runCallbacks
0.00 0.17 0.00 defer.py:501:_startRunCallbacks
0.00 0.02 0.00 loaders.py:125:load
0.00 0.01 0.00 jelly.py:466:jelly
0.00 0.03 0.00 config.py:54:render_GET
0.00 0.01 0.00 pb.py:718:registerReference
0.00 0.02 0.00 botmaster.py:170:reconfigServiceWithBuildbotConfig
0.00 0.03 0.00 resource.py:61:asyncRenderHelper
0.00 0.04 0.00 threadable.py:53:sync
0.00 0.18 0.00 defer.py:393:callback
0.00 0.01 0.00 declarations.py:65:__init__
0.00 0.01 0.00 policies.py:687:callLater
0.00 0.01 0.00 pb.py:812:serialize
0.00 0.02 0.00 buildrequestdistributor.py:397:xform
0.00 0.01 0.00 buildrequestdistributor.py:494:_maybeStartBuildsOnBuilder
0.00 0.15 0.00 tcp.py:215:_dataReceived
0.00 0.01 0.00 static.py:214:__init__
0.00 0.02 0.00 lru.py:220:handle_result
0.00 0.01 0.00 service.py:84:reconfigServiceWithBuildbotConfig
0.00 0.17 0.00 posixbase.py:597:_doReadOrWrite
0.00 0.01 0.00 interface.py:214:__setBases
0.00 0.02 0.00 buildrequestdistributor.py:403:_defaultSorter
0.00 0.01 0.00 builder.py:245:attached
0.00 0.01 0.00 buildrequestdistributor.py:221:_getNextUnclaimedBuildRequest
0.00 0.02 0.00 defer.py:1318:run
0.00 0.16 0.00 defer.py:1128:_inlineCallbacks
0.00 0.01 0.00 http.py:1672:connectionMade
0.00 0.51 0.00 app.py:352:run
0.00 0.16 0.00 defer.py:1184:gotResult
0.00 0.01 0.00 jelly.py:621:unjellyFull
0.00 0.01 0.00 workers.py:118:findWorkerId
0.00 0.04 0.00 defer.py:150:maybeDeferred
0.00 0.19 0.00 log.py:101:callWithLogger
0.00 0.01 0.00 manager.py:127:newConnection
0.00 0.51 0.00 app.py:617:run
0.00 0.01 0.00 resource.py:98:getChildForRequest
0.00 0.02 0.00 buildrequestdistributor.py:440:<lambda>
0.00 0.15 0.00 base.py:1203:mainLoop
0.00 0.02 0.00 buildrequestdistributor.py:387:_maybeStartBuildsOn
0.00 0.15 0.00 tcp.py:209:doRead
0.00 0.51 0.00 twistd.py:25:runApp
0.00 0.01 0.00 rest.py:399:renderRest
0.00 0.02 0.00 builder.py:171:getOldestRequestTime
0.00 0.01 0.00 base.py:225:startService
0.00 0.04 0.00 pb.py:933:proto_answer
0.00 0.01 0.00 resultspec.py:186:apply
0.00 0.03 0.00 environment.py:812:get_template
0.00 0.01 0.00 re.py:249:_compile
0.00 0.01 0.00 builders.py:95:updateBuilderInfo
0.00 0.01 0.00 encoder.py:209:encode
0.00 0.01 0.00 pb.py:889:_recvMessage
0.00 0.01 0.00 buildrequestdistributor.py:57:chooseNextBuild
0.00 0.01 0.00 encoder.py:408:_iterencode_dict
0.00 0.01 0.00 buildrequestdistributor.py:475:_activityLoop
0.00 0.02 0.00 defer.py:317:addCallback
0.00 0.01 0.00 resource.py:70:finish
0.00 0.04 0.00 resource.py:250:render
0.00 0.01 0.00 resource.py:201:getChildWithDefault
0.00 0.01 0.00 connector.py:109:getEndpoint
0.00 0.01 0.00 base.py:712:callLater
0.00 0.01 0.00 lexer.py:412:<lambda>
0.00 0.02 0.00 environment.py:786:_load_template
0.00 0.08 0.00 http.py:1799:allContentReceived
0.00 0.01 0.00 pprint.py:314:_safe_repr
0.00 0.01 0.00 tags.py:28:findTagId
0.00 0.01 0.00 base.py:91:cancel
0.00 0.51 0.00 app.py:364:startReactor
0.00 0.01 0.00 sre_compile.py:572:compile
0.00 0.03 0.00 threadpool.py:265:callInThreadWithCallback
0.00 0.01 0.00 abstract.py:141:_getLogPrefix
0.00 0.02 0.00 _legacy.py:154:publishToNewObserver
0.00 0.01 0.00 static.py:281:getChild
0.00 0.01 0.00 base.py:88:findSomethingId
0.00 0.01 0.00 environment.py:555:compile
0.00 0.09 0.00 basic.py:571:dataReceived
0.00 0.01 0.00 workers.py:33:findWorkerId
0.00 0.01 0.00 declarations.py:68:changed
0.00 0.01 0.00 pb.py:825:unserialize
0.00 0.06 0.00 banana.py:167:gotItem
0.00 0.01 0.00 policies.py:718:setTimeout
0.00 0.01 0.00 encoder.py:434:_iterencode
---
Sample count: 51
Total time: 0.510000 seconds
More information about the users
mailing list