Fwd: OutputModel performance

[Kevin Funk]

On Thursday 07 February 2013, 12:16, Morten Volden wrote:
> ---------- Forwarded message ----------
> From: Morten Volden <mvolden2 at gmail.com>
> Date: 2013/2/6
> Subject: Re: OutputModel performance
> To: Andreas Pakulat <apaku at gmx.de>
> 
> 
> 
> 
> 2013/2/6 Andreas Pakulat <apaku at gmx.de>
> 
> > Hi,
> > 
> > On Wed, Feb 6, 2013 at 4:59 PM, Kevin Funk <krf at gmx.de> wrote:
> > > On Wednesday 06 February 2013, 17:32, Alexander Shaduri wrote:
> > >> Hello,
> > >> 
> > >> On Wed, 06 Feb 2013 13:25:17 +0100
> > >> 
> > >> Kevin Funk wrote:
> > >> > I recently noticed that I get serious UI lockups when running a 'make
> > >> > install' job inside KDevelop for larger projects such as kdelibs.
> > 
> > 'make
> > 
> > >> > install' here may produce roughly ~4500 lines of output in just a few
> > >> > seconds.
> > >> > ...
> > >> > So, the question here:
> > >> > - Did anyone of you guys experience similar issues just to begin
> > >> > with?
> > >> 
> > >> Just from the user's point of view:
> > >> KDevelop is essentially unusable when I'm compiling my project (9
> > 
> > parallel
> > 
> > >> make jobs). It seems that the outputview just cannot handle it quickly
> > >> enough.
> > >> 
> > >> It's a typical cmake/Qt project compiled with make -j9, the full
> > 
> > compilation
> > 
> > >> takes about 30 seconds and produces ~500KB output (~2300 lines).
> > >> CMAKE_VERBOSE_MAKEFILE is on.
> > >> 
> > >> If I set make jobs to 1 or CMAKE_VERBOSE_MAKEFILE to off, it's all
> > >> fine.
> > >> 
> > >> I'd be grateful if you added this as a test case. Compiling, say,
> > 
> > KDevelop
> > 
> > >> with the same settings should give you the same drop in performance.
> > >> 
> > >> Thanks,
> > >> Alexander
> > > 
> > > Just for the record -- I just measured the time it takes to complete
> > > addLineBatch():
> > > 
> > > (...)
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  20 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  10 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  22 ms, processed
> > 
> > lines: 2
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  8 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  8 ms, processed
> > 
> > lines: 2
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  7 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  7 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  12 ms, processed
> > 
> > lines: 3
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  9 ms, processed
> > 
> > lines: 2
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  7 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  8 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  11 ms, processed
> > 
> > lines: 4
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  7 ms, processed
> > 
> > lines: 1
> > 
> > > KDevelop::OutputModel::addLineBatch: elapsed time:  7 ms, processed
> > 
> > lines: 1
> > 
> > > (...)
> > > 
> > > IMO that clearly shows that this takes way too much processing time /
> > 
> > line.
> > 
> > Well, unless you're using a high-precision timer I'm not sure how much
> > you can trust those timings for a single line, it would be more
> > interesting to see an average over 100 calls with the same
> > (non-matching or matching) line or so. IIRC the code for matching is
> > pretty much separate from the rest so it ought to be possible to
> > writeup a test that does this which can then also be better
> > valgrind'ed.
> 
> I can see that I accidentally sent this to Andreas only - sorry about that.
> 
> A test like that already exists in outputmodeltest. It benchmarks the
> different output filtering strategies.
> 
> Here is a sample from a test I just ran:
> QDEBUG : KDevelop::OutputModelTest::benchmarkAddlinesNofilter() average UI
> lockup in ms:  0.263682
> QDEBUG : KDevelop::OutputModelTest::benchmarkAddlinesCompilerfilter()
> average UI lockup in ms:  8.64179
> QDEBUG : KDevelop::OutputModelTest::benchmarkAddlinesScriptErrorfilter()
> average UI lockup in ms:  1.36318
> QDEBUG : KDevelop::OutputModelTest::benchmarkAddlinesStaticAnalysisfilter()
> average UI lockup in ms:  0.228856
> 
> Maybe if we got a sample of the compileoutput that seems to cause trouble,
> rewrote the test a little to feed each line to the matching code and do
> timing on matches. If one or more of the lines sticks out timing wise, it
> should be fairly simple to find the regex that performs badly on the
> line(s).

Here's some sample output to play with: http://pastebin.com/FPEcUWP4
(4400 lines, flushed in ~15 seconds). If this is done inside KDevelop, I get a 
rather sluggish UI with KDevelop keeping 1 core busy at 100%.

I can do some more profiling next week probably (busy writing exams atm). Then 
I can also have a more detailled look at the regexps used.

Greets

-- 
Kevin Funk