Unfortunately the test file for this is confidential; perhaps we can work on getting a less confidential one built. Nevertheless it doesn't really have much text included - a good number of slides and lots of those big pictures beloved of users. IIRC it took 30secs or so to load - in excess of what I'd expect. The callgrind trace shows it taking 57% of the time in FcCompareValueList with 236 million calls :-) I attach the profile of that - quite possible we're just screwing up some freeze / un-freeze layout type thing and so doing dynamic layout as the slides are populated or somesuch.
A representative trace was: Breakpoint 1, psp::PrintFontManager::Substitute (this=0xb6d91140, rPattern=..., rMissingCodes="") at /home/opt/libreoffice/core/vcl/generic/fontmanager/fontconfig.cxx:754 754 FontCfgWrapper& rWrapper = FontCfgWrapper::get(); (gdb) bt #0 psp::PrintFontManager::Substitute (this=0xb6d91140, rPattern=..., rMissingCodes="") at /home/opt/libreoffice/core/vcl/generic/fontmanager/fontconfig.cxx:754 #1 0xb6bbdfbf in GetFcSubstitute (rFontSelData=..., rMissingCodes="") at /home/opt/libreoffice/core/vcl/generic/fontmanager/fontsubst.cxx:121 #2 0xb6bbe1dc in FcPreMatchSubstititution::FindFontSubstitute (this=0xb6d8f544, rFontSelData=...) at /home/opt/libreoffice/core/vcl/generic/fontmanager/fontsubst.cxx:158 #3 0xb6a98e72 in ImplDevFontList::ImplFindByFont (this=0x8502400, rFSD=..., bPrinter=false, pDevSpecific=0x0) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:2501 #4 0xb6a9b3cd in ImplFontCache::GetFontEntry (this=0x84fbdb0, pFontList=0x8502400, aFontSelData=..., pDevSpecific=0x0) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:2364 #5 0xb6a9bb71 in ImplFontCache::GetFontEntry (this=0x84fbdb0, pFontList=0x8502400, rFont=..., rSize=..., fExactHeight=37.5999985, pDevSpecific= 0x0) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:2339 #6 0xb6a9bce0 in ImplNewFont (this=0x86f6a60) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:3024 #7 OutputDevice::ImplNewFont (this=0x86f6a60) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:2979 #8 0xb6a9dc9c in OutputDevice::GetTextHeight (this=0x86f6a60) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:5664 #9 0xb03e470c in SvxFont::QuickGetTextSize (this=0xbfffb3b4, pOut=0x86f6a60, rTxt="LARGE ENOUGH TO DELIVER, FOCUSED ENOUGH TO CARE.", nIdx=0, nLen=48, pDXArray=0x93f1d20) at /home/opt/libreoffice/core/editeng/source/items/svxfont.cxx:437 #10 0xb03b6ee1 in ImpEditEngine::CreateLines (this=0x93f1e48, nPara=0, nStartPosY=0) at /home/opt/libreoffice/core/editeng/source/editeng/impedit3.cxx:1042 #11 0xb03b83a7 in ImpEditEngine::FormatDoc (this=0x93f1e48) at /home/opt/libreoffice/core/editeng/source/editeng/impedit3.cxx:406 #12 0xb03bb289 in FormatAndUpdate (pCurView=0x0, this=0x93f1e48) at /home/opt/libreoffice/core/editeng/source/editeng/impedit3.cxx:4035 #13 ImpEditEngine::FormatAndUpdate (this=0x93f1e48, pCurView=0x0) at /home/opt/libreoffice/core/editeng/source/editeng/impedit3.cxx:4026 #14 0xb038a0b2 in EditEngine::SetUpdateMode (this=0x93da980, bUpdate=1 '\001') at /home/opt/libreoffice/core/editeng/source/editeng/editeng.cxx:1188 #15 0xb007be32 in SvxTextEditSourceImpl::unlock (this=0x93da770) at /home/opt/libreoffice/core/svx/source/unodraw/unoshtxt.cxx:908 #16 0xb006edd6 in SvxShapeText::unlock (this=0xacc0c290) at /home/opt/libreoffice/core/svx/source/unodraw/unoshape.cxx:4161 #17 0xb006fd1e in SvxShape::removeActionLock (this=0xacc0c290) at /home/opt/libreoffice/core/svx/source/unodraw/unoshape.cxx:3944 #18 0xad155bc9 in oox::drawingml::Shape::createAndInsert (this=0x93ef298, rFilterBase=..., rServiceName="com.sun.star.drawing.CustomShape", pTheme=0x9199be0, rxShapes=..., bClearText=0 '\000', aParentTransformation=...) at /home/opt/libreoffice/core/oox/source/drawingml/shape.cxx:562 #19 0xad1c2d14 in oox::ppt::PPTShape::addShape (this=0x93ef298, rFilterBase=..., rSlidePersist=..., pTheme=0x9199be0, rxShapes=..., aTransformation=..., pShapeRect=0x0, pShapeMap=0x93b9a90) at /home/opt/libreoffice/core/oox/source/ppt/pptshape.cxx:296 #20 0xad1ca166 in oox::ppt::SlidePersist::createXShapes (this=0x93b99d0, rFilterBase=...) at /home/opt/libreoffice/core/oox/source/ppt/slidepersist.cxx:155 #21 0xad1c655f in oox::ppt::PresentationFragmentHandler::finalizeImport (this=0xa45d2d60) at /home/opt/libreoffice/core/oox/source/ppt/presentationfragmenthandler.cxx:267 #22 0xacf3c028 in oox::core::FragmentHandler2::endDocument (this=0xa45d2d60) at /home/opt/libreoffice/core/oox/source/core/fragmenthandler2.cxx:66 #23 0xa334dd8d in sax_fastparser::FastSaxParser::parseStream (this=0xa45cf5dc, maStructSource=...) at /home/opt/libreoffice/core/sax/source/fastparser/fastparser.cxx:479 #24 0xacf3441d in oox::core::FastParser::parseStream (this=0x8a532d0, rInputSource=..., bCloseStream=false) at /home/opt/libreoffice/core/oox/source/core/fastparser.cxx:121 #25 0xacf344e2 in oox::core::FastParser::parseStream (this=0x8a532d0, rxInStream=..., rStreamName="ppt/presentation.xml", bCloseStream=false) ---Type <return> to continue, or q <return> to quit--- at /home/opt/libreoffice/core/oox/source/core/fastparser.cxx:129 #26 0xacf40899 in oox::core::XmlFilterBase::importFragment (this=0xa45cf53c, rxHandler=RtlReferencePrinter:to_string rtl::Reference to {<cppu::ImplInheritanceHelper1<oox::core::ContextHandler, com::sun::star::xml::sax::XFastDocumentHandler>> = {<oox::core::ContextHandler> = {<cppu::WeakImplHelper1<com::sun::star::xml::sax::XFastContextHandler>> = {<cppu::OWeakObject> = {<com::sun::star::uno::XWeak> = {<com::sun::star::uno::XInterface> = {_vptr.XInterface = 0xad5211d8}, <No data fields>}, m_refCount = 4, m_pWeakConnectionPoint = 0x0, m_pReserved = 0x700074}, <com::sun::star::lang::XTypeProvider> = {<com::sun::star::uno::XInterface> = {_vptr.XInterface = 0xad521268}, <No data fields>}, <com::sun::star::xml::sax::XFastContextHandler> = {<com::sun::star::uno::XInterface> = {_vptr.XInterface = 0xad521284}, <No data fields>}, <No data fields>}, mxBaseData = {px = 0x8a6ea90, pn = {pi_ = 0x8a6cc28}}}, <com::sun::star::xml::sax::XFastDocumentHandler> = {<com::sun::star::xml::sax::XFastContextHandler> = {<com::sun::star::uno::XInterface> = {_vptr.XInterface = 0xad5212b4}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}) at /home/opt/libreoffice/core/oox/source/core/xmlfilterbase.cxx:314 #27 0xad1c037c in oox::ppt::PowerPointImport::importDocument (this=0xa45cf53c) at /home/opt/libreoffice/core/oox/source/ppt/pptimport.cxx:93 #28 0xacf373ec in oox::core::FilterBase::filter (this=0xa45cf53c, rMediaDescSeq=uno::Sequence of length 14 = {...}) at /home/opt/libreoffice/core/oox/source/core/filterbase.cxx:531 #29 0xad1c0400 in oox::ppt::PowerPointImport::filter (this=0xa45cf53c, rDescriptor=uno::Sequence of length 14 = {...}) at /home/opt/libreoffice/core/oox/source/ppt/pptimport.cxx:149 #30 0xb7868f84 in SfxObjectShell::ImportFrom (this=0x896f878, rMedium=..., bInsert=false) at /home/opt/libreoffice/core/sfx2/source/doc/objstor.cxx:2240 #31 0xa1302d57 in sd::DrawDocShell::ImportFrom (this=0x896f878, rMedium=..., bInsert=false) at /home/opt/libreoffice/core/sd/source/ui/docshell/docshel4.cxx:410 #32 0xb7867edf in SfxObjectShell::DoLoad (this=0x896f878, pMed=0x89c6938) at /home/opt/libreoffice/core/sfx2/source/doc/objstor.cxx:733 #33 0xb788e919 in SfxBaseModel::load (this=0xb16fcc8c, seqArguments=uno::Sequence of length 16 = {...}) at /home/opt/libreoffice/core/sfx2/source/doc/sfxbasemodel.cxx:1873 #34 0xb78b661a in SfxFrameLoader_Impl::load (this=0xa16ece4c, rArgs=uno::Sequence of length 13 = {...}, _rTargetFrame=...) at /home/opt/libreoffice/core/sfx2/source/view/frmload.cxx:611 #35 0xb0ce5b37 in framework::LoadEnv::impl_loadContent (this=0xacc01330) at /home/opt/libreoffice/core/framework/source/loadenv/loadenv.cxx:1150 #36 0xb0ce65f9 in framework::LoadEnv::startLoading (this=0xacc01330) at /home/opt/libreoffice/core/framework/source/loadenv/loadenv.cxx:412 #37 0xb0ca3e6e in framework::LoadDispatcher::impl_dispatch (this=0xacc012e4, rURL=..., lArguments=uno::Sequence of length 7 = {...}, xListener= ...) at /home/opt/libreoffice/core/framework/source/dispatch/loaddispatcher.cxx:168 #38 0xb0ca41dd in framework::LoadDispatcher::dispatchWithReturnValue (this=0xacc012e4, rURL=..., lArguments=uno::Sequence of length 7 = {...}) at /home/opt/libreoffice/core/framework/source/dispatch/loaddispatcher.cxx:105 #39 0xb7bb2e8d in comphelper::SynchronousDispatch::dispatch (xStartPoint=..., sURL="file:///tmp/Bracknell_SiteMeeting_051211_V4_Publish.pptx", sTarget="_default", nFlags=0, lArguments=uno::Sequence of length 7 = {...}) at /home/opt/libreoffice/core/comphelper/source/misc/synchronousdispatch.cxx:84 #40 0xb7740b4b in SfxApplication::OpenDocExec_Impl (this=0x8517e98, rReq=...) at /home/opt/libreoffice/core/sfx2/source/appl/appopen.cxx:1230 #41 0xb779c01c in CallExec (rReq=..., pFunc=<optimized out>, this=0x8517e98) at /home/opt/libreoffice/core/sfx2/inc/sfx2/shell.hxx:201 #42 SfxDispatcher::Call_Impl (this=0x86e95e0, rShell=..., rSlot=..., rReq=..., bRecord=0 '\000') at /home/opt/libreoffice/core/sfx2/source/control/dispatch.cxx:276 #43 0xb779c65b in SfxDispatcher::Execute (this=0x86e95e0, nSlot=5501, eCall=1, nModi=0, rArgs=...) at /home/opt/libreoffice/core/sfx2/source/control/dispatch.cxx:1258 #44 0xb779c6fb in SfxDispatcher::Execute (this=0x86e95e0, nSlot=5501, eCall=1, rArgs=...) at /home/opt/libreoffice/core/sfx2/source/control/dispatch.cxx:1230 #45 0xb773f0b4 in SfxApplication::OpenDocExec_Impl (this=0x8517e98, rReq=...) at /home/opt/libreoffice/core/sfx2/source/appl/appopen.cxx:820 ---Type <return> to continue, or q <return> to quit--- #46 0xb779c01c in CallExec (rReq=..., pFunc=<optimized out>, this=0x8517e98) at /home/opt/libreoffice/core/sfx2/inc/sfx2/shell.hxx:201 #47 SfxDispatcher::Call_Impl (this=0x86e95e0, rShell=..., rSlot=..., rReq=..., bRecord=1 '\001') at /home/opt/libreoffice/core/sfx2/source/control/dispatch.cxx:276 #48 0xb779c25a in SfxDispatcher::PostMsgHandler (this=0x86e95e0, pReq=0x88ab688) at /home/opt/libreoffice/core/sfx2/source/control/dispatch.cxx:1359 #49 0xb78a624f in Call (this=<optimized out>, pCaller=<optimized out>) at /home/opt/libreoffice/core/solver/unxlngi6.pro/inc/tools/link.hxx:140 #50 Call (pCaller=<optimized out>, this=<optimized out>) at /home/opt/libreoffice/core/sfx2/inc/sfx2/genlink.hxx:54 #51 Event (pPostedHint=<optimized out>, this=<optimized out>) at /home/opt/libreoffice/core/sfx2/source/notify/hintpost.cxx:86 #52 SfxHintPoster::Event (this=0x86ea2d8, pPostedHint=0x88ab688) at /home/opt/libreoffice/core/sfx2/source/notify/hintpost.cxx:84 #53 0xb78a61a3 in DoEvent_Impl (pPostedHint=0x88ab688, this=0x86ea2d8) at /home/opt/libreoffice/core/sfx2/source/notify/hintpost.cxx:76 #54 SfxHintPoster::LinkStubDoEvent_Impl (pThis=0x86ea2d8, pCaller=0x88ab688) at /home/opt/libreoffice/core/sfx2/source/notify/hintpost.cxx:80 #55 0xb6ba10f8 in Call (pCaller=<optimized out>, this=<optimized out>) at /home/opt/libreoffice/core/solver/unxlngi6.pro/inc/tools/link.hxx:140 #56 ImplHandleUserEvent (pSVEvent=0x88bd108) at /home/opt/libreoffice/core/vcl/source/window/winproc.cxx:1999 #57 ImplWindowFrameProc (pWindow=0x851d980, nEvent=22, pEvent=0x88bd108) at /home/opt/libreoffice/core/vcl/source/window/winproc.cxx:2571 #58 0xb6ba823a in CallCallback (pEvent=0x88bd108, nEvent=22, this=0x851dbf0) at /home/opt/libreoffice/core/vcl/inc/salframe.hxx:294 #59 SalGenericDisplay::DispatchInternalEvent (this=0x84a2b70) at /home/opt/libreoffice/core/vcl/generic/app/gendisp.cxx:102 #60 0xb351b5d5 in GtkData::userEventFn (data=0x84a0af8) at /home/opt/libreoffice/core/vcl/unx/gtk/app/gtkdata.cxx:958 #61 0xb351b634 in call_userEventFn (data=0x84a0af8) at /home/opt/libreoffice/core/vcl/unx/gtk/app/gtkdata.cxx:968 #62 0xb2b1fd10 in ?? () from /usr/lib/libglib-2.0.so.0 #63 0xb2b23e2f in g_main_context_dispatch () from /usr/lib/libglib-2.0.so.0 #64 0xb2b24560 in ?? () from /usr/lib/libglib-2.0.so.0 #65 0xb2b247fa in g_main_context_iteration () from /usr/lib/libglib-2.0.so.0 #66 0xb351b30f in GtkData::Yield (this=0x84a0af8, bWait=true, bHandleAllCurrentEvents=false) at /home/opt/libreoffice/core/vcl/unx/gtk/app/gtkdata.cxx:595 #67 0xb351bfa3 in GtkInstance::Yield (this=0x849f968, bWait=true, bHandleAllCurrentEvents=false) at /home/opt/libreoffice/core/vcl/unx/gtk/app/gtkinst.cxx:605 #68 0xb69d2009 in ImplYield (i_bWait=true, i_bAllEvents=false) at /home/opt/libreoffice/core/vcl/source/app/svapp.cxx:458 #69 0xb69cfc1c in Application::Yield (i_bAllEvents=false) at /home/opt/libreoffice/core/vcl/source/app/svapp.cxx:492 #70 0xb69cfc4d in Application::Execute () at /home/opt/libreoffice/core/vcl/source/app/svapp.cxx:435 #71 0xb7f42b51 in desktop::Desktop::Main (this=0xbfffef64) at /home/opt/libreoffice/core/desktop/source/app/app.cxx:1885 #72 0xb69d5a92 in ImplSVMain () at /home/opt/libreoffice/core/vcl/source/app/svmain.cxx:178 #73 0xb69d5be3 in SVMain () at /home/opt/libreoffice/core/vcl/source/app/svmain.cxx:215 #74 0xb7f57d58 in soffice_main () at /home/opt/libreoffice/core/desktop/source/app/sofficemain.cxx:67 #75 0x0804852c in sal_main () at /home/opt/libreoffice/core/desktop/source/app/main.c:34 #76 main (argc=Cannot access memory at address 0x0 ) at /home/opt/libreoffice/core/desktop/source/app/main.c:33 (gdb) up 5 #5 0xb6a9bb71 in ImplFontCache::GetFontEntry (this=0x84fbdb0, pFontList=0x8502400, rFont=..., rSize=..., fExactHeight=37.5999985, pDevSpecific= 0x0) at /home/opt/libreoffice/core/vcl/source/gdi/outdev3.cxx:2339 2339 return GetFontEntry( pFontList, aFontSelData, pDevSpecific ); (gdb) l 2334 aSearchName = (*it_name).second; 2335 } 2336 2337 // initialize internal font request object 2338 FontSelectPattern aFontSelData( rFont, aSearchName, rSize, fExactHeight ); 2339 return GetFontEntry( pFontList, aFontSelData, pDevSpecific ); 2340 } 2341 2342 // ----------------------------------------------------------------------- 2343 (gdb) p rFont $1 = (const Font &) @0x86f6b20: {mpImplFont = 0x93caa10} (gdb) p rFont->mpImplFont $2 = (Impl_Font *) 0x93caa10 (gdb) p *rFont->mpImplFont $3 = {mnRefCount = 2, maFamilyName = "Arial", maStyleName = "", maSize = {<Pair> = {nA = 0, nB = 564}, <No data fields>}, maColor = rgb(89, 89, 89), maFillColor = rgba(255, 255, 255, 255), meCharSet = 76, meLanguage = 1033, meCJKLanguage = 2052, meFamily = FAMILY_SWISS, mePitch = PITCH_VARIABLE, meAlign = ALIGN_BASELINE, meWeight = WEIGHT_NORMAL, meWidthType = WIDTH_DONTKNOW, meItalic = ITALIC_NONE, meUnderline = UNDERLINE_NONE, meOverline = UNDERLINE_NONE, meStrikeout = STRIKEOUT_NONE, meRelief = RELIEF_NONE, meEmphasisMark = 0, meType = 3086741292, mnOrientation = 0, mnKerning = 1 '\001', mbWordLine = 0 '\000', mbOutline = 0 '\000', mbConfigLookup = 0 '\000', mbShadow = 0 '\000', mbVertical = 0 '\000', mbTransparent = 1 '\001'} ... 5 = (Impl_Font *) 0x9976748 (gdb) p *maFont->mpImplFont $6 = {mnRefCount = 2, maFamilyName = "Arial", maStyleName = "", maSize = {<Pair> = {nA = 0, nB = 321}, <No data fields>}, maColor = rgb(0, 0, 0), maFillColor = rgba(255, 255, 255, 255), meCharSet = 0, meLanguage = 1023, meCJKLanguage = 1023, meFamily = FAMILY_DONTKNOW, mePitch = PITCH_DONTKNOW, meAlign = ALIGN_BOTTOM, meWeight = WEIGHT_DONTKNOW, meWidthType = WIDTH_DONTKNOW, meItalic = ITALIC_NONE, meUnderline = UNDERLINE_NONE, meOverline = UNDERLINE_NONE, meStrikeout = STRIKEOUT_NONE, meRelief = RELIEF_NONE, meEmphasisMark = 0, meType = 3086741292, mnOrientation = 0, mnKerning = 0 '\000', mbWordLine = 0 '\000', mbOutline = 0 '\000', mbConfigLookup = 0 '\000', mbShadow = 0 '\000', mbVertical = 0 '\000', mbTransparent = 1 '\001'}
10Mb of callgrind output at: http://users.freedesktop.org/~michael/3-5-pptx-import.callgrind.gz too ...
Prolly this is just pptx doing something bad, but thought you might be interested Caolan :-)
If this used to perform much better and sucks now, then it might be http://cgit.freedesktop.org/libreoffice/core/commit/?id=3f9a28f1f704967446b411b3b7e176deeb78ca83 which should be easily enough locally reverted for a test even though the files moved around a bit. If it is that, then we need to cache on the full set of properties of the FontSelectPattern not just the name
Created attachment 55690 [details] tweaked version of known-bad patch for testing ... So the bad news is that, yes reverting this patch makes rather a substantial difference. export OOO_EXIT_POST_STARTUP=1 ; export OOO_DISABLE_RECOVERY=1 ; export RTLd; rm -f $RTL_LOGFILE ; ./soffice.bin /tmp/test.pptx ; cat $RTL_LOGFILE ... 189365 1 } PERFORMANCE - DesktopOpenClients_Impl() and adding the revert / lamers cache: ... 044013 1 } PERFORMANCE - DesktopOpenClients_Impl() So - 44 seconds is already not so ideal for this, particularly when compared to the ~5 seconds it takes to load in Powerpoint on the same machine ;-) But 189 seconds is really a lot worse ;-) 4x slower. Having said that - at 44 seconds, we have do be doing something -really- pretty dumb here, 113 slides 300ms per slide to open it ? it seems amazing.
able to check if http://cgit.freedesktop.org/libreoffice/core/commit/?id=8c023fd645c8b83637ffcde4055886b2e4f94393 makes this better ?
yep, nice work, will do - just re-building master to have a go :-) We should try to get this into -3-5-5 IMHO if it does the trick.
Interestingly I re-ran the test vs. master, and I get a 24 second load time before, and a 23 second load time afterwards (and on a slower machine) - that seems to suggest that the performance problem has either gone away spontaneously - or I'm measuring the wrong thing; frustrating at one level - but encouraging at another :-) I'll investigate further as/when I get home.
Re-profiling with master, I get 12% of the time in libfontconfig which is a big win - whether this patch is enough to fix it or not I don't know; will re-try on libreoffice-3-5 I guess :-)
And re-running on libreoffice-3-5 with and without the patch - I get a 13 second import time; so it -seems- that we already fixed this problem in another way; nevertheless the patch itself will speed up a number of corner cases, so well worth having. Thanks Caolan !