SystemDependentDataBuffer bits ...

[Jan-Marek Glogowski]

So replying to myself.

Am 26.04.19 um 16:46 schrieb Jan-Marek Glogowski:
> Hi everyone,
> 
> the following is just some guess work, as my build will take much longer to verify.
> 
> I had a look at the code and the timer fires every second. That would mean one
> call to Start() for every second, which could trigger the message via timeout,
> which is slightly less then:
> 
>> <mmeeks> vmiklos: ~150k of those while typing ~3 lines of random text in
>> writer =)
> 
> The only thing left is thousands (missed the "k" in 150 at first glance) of
> calls to startUsage and endUsage, always resulting in an empty list, which
> starts and stops the timer all over again.

After the build finished (I just have an N5000 with 4GB RAM - takes some time),
I augmented the code a bit and got this:

info:vcl.schedule:15575:15575:vcl/source/app/scheduler.cxx:588: 1556320265354
0x55bbba60d8a0  restarted  a: 1 p: 1 vcl SystemDependentDataBuffer
aSystemDependentDataBuffer
debug:15575:15575: startUsage 0x55bbbad0a1a0
info:vcl.schedule:15575:15575:vcl/source/app/scheduler.cxx:596: 1556320265354
0x55bbba60d8a0  stopped    a: 1 p: 1 vcl SystemDependentDataBuffer
aSystemDependentDataBuffer
debug:15575:15575: endUsage   0x55bbbad0a1a0
info:vcl.schedule:15575:15575:vcl/source/app/scheduler.cxx:588: 1556320265354
0x55bbba60d8a0  restarted  a: 1 p: 1 vcl SystemDependentDataBuffer
aSystemDependentDataBuffer
debug:15575:15575: startUsage 0x55bbbad05f10
info:vcl.schedule:15575:15575:vcl/source/app/scheduler.cxx:596: 1556320265354
0x55bbba60d8a0  stopped    a: 1 p: 1 vcl SystemDependentDataBuffer
aSystemDependentDataBuffer
debug:15575:15575: endUsage   0x55bbbad05f10
...

few hundred times, which proves my guess. So the Timer actually never runs.
There is no "invoke" line. Nothing is really cached and evicted by the timer!

As I already wrote Stop() is cheap.

And I also already wrote Start() is "expensive" (quotation marks!); I don't
think it really is - not in this or an other case. Worst case would be always
changing the priority, as the lazy cleanup results in high memory usage. The
"restarted" path consists of:

1. Get Scheduler lock. We're the only user, so no fight (look at the logs!).
2. See the task is already scheduled, so no alloc or "fancy other stuff.
3. Get the current timestamp (this is expected to happen often, so cheap).
4. If the scheduled system timer timeout is > the expected Timer timeout,
restart system timer with shorter interval. Happens once. (this is in
Timer::Start(), as it's virtual).

That's it. But since we're already typing, a lot of other stuff will also be
scheduled. For Writer it's "sw::DocumentTimerManager m_aDocIdle", which triggers
background layouting, autotext, grammar and spell checking.

So what is left: as I already guessed, probably a broken cache. startUsage is
always followed by an endUsage, which hold the same pointer (that's rData.get()
in the output). Maybe that is expected most of the time from the design. Yup,
this pollutes the scheduler log output. I updated the patch to "fix" that,
partly by using Michael Meeks initial suggestion.

See the updated https://gerrit.libreoffice.org/#/c/71376/

Jan-Marek