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
Phase 1: convert to ScriptTask; see if the git_lib calls are all instrumented right
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:
#5879I'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.