<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>