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 <[email protected]> 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 <[email protected]> > 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 < >> [email protected]> 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 <[email protected]> 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 < >>>> [email protected]> 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 <[email protected]> >>>>> wrote: >>>>> >>>>>> I'll take a look. >>>>>> >>>>>> Le mer. 10 août 2016 12:45, Francesco Di Mizio < >>>>>> [email protected]> 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 < >>>>>>> [email protected]> wrote: >>>>>>> >>>>>>>> Thanks for that Pierre. I have it on on production and the >>>>>>>> performances do not degrade indeed. >>>>>>>> >>>>>>>> buildbot@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 <[email protected]> >>>>>>>> wrote: >>>>>>>> >>>>>>>>> One can also use Intel® VTune™, you know... :-) >>>>>>>>> >>>>>>>>> Thanks, >>>>>>>>> Vasily >>>>>>>>> 09 авг. 2016 г. 23:56 пользователь "Pierre Tardy" < >>>>>>>>> [email protected]> написал: >>>>>>>>> >>>>>>>>>> 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 < >>>>>>>>>> [email protected]> 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 <[email protected]> >>>>>>>>>>> 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 < >>>>>>>>>>>> [email protected]> 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 < >>>>>>>>>>>>> [email protected]> 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 <[email protected]> >>>>>>>>>>>>>> wrote: >>>>>>>>>>>>>> >>>>>>>>>>>>>>> Also watch 'top' and see if poller processes are hogging >>>>>>>>>>>>>>> resources. >>>>>>>>>>>>>>> >>>>>>>>>>>>>> >>>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> _______________________________________________ >>>>>>>>>> users mailing list >>>>>>>>>> [email protected] >>>>>>>>>> https://lists.buildbot.net/mailman/listinfo/users >>>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>> >>>>> >>> >>
% 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
_______________________________________________ users mailing list [email protected] https://lists.buildbot.net/mailman/listinfo/users
