Is ScAreaLink::RefreshHdl run too often?

Tue Jun 29 13:24:34 UTC 2021

My slow ASan+UBSan Linux builds sometimes livelock in e.g. 
UITest_calc_tests8:  The soffice.bin main thread's event loop at

[...]
> #33 0x00007f7fe8ea35dc in ScAreaLink::RefreshHdl(Timer*) (this=0x611000891240) at sc/source/ui/docshell/arealink.cxx:492
> #34 0x00007f7fe8e920a9 in ScAreaLink::LinkStubRefreshHdl(void*, Timer*) (instance=0x611000891240, data=0x611000891288) at sc/source/ui/docshell/arealink.cxx:490
> #35 0x00007f8049aacf7e in Link<Timer*, void>::Call(Timer*) const (this=0x6110008912a8, data=0x611000891288) at include/tools/link.hxx:111
> #36 0x00007f8049aac55d in Timer::Invoke() (this=0x611000891288) at vcl/source/app/timer.cxx:75
> #37 0x00007f7fe71b606f in ScRefreshTimer::Invoke() (this=0x611000891288) at sc/source/core/tool/refreshtimer.cxx:126
> #38 0x00007f8049903fcc in Scheduler::CallbackTaskScheduling() () at vcl/source/app/scheduler.cxx:471
> #39 0x00007f804a9ae704 in SalTimer::CallCallback() (this=0x6030002ef180) at vcl/inc/saltimer.hxx:54
> #40 0x00007f804a9a22f1 in SvpSalInstance::CheckTimeout(bool) (this=0x611000001bc0, bExecuteTimers=true) at vcl/headless/svpinst.cxx:210
> #41 0x00007f804a9a8f06 in SvpSalInstance::DoYield(bool, bool) (this=0x611000001bc0, bWait=true, bHandleAllCurrentEvents=false) at vcl/headless/svpinst.cxx:467
> #42 0x00007f80499f6eb2 in ImplYield(bool, bool) (i_bWait=true, i_bAllEvents=false) at vcl/source/app/svapp.cxx:465
> #43 0x00007f80499f5fd8 in Application::Yield() () at vcl/source/app/svapp.cxx:532
> #44 0x00007f80499f5c0a in Application::Execute() () at vcl/source/app/svapp.cxx:444
> #45 0x00007f807e228626 in desktop::Desktop::Main() (this=0x7f8017cb8080) at desktop/source/app/app.cxx:1602
> #46 0x00007f8049a965ca in ImplSVMain() () at vcl/source/app/svmain.cxx:199
> #47 0x00007f8049a9faa1 in SVMain() () at vcl/source/app/svmain.cxx:231
> #48 0x00007f807e40d23b in soffice_main() () at desktop/source/app/sofficemain.cxx:98
> #49 0x000000000030114d in sal_main () at desktop/source/app/main.c:49
> #50 0x0000000000301127 in main (argc=7, argv=0x7ffc396eab68) at desktop/source/app/main.c:47

keeps invoking ScAreaLink::RefreshHdl.  It looks like the work that it 
does takes so long that a fresh timer-triggered invocation is already 
pending whenever the previous one is done.  So Application::Execute 
(frame 44) keeps calling Appliation::Yield (frame 43) keeps calling 
SvpSalInstance::DoYield (frame 41) keeps calling ScAreaLink::RefreshHdl 
(frame 33), without SvpSalInstance::DoYield ever running into a code 
path that would temporarily release the SolarMutex, so thread 1 keeps 
running forever with the SolarMutex locked.

The controlling Python process sent a remote URP request that is pending 
in soffice.bin at

> Thread 24 (LWP 425037 "cppu_threadpool"):
> #0  0x00007f807d6aa7b0 in __lll_lock_wait () at /lib64/libpthread.so.0
> #1  0x00007f807d6a35d0 in pthread_mutex_lock () at /lib64/libpthread.so.0
> #2  0x00007f807f039467 in osl_acquireMutex(oslMutex) (pMutex=0x604000092290) at sal/osl/unx/mutex.cxx:100
> #3  0x00007f804600acba in osl::Mutex::acquire() (this=0x60e0000250a8) at include/osl/mutex.hxx:61
> #4  0x00007f804a9a6b2a in SvpSalYieldMutex::doAcquire(unsigned int) (this=0x60e0000250a0, nLockCount=1) at vcl/headless/svpinst.cxx:383
> #5  0x00007f80466d0db2 in comphelper::SolarMutex::acquire(unsigned int) (this=0x60e0000250a0, nLockCount=1) at include/comphelper/solarmutex.hxx:86
> #6  0x00007f80466d0c34 in osl::Guard<comphelper::SolarMutex>::Guard(comphelper::SolarMutex&) (this=0x7f7e5623d520, t=...) at include/osl/mutex.hxx:142
> #7  0x00007f80466cf29d in SolarMutexGuard::SolarMutexGuard() (this=0x7f7e5623d520) at include/vcl/svapp.hxx:1348
> #8  0x00007f804a4a80e3 in (anonymous namespace)::UITestUnoObj::executeCommand(rtl::OUString const&) (this=0x60b000157b90, rCommand=".uno:Undo") at vcl/source/uitest/uno/uitest_uno.cxx:69
> #9  0x00007f8016a2bd9d in gcc3::callVirtualMethod(void*, unsigned int, void*, _typelib_TypeDescriptionReference*, bool, unsigned long*, unsigned int, unsigned long*, double*) (pThis=0x60b000157be0, nVtableIndex=3, pRegisterReturn=0x60200083c6b0, pReturnTypeRef=0x6070000033c0, bSimpleReturn=true, pStack=0x7f7e5f743280, nStack=0, pGPR=0x7f7e56715060, pFPR=0x7f7e567150c0) at bridges/source/cpp_uno/gcc3_linux_x86-64/callvirtualmethod.cxx:77
> #10 0x00007f8016a2666a in cpp_call(bridges::cpp_uno::shared::UnoInterfaceProxy*, bridges::cpp_uno::shared::VtableSlot, _typelib_TypeDescriptionReference*, int, _typelib_MethodParameter*, void*, void**, _uno_Any**) (pThis=0x606001f60160, aVtableSlot=..., pReturnTypeRef=0x6070000033c0, nParams=1, pParams=0x6030012ba2b0, pUnoReturn=0x60200083c6b0, pUnoArgs=0x60200083c690, ppUnoExc=0x7f7e568b7880) at bridges/source/cpp_uno/gcc3_linux_x86-64/uno2cpp.cxx:233
> #11 0x00007f8016a23509 in unoInterfaceProxyDispatch(uno_Interface*, typelib_TypeDescription const*, void*, void**, uno_Any**) (pUnoI=0x606001f60160, pMemberDescr=0x60f00007f480, pReturn=0x60200083c6b0, pArgs=0x60200083c690, ppException=0x7f7e568b7880) at bridges/source/cpp_uno/gcc3_linux_x86-64/uno2cpp.cxx:413
> #12 0x00007f80119a23dd in binaryurp::IncomingRequest::execute_throw(binaryurp::BinaryAny*, std::__debug::vector<binaryurp::BinaryAny, std::allocator<binaryurp::BinaryAny> >*) const (this=0x60d00034eb10, returnValue=0x7f7e568b6020, outArguments=0x7f7e568b6060) at binaryurp/source/incomingrequest.cxx:235
> #13 0x00007f801199c2ac in binaryurp::IncomingRequest::execute() const (this=0x60d00034eb10) at binaryurp/source/incomingrequest.cxx:78
> #14 0x00007f8011a78a33 in request(void*) (pThreadSpecificData=0x60d00034eb10) at binaryurp/source/reader.cxx:85
> #15 0x00007f807779595a in cppu_threadpool::JobQueue::enter(void const*, bool) (this=0x6120000f67c0, nDisposeId=0x60600052c940, bReturnWhenNoJob=true) at cppu/source/threadpool/jobqueue.cxx:100
> #16 0x00007f80777be0ad in cppu_threadpool::ORequestThread::run() (this=0x60600052c940) at cppu/source/threadpool/thread.cxx:164
> #17 0x00007f80777d0c05 in threadFunc(void*) (param=0x60600052c950) at include/osl/thread.hxx:189
> #18 0x00007f807f0d1170 in osl_thread_start_Impl(void*) (pData=0x60c00021a600) at sal/osl/unx/thread.cxx:264

waiting forever to acquire the SolarMutex.

<https://git.libreoffice.org/core/+/b9ea3467383ccdfe4be842e61267256f281487ee%5E!/> 
"svp: always release SolarMutex on yield" tried to address that (by 
making sure that SvpSalInstance::DoYield eventually releases the 
SolarMutex temporarily, but it was reverted again at least for now with 
<https://git.libreoffice.org/core/+/4abd2598f7816891af3bd462ffaee57f3423b9f9%5E!/> 
"Revert: svp: always release SolarMutex on yield".

However, regardless of how best to solve the livelock, it looks 
questionable whether ScAreaLink::RefreshHdl should trigger so often in 
the first place?