Bug 106488 - very slow document open ....
Summary: very slow document open ....
Status: RESOLVED FIXED
Alias: None
Product: LibreOffice Online
Classification: Unclassified
Component: LibreOffice (show other bugs)
Version:
(earliest affected)
unspecified
Hardware: All All
: medium critical
Assignee: Not Assigned
URL:
Whiteboard: target:5.4.0
Keywords:
Depends on:
Blocks:
 
Reported: 2017-03-11 00:00 UTC by Michael Meeks
Modified: 2017-03-11 21:48 UTC (History)
2 users (show)

See Also:
Crash report or crash signature:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Meeks 2017-03-11 00:00:29 UTC 
I get an -extremely- long document / spinner situation while trying to get my LibreOffice online (master) to startup;  after much hair tearing - this appears to be down to waiting for the child process to load the document and send the first 'status:' message back.

This in turn seems to be triggered by the kit process stalling / hanging here:

Thread 3 (Thread 0x7f5fadb54700 (LWP 9436)):
#0  0x00007f5ff902bbfd in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f5fe4f26cf1 in __libc_res_nsend (ansp2_malloced=0x0, resplen2=0x0, anssizp2=0x0, ansp2=0x0, anscp=0x7f5fadb4df20, gotsomewhere=<synthetic pointer>, v_circuit=<synthetic pointer>, ns=0, terrno=0x7f5fadb4cdf8, anssizp=0x7f5fadb4cf30, ansp=0x7f5fadb4cde8, buflen2=0, buf2=0x0, buflen=28, buf=0x7f5fadb4cf60 "t\302\001", statp=0x7f5fadb54db8) at res_send.c:1180
#2  0x00007f5fe4f26cf1 in __libc_res_nsend (statp=statp@entry=0x7f5fadb54db8, buf=buf@entry=0x7f5fadb4cf60 "t\302\001", buflen=28, buf2=buf2@entry=0x0, buflen2=buflen2@entry=0, ans=ans@entry=0x7f5fadb4daf0 "2\221\201\200", anssiz=anssiz@entry=1024, ansp=ansp@entry=0x7f5fadb4df20, ansp2=ansp2@entry=0x0, nansp2=nansp2@entry=0x0, resplen2=resplen2@entry=0x0, ansp2_malloced=ansp2_malloced@entry=0x0) at res_send.c:545
#3  0x00007f5fe4f24c1c in __GI___libc_res_nquery (statp=statp@entry=0x7f5fadb54db8, name=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", class=class@entry=1, type=type@entry=1, answer=answer@entry=0x7f5fadb4daf0 "2\221\201\200", anslen=anslen@entry=1024, answerp=answerp@entry=0x7f5fadb4df20, answerp2=answerp2@entry=0x0, nanswerp2=nanswerp2@entry=0x0, resplen2=resplen2@entry=0x0, answerp2_malloced=answerp2_malloced@entry=0x0) at res_query.c:227
#4  0x00007f5fe4f25220 in __libc_res_nquerydomain (statp=statp@entry=0x7f5fadb54db8, name=name@entry=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", domain=domain@entry=0x0, class=class@entry=1, type=type@entry=1, answer=0x7f5fadb4daf0 "2\221\201\200", anslen=anslen@entry=1024, answerp=answerp@entry=0x7f5fadb4df20, answerp2=answerp2@entry=0x0, nanswerp2=nanswerp2@entry=0x0, resplen2=resplen2@entry=0x0, answerp2_malloced=answerp2_malloced@entry=0x0) at res_query.c:591
#5  0x00007f5fe4f25ae1 in __GI___libc_res_nsearch (statp=0x7f5fadb54db8, name=name@entry=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", class=class@entry=1, type=type@entry=1, answer=<optimized out>, 
    answer@entry=0x7f5fadb4daf0 "2\221\201\200", anslen=anslen@entry=1024, answerp=0x7f5fadb4df20, answerp2=answerp2@entry=0x0, nanswerp2=nanswerp2@entry=0x0, resplen2=resplen2@entry=0x0, answerp2_malloced=answerp2_malloced@entry=0x0) at res_query.c:492
#6  0x00007f5facc266bd in __GI__nss_dns_gethostbyname3_r (name=name@entry=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", af=af@entry=2, result=result@entry=0x7f5fadb4e4b0, buffer=buffer@entry=0x7f5fadb4e4d0 "\377\002", buflen=buflen@entry=2048, errnop=errnop@entry=0x7f5fadb54670, h_errnop=h_errnop@entry=0x7f5fadb4e4ac, ttlp=ttlp@entry=0x0, canonp=canonp@entry=0x0) at nss_dns/dns-host.c:192
#7  0x00007f5facc269d0 in _nss_dns_gethostbyname_r (name=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", result=0x7f5fadb4e4b0, buffer=0x7f5fadb4e4d0 "\377\002", buflen=2048, errnop=0x7f5fadb54670, h_errnop=0x7f5fadb4e4ac)
    at nss_dns/dns-host.c:273
#8  0x00007f5ff90459b3 in __gethostbyname_r (name=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", resbuf=0x7f5fadb4e4b0, buffer=0x7f5fadb4e4d0 "\377\002", buflen=2048, result=0x7f5fadb4e488, h_errnop=0x7f5fadb4e4ac) at ../nss/getXXbyYY_r.c:266
#9  0x00007f5ff56646d0 in osl_gethostbyname_r(char const*, hostent*, char*, int, int*) (name=name@entry=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc", result=result@entry=0x7f5fadb4e4b0, buffer=buffer@entry=0x7f5fadb4e4d0 "\377\002", buflen=buflen@entry=2048, h_errnop=h_errnop@entry=0x7f5fadb4e4ac) at /data/opt/libreoffice/master/sal/osl/unx/socket.cxx:716
#10 0x00007f5ff5665361 in osl_psz_createHostAddrByName(char const*) (pszHostname=pszHostname@entry=0x7f5ff58a6fe0 <osl_psz_getLocalHostname(char*, unsigned int)::LocalHostname> "linux-fhlc") at /data/opt/libreoffice/master/sal/osl/unx/socket.cxx:925
#11 0x00007f5ff566578c in osl_psz_getLocalHostname(char*, unsigned int) (pBuffer=pBuffer@entry=0x7f5fadb4ed00 "", nBufLen=nBufLen@entry=1024)
    at /data/opt/libreoffice/master/sal/osl/unx/socket.cxx:1054
#12 0x00007f5ff5665817 in osl_getLocalHostname(rtl_uString**) (ustrLocalHostname=0x7f5fadb4f160)
    at /data/opt/libreoffice/master/sal/osl/unx/socket.cxx:1017
---Type <return> to continue, or q <return> to quit---
#13 0x00007f5ff3fadaa9 in osl::SocketAddr::getLocalHostname(oslSocketResult*) (pResult=pResult@entry=0x0)
    at /data/opt/libreoffice/master/include/osl/socket.hxx:183
#14 0x00007f5ff3fad8f3 in svt::LockFileCommon::GenerateOwnEntry() () at /data/opt/libreoffice/master/svl/source/misc/lockfilecommon.cxx:225
#15 0x00007f5ff3f6da71 in svt::DocumentLockFile::CreateOwnLockFile() (this=this@entry=0x7f5fadb4f3e0)
    at /data/opt/libreoffice/master/svl/source/misc/documentlockfile.cxx:104
#16 0x00007f5ff4806a2f in SfxMedium::LockOrigFileOnDemand(bool, bool) (this=0x7f5fa00b17f0, bLoading=bLoading@entry=true, bNoUI=bNoUI@entry=false) at /data/opt/libreoffice/master/sfx2/source/doc/docfile.cxx:1186
#17 0x00007f5ff485c7e6 in SfxObjectShell::DoLoad(SfxMedium*) (this=0x7f5fa00a1120, pMed=pMed@entry=0x7f5fa00b17f0)
    at /data/opt/libreoffice/master/sfx2/source/doc/objstor.cxx:673
#18 0x00007f5ff488700d in SfxBaseModel::load(com::sun::star::uno::Sequence<com::sun::star::beans::PropertyValue> const&) (this=0x7f5ffbe67b38, seqArguments=...) at /data/opt/libreoffice/master/sfx2/source/doc/sfxbasemodel.cxx:1802
#19 0x00007f5ff492a0f8 in (anonymous namespace)::SfxFrameLoader_Impl::load(com::sun::star::uno::Sequence<com::sun::star::beans::PropertyValue> const&, com::sun::star::uno::Reference<com::sun::star::frame::XFrame> const&) (this=<optimized out>, rArgs=..., _rTargetFrame=...)
    at /data/opt/libreoffice/master/sfx2/source/view/frmload.cxx:694
#20 0x00007f5fd0d7e6e5 in framework::LoadEnv::impl_loadContent() (this=this@entry=0x7f5fadb50110)
    at /data/opt/libreoffice/master/framework/source/loadenv/loadenv.cxx:1081
#21 0x00007f5fd0d7eaad in framework::LoadEnv::startLoading() (this=this@entry=0x7f5fadb50110)
    at /data/opt/libreoffice/master/framework/source/loadenv/loadenv.cxx:370
#22 0x00007f5fd0d7f005 in framework::LoadEnv::loadComponentFromURL(com::sun::star::uno::Reference<com::sun::star::frame::XComponentLoader> const&, com::sun::star::uno::Reference<com::sun::star::uno::XComponentContext> const&, rtl::OUString const&, rtl::OUString const&, int, com::sun::star::uno::Sequence<com::sun::star::beans::PropertyValue> const&) (xLoader=..., xContext=..., sURL=..., sTarget=..., nFlags=nFlags@entry=0, lArgs=...)
    at /data/opt/libreoffice/master/framework/source/loadenv/loadenv.cxx:156
#23 0x00007f5fd0da18c2 in framework::Desktop::loadComponentFromURL(rtl::OUString const&, rtl::OUString const&, int, com::sun::star::uno::Sequence<com::sun::star::beans::PropertyValue> const&) (this=0x7f5fd1bc2530, sURL=..., sTargetFrameName=..., nSearchFlags=0, lArguments=...)
    at /data/opt/libreoffice/master/framework/source/services/desktop.cxx:619
#24 0x00007f5ff886560c in lo_documentLoadWithOptions(LibreOfficeKit*, char const*, char const*) (pThis=<optimized out>, pURL=<optimized out>, pOptions=<optimized out>) at /data/opt/libreoffice/master/desktop/source/lib/init.cxx:1193
#25 0x000000000046894d in Document::load(std::shared_ptr<ChildSession> const&, std::string const&, std::string const&, std::string const&, std::string const&, bool) (pFilterOptions=0x0, pUrl=<optimized out>, this=<optimized out>)
    at /data/opt/libreoffice/master/include/LibreOfficeKit/LibreOfficeKit.hxx:487
#26 0x000000000046894d in Document::load(std::shared_ptr<ChildSession> const&, std::string const&, std::string const&, std::string const&, std::string const&, bool) (this=this@entry=0x108bb08, session=..., uri=..., userName=..., docPassword=..., renderOpts=..., haveDocPassword=haveDocPassword@entry=false) at kit/Kit.cpp:1156
#27 0x0000000000469f8f in Document::onLoad(std::string const&, std::string const&, std::string const&, std::string const&, std::string const&, bool) (this=0x108bb08, sessionId=..., uri=..., userName=..., docPassword=..., renderOpts=..., haveDocPassword=false) at kit/Kit.cpp:939
#28 0x00000000004291a6 in ChildSession::loadDocument(char const*, int, std::vector<std::string, std::allocator<std::string> > const&) (this=this@entry=0x1d8cb78, tokens=...) at kit/ChildSession.cpp:329
#29 0x0000000000430696 in ChildSession::_handleInput(char const*, int) (this=<optimized out>, buffer=<optimized out>, length=<optimized out>)
---Type <return> to continue, or q <return> to quit---
    at kit/ChildSession.cpp:166
#30 0x000000000048271b in Session::handleMessage(bool, WebSocketHandler::WSOpCode, std::vector<char, std::allocator<char> >&) (this=0x1d8cb78, data=...) at common/Session.cpp:175
#31 0x0000000000454a64 in Document::forwardToChild(std::string const&, std::vector<char, std::allocator<char> > const&) (this=this@entry=0x108bb08, prefix=..., payload=...) at kit/Kit.cpp:1296
#32 0x0000000000463299 in Document::run() (this=0x108bb08) at kit/Kit.cpp:1405
#33 0x00007f5ffa5da096 in Poco::ThreadImpl::runnableEntry(void*) () at /usr/lib64/libPocoFoundation.so.47
#34 0x00007f5ff92ff0a4 in start_thread (arg=0x7f5fadb54700) at pthread_create.c:309
#35 0x00007f5ff903402d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 2 (Thread 0x7f5fdf701700 (LWP 9415)):
#0  0x00007f5ff930579c in __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007f5ff93014a4 in _L_lock_986 () at /lib64/libpthread.so.0
#2  0x00007f5ff9301306 in __GI___pthread_mutex_lock (mutex=0x12101d0) at ../nptl/pthread_mutex_lock.c:114
#3  0x00007f5ff565b746 in osl_acquireMutex(oslMutexImpl*) (pMutex=0x12101d0) at /data/opt/libreoffice/master/sal/osl/unx/mutex.cxx:99
#4  0x00007f5feff4c638 in osl::Mutex::acquire() (this=this@entry=0x12101a8) at /data/opt/libreoffice/master/include/osl/mutex.hxx:56
#5  0x00007f5ff039002d in SalYieldMutex::acquire() (this=0x12101a0) at /data/opt/libreoffice/master/vcl/unx/generic/app/geninst.cxx:54
#6  0x00007f5ff03901dc in SalGenericInstance::AcquireYieldMutex(unsigned long) (this=<optimized out>, nCount=1)
    at /data/opt/libreoffice/master/vcl/unx/generic/app/geninst.cxx:116
#7  0x00007f5ff038b4a2 in SvpSalInstance::DoReleaseYield(int) (this=this@entry=0x12113b0, nTimeoutMS=16304)
    at /data/opt/libreoffice/master/vcl/headless/svpinst.cxx:395
#8  0x00007f5ff038c12a in SvpSalInstance::DoYield(bool, bool, unsigned long) (this=0x12113b0, bWait=<optimized out>, bHandleAllCurrentEvents=<optimized out>, nReleased=<optimized out>) at /data/opt/libreoffice/master/vcl/headless/svpinst.cxx:374
#9  0x00007f5ff02b79c8 in ImplYield(bool, bool, unsigned long) (i_bWait=i_bWait@entry=true, i_bAllEvents=i_bAllEvents@entry=false, nReleased=nReleased@entry=0) at /data/opt/libreoffice/master/vcl/source/app/svapp.cxx:504
#10 0x00007f5ff02b5dde in Application::Yield() () at /data/opt/libreoffice/master/vcl/source/app/svapp.cxx:557
#11 0x00007f5ff02b5ed7 in Application::Execute() () at /data/opt/libreoffice/master/vcl/source/app/svapp.cxx:466
#12 0x00007f5ff8808895 in desktop::Desktop::DoExecute() () at /data/opt/libreoffice/master/desktop/source/app/app.cxx:1359
#13 0x00007f5ff8810898 in desktop::Desktop::Main() (this=0x7f5fdf700e30) at /data/opt/libreoffice/master/desktop/source/app/app.cxx:1685
#14 0x00007f5ff02bd543 in ImplSVMain() () at /data/opt/libreoffice/master/vcl/source/app/svmain.cxx:185
#15 0x00007f5ff02bd625 in SVMain() () at /data/opt/libreoffice/master/vcl/source/app/svmain.cxx:223
#16 0x00007f5ff88408d5 in soffice_main() () at /data/opt/libreoffice/master/desktop/source/app/sofficemain.cxx:166
#17 0x00007f5ff885d7b9 in lo_startmain(void*) () at /data/opt/libreoffice/master/desktop/source/lib/init.cxx:3002
#18 0x00007f5ff5669326 in osl_thread_start_Impl(void*) (pData=0x10a5100) at /data/opt/libreoffice/master/sal/osl/unx/thread.cxx:240
#19 0x00007f5ff92ff0a4 in start_thread (arg=0x7f5fdf701700) at pthread_create.c:309
#20 0x00007f5ff903402d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 1 (Thread 0x7f5ffbf1e740 (LWP 9414)):
---Type <return> to continue, or q <return> to quit---
#0  0x00007f5ff9034603 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f5ffae13ac5 in Poco::Net::SocketImpl::poll(Poco::Timespan const&, int) () at /usr/lib64/libPocoNet.so.47
#2  0x0000000000470d20 in IoUtil::SocketProcessor(std::shared_ptr<LOOLWebSocket> const&, std::string const&, std::function<bool (std::vector<char, std::allocator<char> > const&)> const&, std::function<void ()> const&, std::function<bool ()> const&) (this=<optimized out>, mode=1, timeout=...) at /usr/include/Poco/Net/Socket.h:376
#3  0x0000000000470d20 in IoUtil::SocketProcessor(std::shared_ptr<LOOLWebSocket> const&, std::string const&, std::function<bool (std::vector<char, std::allocator<char> > const&)> const&, std::function<void ()> const&, std::function<bool ()> const&) (ws=..., name=..., handler=..., closeFrame=..., stopPredicate=...) at common/IoUtil.cpp:73
#4  0x000000000044a54a in lokit_main(std::string const&, std::string const&, std::string const&, std::string const&, bool, bool, bool) (childRoot=..., sysTemplate=..., loTemplate=..., loSubPath=..., noCapabilities=<optimized out>, queryVersion=queryVersion@entry=true, displayVersion=false)
    at kit/Kit.cpp:1840
#5  0x000000000043af93 in createLibreOfficeKit(std::string const&, std::string const&, std::string const&, std::string const&, bool) (childRoot=..., sysTemplate=..., loTemplate=..., loSubPath=..., queryVersion=queryVersion@entry=true) at kit/ForKit.cpp:251
#6  0x000000000041eb76 in main(int, char**) (argc=<optimized out>, argv=0x7ffc6af1ecd8) at kit/ForKit.cpp:457
Comment 1 Michael Meeks 2017-03-11 00:11:48 UTC 
Presumably clobbering this guy:

bool IsLockingUsed()
{
    return officecfg::Office::Common::Misc::UseLocking::get();
}

elegantly would fix the problem =)
Comment 2 Michael Meeks 2017-03-11 00:20:29 UTC 
Yep - ~instant open with that hacked out; never assume too hard that the problem is in the piece you just re-factored ! =)

An elegant fix will involve a loolwsd configuration overlay.
Comment 3 Michael Meeks 2017-03-11 21:48:14 UTC 
Fix the horror in a pleasant way =)
Comment 4 Commit Notification 2017-03-11 21:48:26 UTC 
Michael Meeks committed a patch related to this issue.
It has been pushed to "master":

http://cgit.freedesktop.org/libreoffice/online/commit/?id=bf8f8f17384e0b31345eac20493d4b2acf670bd9

tdf#106488 - fix by disabling un-necessary locking for the kit.