#5788 refresh-last-commits.py runs really slow

v1.0.0
closed
Cory Johns
performance (126) sf-1 (616)
General
Tim Van Steenburgh
2015-08-20
2013-02-08
Dave Brondsema
No

See strace capture on sfs-alluradaemon-1 at /tmp/refresh-commits-strace*.txt and the stdout below. It's taking a lot longer than it did on a sandbox. Perhaps it'd help to run it as a task so we can get timermiddleware instrumentation on it.

[root@sfs-alluradaemon-1 ~]# time allurapaste script /var/local/config/production.ini /var/local/allura/scripts/refresh-last-commits.py -- --project allura --mount_point git --diffs --clean --all
Processing diffs
  Processed 1000 commits (max: 1.661983, avg: 0.110554, mavg: 0.110554, tot: 110.553736)
  Processed 2000 commits (max: 1.661983, avg: 0.100717, mavg: 0.090881, tot: 201.434669)
  Processed 3000 commits (max: 1.661983, avg: 0.096351, mavg: 0.087617, tot: 289.051796)
  Processed 4000 commits (max: 1.661983, avg: 0.098891, mavg: 0.106511, tot: 395.563094)
  Processed 5000 commits (max: 1.661983, avg: 0.099963, mavg: 0.104254, tot: 499.816750)
  Processed 6000 commits (max: 1.661983, avg: 0.098845, mavg: 0.093253, tot: 593.069881)
Processing last commits

  Processed 100 commits (max: 560.545987, avg: 40.430805, mavg: 40.430805, tot: 4043.080515)
  Processed 200 commits (max: 916.256613, avg: 52.380540, mavg: 64.330275, tot: 10476.108040)
  Processed 300 commits (max: 1012.123247, avg: 97.011370, mavg: 186.273030, tot: 29103.411073)
  Processed 400 commits (max: 1846.281802, avg: 96.009094, mavg: 93.002264, tot: 38403.637440)
  Processed 500 commits (max: 1846.281802, avg: 87.607987, mavg: 54.003560, tot: 43803.993399)
  Processed 600 commits (max: 1846.281802, avg: 81.074240, mavg: 48.405505, tot: 48644.543909)
  Processed 700 commits (max: 1846.281802, avg: 76.386980, mavg: 48.263419, tot: 53470.885778)
  Processed 800 commits (max: 1846.281802, avg: 69.261329, mavg: 19.381774, tot: 55409.063193)
  Processed 900 commits (max: 1846.281802, avg: 64.583635, mavg: 27.162086, tot: 58125.271821)
  Processed 1000 commits (max: 1846.281802, avg: 60.936957, mavg: 28.116857, tot: 60936.957485)
  Processed 1100 commits (max: 1846.281802, avg: 61.262085, mavg: 64.513361, tot: 67388.293568)
  Processed 1200 commits (max: 1846.281802, avg: 58.882689, mavg: 32.709333, tot: 70659.226848)
  Processed 1300 commits (max: 1846.281802, avg: 58.084282, mavg: 48.503393, tot: 75509.566106)
  Processed 1400 commits (max: 1846.281802, avg: 56.083934, mavg: 30.079418, tot: 78517.507929)
^-- still running

Related

Tickets: #5879

Discussion

  • Dave Brondsema

    Dave Brondsema - 2013-02-08
    • Milestone: forge-feb-22 --> forge-mar-08
     

  • Dave Brondsema

    Dave Brondsema - 2013-02-22
    • size: --> 1
     

  • Dave Brondsema

    Dave Brondsema - 2013-02-22

    Phase 1: convert to ScriptTask; see if the git_lib calls are all instrumented right

     

  • Cory Johns - 2013-02-22
    • status: open --> in-progress
    • assigned_to: Cory Johns
     

  • Cory Johns - 2013-02-26
    • status: in-progress --> code-review
     

  • Cory Johns - 2013-02-26

    allura:cj/5788

    In testing to confirm that the instrumentation was working, I noticed some clear optimization points so I went ahead and addressed those (which brought my test set of the first 100 commits on Allura down from ~40s to ~6s). We'll still want to do [#5879] to see if there are any bottlenecks specific to production and address any further possible optimizations, but I think this is a significant first round.

     

    Related

    Tickets: #5879

  • Tim Van Steenburgh - 2013-02-28
    • qa: Tim Van Steenburgh
     

  • Tim Van Steenburgh - 2013-02-28

    I'm not seeing the same magnitude of a speedup (mine still takes ~29s per 100 commits), but merging anyway as the behavior looks correct, and I suspect the speed difference may be due to sandbox "issues." We can run it in prod and see how the performance is there.

     

  • Tim Van Steenburgh - 2013-02-28
    • status: code-review --> closed
     

Log in to post a comment.