<div dir="ltr">Thanks Pierre, for the db I use either mysql or postgres, not sqllite. <div>Logs are not suspiciously long - longets might be around 500 lines. Only one step is doing something fancy with the logs by using a LogLineObserver and regexp matching to create other log links.</div><div>That profile snapshot was taked after 230 builds were built.<div><br></div><div>Right now I have 10 workers so that's the max number of builds that can be running simultaniously.</div><div>Those builds get scheduled either by my custon http scheduler (we dwelled on it above) or by the p4 source scheduler polling every 3 minutes.</div><div><br></div><div>As stated previously, developers submit build requests from a webpage to the http scheduler. Upon opening, the web page queries Buildbot's rest API to see if there are already ongoing and/or completed builds for the given p4 changelist. </div><div>The amount of http requests sent to buildbot by one single page instance can vary a lot even in complexity. As an example, every time the web page is asking buildbot what its builders are and that's all, other times it has to ask buildbot for a specifc property's value for a few builds.</div><div>Also the number of coders using this page can go from zero up to any number (reasonably no more than 10) and each instance of the page is unique per coder meaning it'll do its own REST requests to buildbot.</div><div><br></div><div>Furthermore when builds get kicked, the web page opens a websocket connection to buildbot to recieve progress updates on the builds. As builds complete, they get closed. Some may indeed stay dangling upon refreshing.</div></div><div><br></div><div><br></div><div><br></div><div><br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 17, 2016 at 12:05 PM, Pierre Tardy <span dir="ltr"><<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi,<div><br></div><div>Appended is the decoded stats..</div><div>I can only see normal buildbot operations there. just a lot of them. how much loaded is your bot? How many build in parrallel does it have?</div><div>How many workers? What are the size of the logs?</div><div><br></div><div>Most importantly are you using sqlite?</div><div>sqlite only works with one thread in buildbot nine, which could lead indeed to slow UI when there are lots of activity, as UI queries are not prioritized over core queries.</div><div>Other sql backend do not have such issues.</div><div><br></div><div><div>Wed Aug 17 11:47:56 2016 profile.stats</div><div><br></div><div> 235488234 function calls (219896405 primitive calls) in 57689.889 seconds</div><div><font face="monospace"><br></font></div><div><font face="monospace"> Ordered by: cumulative time</font></div><div><font face="monospace"> List reduced from 3158 to 200 due to restriction <200></font></div><div><font face="monospace"><br></font></div><div><font face="monospace"> ncalls tottime percall cumtime percall filename:lineno(function)</font></div><div><font face="monospace"> 1 0.000 0.000 57689.894 57689.894 base.py:1192(run)</font></div><div><font face="monospace"> 1 8.549 8.549 57689.894 57689.894 base.py:1197(mainLoop)</font></div><div><font face="monospace"> 654066 25.880 0.000 55191.310 0.084 epollreactor.py:367(doPoll)</font></div><div><font face="monospace"> 654066 53208.486 0.<a href="tel:081%2053208" value="+3908153208" target="_blank">081 53208</a>.487 0.081 {method 'poll' of 'select.epoll' objects}</font></div><div><font face="monospace">1704464/415799 114.955 0.000 2846.125 0.007 defer.py:1109(_<wbr>inlineCallbacks)</font></div><div><font face="monospace">3434730/688115 212.408 0.000 2740.953 0.004 defer.py:513(_runCallbacks)</font></div><div><font face="monospace">2301115/1429188 3.898 0.000 2521.992 0.002 {method 'send' of 'generator' objects}</font></div><div><font face="monospace"> 654066 19.060 0.000 2475.261 0.004 base.py:787(runUntilCurrent)</font></div><div><font face="monospace">2148660/797905 18.536 0.000 2319.208 0.003 defer.py:371(callback)</font></div><div><font face="monospace">2148861/797914 24.725 0.000 2311.151 0.003 defer.py:484(_<wbr>startRunCallbacks)</font></div><div><font face="monospace">1354560/496825 18.306 0.000 2191.695 0.004 defer.py:1179(gotResult)</font></div><div><font face="monospace"> 382334 11.614 0.000 1956.812 0.005 log.py:88(callWithLogger)</font></div><div><font face="monospace">936750/366288 20.765 0.000 1955.853 0.005 defer.py:1262(unwindGenerator)</font></div><div><font face="monospace"> 382334 11.120 0.000 1943.570 0.005 log.py:81(callWithContext)</font></div><div><font face="monospace"> 382334 3.573 0.000 1918.521 0.005 context.py:117(<wbr>callWithContext)</font></div><div><font face="monospace"> 382334 10.873 0.000 1913.555 0.005 context.py:61(callWithContext)</font></div><div><font face="monospace"> 382322 23.054 0.000 1901.996 0.005 posixbase.py:555(_<wbr>doReadOrWrite)</font></div><div><font face="monospace"> 112747 5.568 0.000 1249.128 0.011 tcp.py:193(doRead)</font></div><div><font face="monospace"> 112747 2.434 0.000 1000.258 0.009 tcp.py:212(_dataReceived)</font></div><div><font face="monospace"> 104450 160.171 0.002 915.091 0.009 banana.py:171(dataReceived)</font></div><div><font face="monospace"> 207384 2.815 0.000 878.622 0.004 logs.py:110(generateEvent)</font></div><div><font face="monospace">449643/249989 7.493 0.000 854.141 0.003 defer.py:129(maybeDeferred)</font></div><div><font face="monospace"> 192309 3.906 0.000 842.046 0.004 logs.py:130(appendLog)</font></div><div><font face="monospace"> 274303 5.751 0.000 790.022 0.003 pool.py:205(do)</font></div><div><font face="monospace"> 274364 10.202 0.000 784.280 0.003 threads.py:22(<wbr>deferToThreadPool)</font></div><div><font face="monospace"> 274364 14.368 0.000 773.181 0.003 threadpool.py:210(<wbr>callInThreadWithCallback)</font></div><div><font face="monospace"> 299763 5.259 0.000 759.525 0.003 connector.py:117(get)</font></div><div><font face="monospace"> 274364 6.264 0.000 757.978 0.003 _team.py:159(do)</font></div><div><font face="monospace"> 274367 41.737 0.000 751.404 0.003 _threadworker.py:91(do)</font></div><div><font face="monospace">199395/179107 4.397 0.000 737.929 0.004 defer.py:1312(execute)</font></div><div><font face="monospace"> 2102892 27.496 0.000 706.477 0.000 banana.py:162(gotItem)</font></div><div><font face="monospace"> 114728 1.872 0.000 678.239 0.006 banana.py:128(<wbr>callExpressionReceived)</font></div><div><font face="monospace"> 114718 2.676 0.000 676.366 0.006 pb.py:555(expressionReceived)</font></div><div><font face="monospace"> 104696 0.721 0.000 669.270 0.006 pb.py:874(proto_message)</font></div><div><font face="monospace"> 104696 2.231 0.000 668.548 0.006 pb.py:879(_recvMessage)</font></div><div><font face="monospace">2333378/1667165 68.647 0.000 638.402 0.000 defer.py:288(addCallbacks)</font></div><div><font face="monospace"> 228307 3.802 0.000 610.345 0.003 util.py:696(untilConcludes)</font></div><div><font face="monospace"> 103736 1.691 0.000 586.090 0.006 flavors.py:102(<wbr>remoteMessageReceived)</font></div><div><font face="monospace"> 98998 2.784 0.000 544.312 0.005 remotecommand.py:178(remote_<wbr>update)</font></div><div><font face="monospace"> 99279 1.197 0.000 539.977 0.005 metrics.py:92(wrapper)</font></div><div><font face="monospace"> 998915 515.279 0.001 515.279 0.001 {method 'acquire' of 'thread.lock' objects}</font></div><div><font face="monospace"> 274364 16.972 0.000 498.645 0.002 _team.py:166(<lambda>)</font></div><div><font face="monospace"> 274364 55.232 0.000 481.672 0.002 _team.py:169(_<wbr>coordinateThisTask)</font></div><div><font face="monospace">368054/269548 2.834 0.000 480.960 0.002 defer.py:310(addCallback)</font></div><div><font face="monospace">199395/102320 4.001 0.000 460.815 0.005 defer.py:1290(run)</font></div><div><font face="monospace"> 193043 2.646 0.000 454.043 0.002 remotecommand.py:269(<wbr>remoteUpdate)</font></div><div><font face="monospace"> 98828 1.352 0.000 444.287 0.004 misc.py:24(wrapper)</font></div><div><font face="monospace"> 274364 12.877 0.000 425.411 0.002 _threadworker.py:50(do)</font></div><div><font face="monospace"> 274379 56.362 0.000 410.585 0.001 Queue.py:107(put)</font></div><div><font face="monospace"> 118557 8.707 0.000 391.516 0.003 base.py:64(produceEvent)</font></div><div><font face="monospace"> 73113 11.027 0.000 383.481 0.005 abstract.py:234(doWrite)</font></div><div><font face="monospace">175167/143422 6.702 0.000 372.379 0.003 threadable.py:49(sync)</font></div><div><font face="monospace"> 155226 1.157 0.000 360.081 0.002 connector.py:107(getEndpoint)</font></div><div><font face="monospace"> 155226 31.409 0.000 358.924 0.002 pathmatch.py:45(__getitem__)</font></div><div><font face="monospace"> 96155 2.231 0.000 348.588 0.004 log.py:74(<lambda>)</font></div><div><font face="monospace">96524/95460 1.883 0.000 326.433 0.003 lineboundaries.py:32(append)</font></div><div><font face="monospace">199393/199333 1.528 0.000 324.017 0.002 defer.py:1285(_<wbr>releaseAndReturn)</font></div><div><font face="monospace">201639/201210 2.532 0.000 322.497 0.002 defer.py:1368(release)</font></div><div><font face="monospace"> 155226 312.259 0.002 322.348 0.002 pathmatch.py:79(_compile)</font></div><div><font face="monospace"> 96155 2.827 0.000 315.731 0.003 logs.py:198(appendLog)</font></div><div><font face="monospace"> 73113 1.922 0.000 305.072 0.004 tcp.py:228(writeSomeData)</font></div><div><font face="monospace"> 311176 2.758 0.000 304.071 0.001 logs.py:50(get)</font></div><div><font face="monospace"> 73113 302.341 0.004 302.341 0.004 {method 'send' of '_socket.socket' objects}</font></div><div><font face="monospace"> 241229 99.388 0.000 298.465 0.001 simple.py:39(produce)</font></div><div><font face="monospace"> 137584 10.229 0.000 297.448 0.002 log.py:247(msg)</font></div><div><font face="monospace"> 103693 3.131 0.000 292.473 0.003 logs.py:79(getLog)</font></div><div><font face="monospace"> 147250 1.436 0.000 282.022 0.002 remotecommand.py:226(<wbr>addStdout)</font></div><div><font face="monospace"> 137584 4.478 0.000 279.129 0.002 _legacy.py:97(<wbr>publishToNewObserver)</font></div><div><font face="monospace"> 137826 4.193 0.000 274.752 0.002 _observer.py:108(__call__)</font></div><div><font face="monospace"> 275652 2.541 0.000 270.559 0.001 _legacy.py:44(__call__)</font></div><div><font face="monospace"> 275652 3.502 0.000 267.804 0.001 log.py:539(emit)</font></div><div><font face="monospace"> 103718 1.485 0.000 265.556 0.003 logs.py:66(_getLog)</font></div><div><font face="monospace">94968/93904 12.745 0.000 262.480 0.003 log.py:159(wholeLines)</font></div><div><font face="monospace"> 26274 2.272 0.000 262.479 0.010 buildstep.py:451(startStep)</font></div><div><font face="monospace">74361/73660 0.854 0.000 258.791 0.004 log.py:171(addStdout)</font></div><div><font face="monospace"> 112747 243.302 0.002 243.302 0.002 {method 'recv' of '_socket.socket' objects}</font></div><div><font face="monospace"> 274384 49.407 0.000 230.840 0.001 threading.py:373(notify)</font></div><div><font face="monospace"> 69570 220.145 0.003 220.145 0.003 {method 'write' of 'file' objects}</font></div><div><font face="monospace">1659280/1644079 16.320 0.000 206.367 0.000 defer.py:331(addBoth)</font></div><div><font face="monospace"> 10667920 182.099 0.000 184.380 0.000 tuplematch.py:19(matchTuple)</font></div><div><font face="monospace"> 192299 173.403 0.001 173.403 0.001 {method 'sub' of '_sre.SRE_Pattern' objects}</font></div><div><font face="monospace"> 274399 11.041 0.000 169.881 0.001 threading.py:300(_is_owned)</font></div><div><font face="monospace"> 12967 0.551 0.000 156.150 0.012 buildstep.py:605(run)</font></div><div><font face="monospace"> 218466 2.708 0.000 144.798 0.001 posixbase.py:141(doRead)</font></div><div><font face="monospace"> 218741 5.788 0.000 142.305 0.001 fdesc.py:62(readFromFD)</font></div><div><font face="monospace"> 218741 135.535 0.001 135.535 0.001 {posix.read}</font></div><div><font face="monospace"> 23350 0.257 0.000 131.984 0.006 steps.py:119(generateEvent)</font></div><div><font face="monospace"> 2124 0.043 0.000 130.321 0.061 shell.py:253(start)</font></div><div><font face="monospace"> 2124 0.523 0.000 129.577 0.061 buildstep.py:921(startCommand)</font></div><div><font face="monospace"> 37583 1.340 0.000 113.859 0.003 logfile.py:197(write)</font></div><div><font face="monospace"> 37583 0.808 0.000 112.488 0.003 logfile.py:105(write)</font></div><div><font face="monospace"> 146080 106.269 0.001 106.269 0.001 {method 'modify' of 'select.epoll' objects}</font></div><div><font face="monospace"> 4915 0.151 0.000 104.365 0.021 eventual.py:37(_turn)</font></div><div><font face="monospace"> 4719 0.201 0.000 104.214 0.022 remotecommand.py:134(_<wbr>finished)</font></div><div><font face="monospace"> 9437 0.250 0.000 96.007 0.010 buildstep.py:832(runCommand)</font></div><div><font face="monospace"> 4719 0.234 0.000 95.603 0.020 remotecommand.py:80(run)</font></div><div><font face="monospace"> 192309 2.155 0.000 95.360 0.000 log.py:68(addRawLines)</font></div><div><font face="monospace"> 110000 1.078 0.000 89.085 0.001 pb.py:581(sendCall)</font></div><div><font face="monospace"> 110010 2.046 0.000 88.008 0.001 banana.py:302(sendEncoded)</font></div><div><font face="monospace"> 120190 0.877 0.000 84.101 0.001 base.py:59(sanitizeMessage)</font></div><div><font face="monospace">2025413/120551 40.610 0.000 83.825 0.001 copy.py:145(deepcopy)</font></div><div><font face="monospace"> 18330 0.640 0.000 80.581 0.004 buildsets.py:34(db2data)</font></div><div><font face="monospace">124182/120551 11.702 0.000 80.247 0.001 copy.py:253(_deepcopy_dict)</font></div><div><font face="monospace"> 142700 7.776 0.000 80.184 0.001 epollreactor.py:238(_add)</font></div><div><font face="monospace"> 104696 2.288 0.000 79.409 0.001 pb.py:921(_sendAnswer)</font></div><div><font face="monospace"> 10688 0.344 0.000 78.735 0.007 rest.py:326(renderRest)</font></div><div><font face="monospace"> 41284 0.288 0.000 76.702 0.002 buildsets.py:44(getSs)</font></div><div><font face="monospace"> 135155 1.329 0.000 75.917 0.001 abstract.py:436(startWriting)</font></div><div><font face="monospace"> 135155 4.440 0.000 74.587 0.001 epollreactor.py:282(addWriter)</font></div><div><font face="monospace"> 27246 0.552 0.000 74.348 0.003 base.py:515(wakeUp)</font></div><div><font face="monospace"> 27246 3.021 0.000 73.795 0.003 posixbase.py:169(wakeUp)</font></div><div><font face="monospace"> 165 0.033 0.000 73.278 0.444 buildsets.py:86(db2data)</font></div><div><font face="monospace"> 123407 1.556 0.000 71.174 0.001 _newtls.py:182(write)</font></div><div><font face="monospace"> 6478 1.397 0.000 71.077 0.011 basic.py:542(dataReceived)</font></div><div><font face="monospace">254926/246533 5.769 0.000 70.023 0.000 defer.py:846(_cbDeferred)</font></div><div><font face="monospace"> 123584 2.385 0.000 69.097 0.001 abstract.py:339(write)</font></div><div><font face="monospace"> 27246 67.073 0.002 67.073 0.002 {posix.write}</font></div><div><font face="monospace"> 106913 2.842 0.000 66.625 0.001 epollreactor.py:299(_remove)</font></div><div><font face="monospace"> 46168 0.983 0.000 65.580 0.001 http.py:1675(lineReceived)</font></div><div><font face="monospace"> 80486 1.303 0.000 63.860 0.001 abstract.py:423(stopWriting)</font></div><div><font face="monospace"> 5829 0.057 0.000 63.464 0.011 http.py:1780(<wbr>allContentReceived)</font></div><div><font face="monospace"> 5829 0.190 0.000 63.216 0.011 http.py:769(requestReceived)</font></div><div><font face="monospace"> 86356 3.425 0.000 62.633 0.001 epollreactor.py:336(<wbr>removeWriter)</font></div><div><font face="monospace"> 11238 0.331 0.000 60.409 0.005 steps.py:138(<wbr>setStepStateString)</font></div><div><font face="monospace"> 105839 1.873 0.000 57.857 0.001 metrics.py:59(log)</font></div><div><font face="monospace"> 5770 0.303 0.000 56.276 0.010 server.py:161(process)</font></div><div><font face="monospace"> 14168 0.479 0.000 54.273 0.004 remotecommand.py:235(<wbr>addStderr)</font></div><div><font face="monospace"> 175167 2.737 0.000 53.558 0.000 threadable.py:33(_synchPre)</font></div><div><font face="monospace"> 5770 0.047 0.000 51.881 0.009 server.py:227(render)</font></div><div><font face="monospace"> 4242 0.221 0.000 51.620 0.012 remotecommand.py:394(_start)</font></div><div><font face="monospace"> 175180 10.267 0.000 50.821 0.000 threading.py:147(acquire)</font></div><div><font face="monospace"> 5148 0.632 0.000 50.624 0.010 tcp.py:1016(doRead)</font></div><div><font face="monospace"> 7539 0.421 0.000 49.435 0.007 logs.py:116(addLog)</font></div><div><font face="monospace">7412/7084 0.052 0.000 49.199 0.007 log.py:174(addStderr)</font></div><div><font face="monospace"> 2166573 46.210 0.000 46.695 0.000 banana.py:35(b1282int)</font></div><div><font face="monospace"> 7299 0.416 0.000 46.610 0.006 posixbase.py:237(_<wbr>disconnectSelectable)</font></div><div><font face="monospace"> 35125 0.407 0.000 44.185 0.001 steps.py:52(get)</font></div><div><font face="monospace"> 232 0.008 0.000 43.019 0.185 waf_step.py:75(start)</font></div><div><font face="monospace"> 11700 0.408 0.000 42.572 0.004 steps.py:28(getStep)</font></div><div><font face="monospace"> 5401 0.575 0.000 40.441 0.007 resource.py:52(<wbr>asyncRenderHelper)</font></div><div><font face="monospace"> 56875 0.787 0.000 39.562 0.001 properties.py:194(render)</font></div><div><font face="monospace"> 430148 4.588 0.000 38.949 0.000 socket.py:227(meth)</font></div><div><font face="monospace"> 7538 0.289 0.000 38.684 0.005 logs.py:137(finishLog)</font></div><div><font face="monospace"> 5658 0.084 0.000 38.201 0.007 http.py:929(finish)</font></div><div><font face="monospace"> 5344 0.043 0.000 38.059 0.007 rest.py:423(render)</font></div><div><font face="monospace"> 5599 0.031 0.000 37.888 0.007 server.py:216(finish)</font></div><div><font face="monospace"> 59388 5.052 0.000 37.616 0.001 defer.py:789(__init__)</font></div><div><font face="monospace">3896/3744 0.135 0.000 37.356 0.010 lru.py:206(handle_result)</font></div><div><font face="monospace"> 5401 0.149 0.000 36.074 0.007 resource.py:65(finish)</font></div><div><font face="monospace"> 2626 0.036 0.000 35.977 0.014 build.py:472(_stepDone)</font></div><div><font face="monospace"> 10688 0.211 0.000 35.616 0.003 rest.py:433(asyncRender)</font></div><div><font face="monospace">132060/56875 1.371 0.000 34.532 0.001 properties.py:153(render)</font></div><div><font face="monospace"> 4720 0.337 0.000 32.234 0.007 remotecommand.py:302(<wbr>remoteComplete)</font></div><div><font face="monospace"> 214676 1.441 0.000 31.946 0.000 pb.py:819(unserialize)</font></div><div><font face="monospace"> 5898 0.169 0.000 30.568 0.005 tcp.py:277(connectionLost)</font></div><div><font face="monospace"> 214676 1.420 0.000 30.505 0.000 jelly.py:1127(unjelly)</font></div><div><font face="monospace"> 3794 0.325 0.000 29.815 0.008 debounce.py:63(invoke)</font></div><div><font face="monospace"> 5655 0.099 0.000 29.609 0.005 http.py:2116(log)</font></div><div><font face="monospace"> 2626 0.159 0.000 29.405 0.011 buildstep.py:710(releaseLocks)</font></div><div><font face="monospace"> 94046 2.530 0.000 28.971 0.000 remotecommand.py:220(_unwrap)</font></div><div><font face="monospace"> 5901 0.208 0.000 28.758 0.005 tcp.py:113(_closeSocket)</font></div><div><font face="monospace">20354/15469 0.158 0.000 28.597 0.002 properties.py:773(<wbr>getRenderingFor)</font></div><div><font face="monospace"> 5901 28.267 0.005 28.267 0.005 {method 'shutdown' of '_socket.socket' objects}</font></div><div><font face="monospace"> 97233 0.980 0.000 28.000 0.000 buildstep.py:172(_delay)</font></div><div><font face="monospace"> 8556 0.231 0.000 27.730 0.003 socket.py:205(accept)</font></div><div><font face="monospace"> 11238 0.144 0.000 27.620 0.002 buildstep.py:416(<wbr>updateSummary)</font></div><div><font face="monospace">197524/103421 5.643 0.000 27.552 0.000 buildstep.py:156(_catchup)</font></div><div><font face="monospace"> 2626 0.227 0.000 27.243 0.010 build.py:481(stepDone)</font></div><div><font face="monospace"> 214676 1.022 0.000 27.214 0.000 jelly.py:620(unjellyFull)</font></div><div><font face="monospace"> 12452 0.852 0.000 26.962 0.002 properties.py:62(<wbr>setBuildProperties)</font></div><div><font face="monospace"> 8556 26.674 0.003 26.674 0.003 {method 'accept' of '_socket.socket' objects}</font></div><div><font face="monospace">239750/119875 1.432 0.000 26.644 0.000 operators.py:296(__eq__)</font></div><div><font face="monospace"> 94046 1.570 0.000 26.408 0.000 buildstep.py:203(unwrap)</font></div><div><font face="monospace">819050/214676 12.506 0.000 26.192 0.000 jelly.py:627(unjelly)</font></div><div><font face="monospace"> 122012 0.374 0.000 26.079 0.000 elements.py:682(operate)</font></div><div><font face="monospace"> 547659 3.241 0.000 25.979 0.000 defer.py:70(succeed)</font></div><div><font face="monospace"> 119875 0.484 0.000 25.507 0.000 {operator.eq}</font></div><div><font face="monospace"> 222329 1.154 0.000 25.419 0.000 buildrequests.py:106(get)</font></div><div><font face="monospace"> 1988554 24.414 0.000 25.402 0.000 copy.py:267(_keep_alive)</font></div><div><font face="monospace"> 7536 0.317 0.000 25.275 0.003 log.py:89(finish)</font></div><div><font face="monospace"> 7881 0.067 0.000 25.165 0.003 steps.py:152(finishStep)</font></div><div><font face="monospace"> 42090 0.289 0.000 24.794 0.001 defer.py:898(gatherResults)</font></div><div><font face="monospace">12915/12450 0.183 0.000 24.618 0.002 properties.py:810(<wbr>getRenderingFor)</font></div><div><font face="monospace"> 122012 0.662 0.000 24.525 0.000 <string>:1(<lambda>)</font></div><div><font face="monospace"> 3746 0.039 0.000 24.210 0.006 steps.py:118(<wbr>setStepStateString)</font></div><div><font face="monospace"> 122012 1.937 0.000 23.863 0.000 type_api.py:60(operate)</font></div><div><font face="monospace"> 93701 0.454 0.000 23.201 0.000 log.py:44(<lambda>)</font></div><div><font face="monospace"> 137050 0.815 0.000 22.948 0.000 {method 'decode' of 'str' objects}</font></div><div><font face="monospace"> 63974 22.720 0.000 22.720 0.000 {method 'flush' of 'file' objects}</font></div><div><font face="monospace"> 99036 0.681 0.000 22.175 0.000 utf_8.py:15(decode)</font></div><div><font face="monospace">736278/110010 13.325 0.000 22.082 0.000 banana.py:318(_encode)</font></div><div><font face="monospace"> 120561 1.807 0.000 21.838 0.000 default_comparator.py:22(_<wbr>boolean_compare)</font></div><div><font face="monospace"> 99036 21.494 0.000 21.494 0.000 {_codecs.utf_8_decode}</font></div><div><font face="monospace"> 7881 0.047 0.000 20.958 0.003 steps.py:132(startStep)</font></div><div><font face="monospace"> 2350 0.058 0.000 20.841 0.009 git.py:333(_dovccmd)</font></div><div><font face="monospace"> 7881 0.057 0.000 20.604 0.003 steps.py:124(addStep)</font></div><div><font face="monospace"> 519918 6.520 0.000 20.222 0.000 context.py:120(getContext)</font></div><div><font face="monospace"> 2345 0.112 0.000 19.871 0.008 task.py:199(__call__)</font></div><div><font face="monospace"> 4719 0.185 0.000 19.753 0.004 remotecommand.py:123(_start)</font></div><div><font face="monospace"> 4719 0.084 0.000 19.520 0.004 pb.py:248(remoteStartCommand)</font></div></div></div><div class="HOEnZb"><div class="h5"><br><div class="gmail_quote"><div dir="ltr">Le mer. 17 août 2016 à 11:11, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Sending again this email with a link to download the profile as prob it was too big as attachment<div><a href="http://www.filedropper.com/profile_6" target="_blank">http://www.filedropper.com/<wbr>profile_6</a><br></div></div><div dir="ltr"><div><br></div><div><div style="font-size:12.8px">I was able to run twistd with cprofile in production for one day. It was taken with twists 15.5.0 and python 2.7.10.</div><div style="font-size:12.8px">If you could take a look it'd be great ;)</div></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 17, 2016 at 11:03 AM, Francesco Di Mizio <span dir="ltr"><<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hey Pierre,<div><br></div><div>I was able to run twistd with cprofile in production for one day. It was taken with twists 15.5.0 and python 2.7.10.</div><div>If you could take a look it'd be great ;)</div><span><font color="#888888"><div><br></div><div>Francesco</div></font></span></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Aug 12, 2016 at 4:26 PM, Francesco Di Mizio <span dir="ltr"><<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">If I knew how to reproduce the slowness I wouldnt have to rpofile ;)<div><br></div><div>Jokes aside, I tried to nuke the log file and indeed it gets re-created every 10 secs but the content is just always the same even though the master is actually running and I see it hitting the CPU spikes.I get the same things on my test env: 50 smaples and then that's all. I am 100% that the log I attached before did NOT include any spikes. That's just the result of a few seconds of buildbot running. Then you know... somehow it doesnt update.</div><div><br></div><div>If you think it can make a difference I can try the new snippet (is it incomplete? It's missing dump_stats function)</div><div><br></div><div><br></div><div><br></div></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Aug 12, 2016 at 3:48 PM, Pierre Tardy <span dir="ltr"><<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hy Francesco,<div><br></div><div>This is weird, as on my environment I can see the sample count growing. It only grows if the process is not idle, though</div><div>So I have to use the master ui to actually make the profile change on my test environment.</div><div>Your profile looks like fairly idle. I can see pprint and write to logfile which might be not scalable if the data start growing do you have some heavy debug log in your prod?</div><div><br></div><div>Here is an updated more simple snippet, but this should not change many thing.</div><div>You can improve the TimerService '10' value to something bigger in order to dump less often. </div><div>Are you sure you did reproduce the slowness while profiling?</div><div><br></div><div><br></div><div><span><div>import statprof</div><div>from twisted.application.internet import TimerService</div><div>from buildbot.util.service import BuildbotService</div></span><div>from twisted.internet import reactor</div><span><div><br></div><div>class BuildbotTimerService(<wbr>TimerService, BuildbotService):</div><div> name = "timer"</div><div> def __init__(self):</div><div> BuildbotService.__init__(self)</div><div> TimerService.__init__(self, 10, self.dump_stats)</div></span><div> reactor.callFromThread(<wbr>statprof.start)</div><span><div><br></div><div> def dump_stats(self):</div><div> statprof.stop()</div><div> with open("profile.txt", "w") as f:</div><div> statprof.display(f)</div></span><span><div> statprof.display()</div><div> statprof.start()</div><div><br></div><div>c['services'] = [ BuildbotTimerService() ]</div></span></div><div><br></div></div><div><div><br><div class="gmail_quote"><div dir="ltr">Le ven. 12 août 2016 à 14:21, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Sure thing. it's attached. <div>Please note the sampe count has been stuck at 51 for over 1 hour even if the master is running.<br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Aug 12, 2016 at 12:38 PM, Pierre Tardy <span dir="ltr"><<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><p dir="ltr">The first lines are the important ones. Can you send the full file?</p><div><div>
<br><div class="gmail_quote"><div dir="ltr">Le ven. 12 août 2016 12:23, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">It does work but statprof seems to stop getting samples. Last few lines from it:<div><br></div><div><div>2016-08-12 10:19:43+0000 [-] 0.00 0.06 0.00 banana.py:167:gotItem</div><div>2016-08-12 10:19:43+0000 [-] 0.00 0.01 0.00 policies.py:718:setTimeout</div><div>2016-08-12 10:19:43+0000 [-] 0.00 0.01 0.00 encoder.py:434:_iterencode</div><div>2016-08-12 10:19:43+0000 [-] ---</div><div>2016-08-12 10:19:43+0000 [-] Sample count: 51</div><div>2016-08-12 10:19:43+0000 [-] Total time: 0.510000 seconds</div></div><div><br></div><div>The server is running.</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Aug 11, 2016 at 10:46 AM, Francesco Di Mizio <span dir="ltr"><<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Pierre many thanks for that. I do not remember why the force scheduler api didnt suite my needs, that was my first approach.<div>I will try the new snippet when I get to work in a few hours.</div></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 10, 2016 at 11:18 PM, Pierre Tardy <span dir="ltr"><<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi,<div><br></div><div>After carefully looking at your code, it does not look to have obvious performance flaw.</div><div>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.</div><div><br></div><div>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.</div><div><br></div><div>statprof does not like to stop before start</div><div><br></div><div>Please try again with this code:</div><div><br></div><div><span><div><br></div><div>import statprof</div><div>from twisted.application.internet import TimerService</div><div>from buildbot.util.service import BuildbotService</div><div>class BuildbotTimerService(<wbr>TimerService, BuildbotService):</div><div> name = "timer"</div><div> def __init__(self):</div><div> BuildbotService.__init__(self)</div><div> TimerService.__init__(self, 10, self.dump_stats)</div></span><div> self.started = False</div><div> def dump_stats(self):</div><div> if not self.started:</div><div> statprof.start()</div><div> self.started = True</div><div> return</div><span><div> statprof.stop()</div><div> with open("profile.txt", "w") as f:</div><div> statprof.display(f)</div></span><div> statprof.display()</div><span><div> statprof.start()</div><div><br></div><div>c['services'] = [ BuildbotTimerService() ]</div></span></div><div><br></div><div><br></div></div><div><div><br><div class="gmail_quote"><div dir="ltr">Le mer. 10 août 2016 à 14:14, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Many thanks. Find it attached. <div><br></div><div>It's a tiny http server. People use a web page to send an HTTP request to it to kick off builds.</div><div><br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 10, 2016 at 1:55 PM, Pierre Tardy <span dir="ltr"><<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><p dir="ltr">I'll take a look. </p><div><div>
<br><div class="gmail_quote"><div dir="ltr">Le mer. 10 août 2016 12:45, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">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.</div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 10, 2016 at 12:10 PM, Francesco Di Mizio <span dir="ltr"><<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Thanks for that Pierre. I have it on on production and the performances do not degrade indeed.<div><br></div><div>buildbot@e2123a50d1fb:~$ cat profile.txt<br><div>No samples recorded.<br></div></div><div><br></div><div>I need to study statprof a bit now ;)</div></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 10, 2016 at 11:20 AM, Vasily <span dir="ltr"><<a href="mailto:vassnlit@gmail.com" target="_blank">vassnlit@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><p dir="ltr">One can also use Intel® VTune™, you know... :-)</p>
<p dir="ltr">Thanks, <br>
Vasily</p>
<div class="gmail_quote">09 авг. 2016 г. 23:56 пользователь "Pierre Tardy" <<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>> написал:<br type="attribution"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div><div dir="ltr"><div>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</div><div><br></div><div><br></div><div>import statprof</div><div>from twisted.application.internet import TimerService</div><div>from buildbot.util.service import BuildbotService</div><div>class BuildbotTimerService(<wbr>TimerService, BuildbotService):</div><div> name = "timer"</div><div> def __init__(self):</div><div> BuildbotService.__init__(self)</div><div> TimerService.__init__(self, 10, self.dump_stats)</div><div> def dump_stats(self):</div><div> <span style="line-height:1.5"> statprof.stop()</span></div><div> with open("profile.txt", "w") as f:</div><div> statprof.display(f)</div><div> <span style="line-height:1.5"> statprof.start()</span></div><div><br></div><div>c['services'] = [ BuildbotTimerService() ]</div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr">Le mar. 9 août 2016 à 21:44, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Pierre,<div><br></div><div>if you can enlighten on how you intend to use statprof, I will be happy to give it a try.</div><div>This problem here is on top of my list right now as it's making my prod env unusable.</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Aug 9, 2016 at 8:25 PM, Pierre Tardy <span dir="ltr"><<a href="mailto:tardyp@gmail.com" target="_blank">tardyp@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><p dir="ltr">Please note that cprofile is very intrusive and will lead to about 3x slower code.</p>
<p dir="ltr"> 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</p><div><div>
<br><div class="gmail_quote"><div dir="ltr">Le mar. 9 août 2016 19:15, Francesco Di Mizio <<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>> a écrit :<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">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.<div>If anybody is curious the following worked for me:</div><div>twistd --savestats -n --profiler=cprofile --profile=/crcdata/<a href="http://profile.st" target="_blank">profile.st</a><wbr>ats -y ./buildbot.tac</div><div><br></div><div><br><div><br></div></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Aug 9, 2016 at 5:21 PM, Francesco Di Mizio <span dir="ltr"><<a href="mailto:francescodimizio@gmail.com" target="_blank">francescodimizio@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Well that's expected to an extent - p4 poller is running 'p4 changes' every pollinterval seconds.<div><br></div><div>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.</div></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Aug 9, 2016 at 5:08 PM, Dan Kegel <span dir="ltr"><<a href="mailto:dank@kegel.com" target="_blank">dank@kegel.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><p dir="ltr">Also watch 'top' and see if poller processes are hogging resources.</p>
</blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
<br></div></div><span>______________________________<wbr>_________________<br>
users mailing list<br>
<a href="mailto:users@buildbot.net" target="_blank">users@buildbot.net</a><br>
<a href="https://lists.buildbot.net/mailman/listinfo/users" rel="noreferrer" target="_blank">https://lists.buildbot.net/<wbr>mailman/listinfo/users</a><br></span></blockquote></div>
</blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</blockquote></div>
</div></div></blockquote></div><br></div>