Re: slow opening of docs
On Tue, Jan 09, 2007 at 07:52:10PM +0100, Edwin Leuven wrote: > Abdelrazak Younes wrote: > >Could you profile this instead: > >lyx -e text UserGuide.lyx > > another try: > > % cumulative self self total > time seconds secondscalls ms/call ms/call name > 16.00 0.04 0.0424961 0.00 0.00 > lyx::LyXLex::Pimpl::nextToken() > 12.00 0.07 0.03 184108 0.00 0.00 > lyx::Paragraph::setFont(int, lyx::LyXFont const&) > 8.00 0.09 0.02 180583 0.00 0.00 > lyx::Paragraph::insertChar(int, wchar_t, lyx::LyXFont > const&, lyx::Change const&) > 8.00 0.11 0.0239984 0.00 0.00 > lyx::LyXLex::getString() const > 8.00 0.13 0.02 1148 0.02 0.02 > lyx::LyXTextClass::LyXTextClass(lyx::LyXTextClass con > st&) > [...] The total running time is too small to make any judgement. Put this i a repeat 100 loop. Andre'
Re: slow opening of docs
Abdelrazak Younes wrote: > You are a complicated guy Georg. I was answering to your false > assumption so, in this regard, you misread the patch. I cannot read your > mind and understand what you don't like. I might be complicated, but I still do not think that I misread anything. I only tried to explain why I did not like a particular function. But anyway, it does not matter since this function is not intended to stay, so we don't need to discuss this further :-) > It I continue the cleanup I would also get rid of that method. Yes, I overread that, sorry. Georg
Re: slow opening of docs
On Thu, Jan 11, 2007 at 03:11:31PM +0100, Abdelrazak Younes wrote: > Indeed. On cygwin there's one second improvement (from 7s to 6s) when > loading a really big file (4megs). I repeated the test multiple times to > make sure that the file was already in the cache. > > But I do not trust cygwin much on this because it seems much quicker at > the "normal" console. Nothing stops you from using the cygwin time command in a cmd.exe shell: C:\> c:\cygwin\bin\time c:\your\path\lyx-qt4.exe ... -- Enrico
Re: slow opening of docs
Georg Baum wrote: Abdelrazak Younes wrote: Georg Baum wrote: I think you misread something. In my patch, it's either: I don't think so, see below. You are a complicated guy Georg. I was answering to your false assumption so, in this regard, you misread the patch. I cannot read your mind and understand what you don't like. int i = lex.readInteger(); or lex.next(str); int i = lex.toInteger(str); Either you just want to convert str to an integer. Then you should use int i = convert(str); And that's exactly what toInt(str) does. The reason why it is a LyXLex member is that it does some checking and call LyXLex::printError() if needed: And that's exactly what I don't like. Passing the buffer to a member function of lex does just look wrong. Either you do all the processing in lex as in getInteger(), or if that does not work for some reason then do everything manually (including calling lex.printError() on failure). What lex.getInteger() does is immediately clear without even looking at the docs. For lex.toInteger(str) I have to look up the docs or the implementation to know why I should use this instead of convert(str). You must have misread this line in my previous mail: It I continue the cleanup I would also get rid of that method. Abdel.
Re: slow opening of docs
Abdelrazak Younes wrote: > Georg Baum wrote: > I think you misread something. In my patch, it's either: I don't think so, see below. > int i = lex.readInteger(); > > or > lex.next(str); > int i = lex.toInteger(str); > >> Either you just want to convert str to an integer. >> Then you should use >> >> int i = convert(str); > > And that's exactly what toInt(str) does. The reason why it is a LyXLex > member is that it does some checking and call LyXLex::printError() if > needed: And that's exactly what I don't like. Passing the buffer to a member function of lex does just look wrong. Either you do all the processing in lex as in getInteger(), or if that does not work for some reason then do everything manually (including calling lex.printError() on failure). What lex.getInteger() does is immediately clear without even looking at the docs. For lex.toInteger(str) I have to look up the docs or the implementation to know why I should use this instead of convert(str). Georg
Re: slow opening of docs
Georg Baum wrote: Abdelrazak Younes wrote: Jean-Marc Lasgouttes wrote: "Abdelrazak" == Abdelrazak Younes <[EMAIL PROTECTED]> writes: Abdelrazak> And got rid of this. So if this profile is correct, the Abdelrazak> attached patch will save more than 8% time at file Abdelrazak> reading. Could you try it out please Edwin? This looks like a very big patch for such a result. I said "at least 8%", I hope it will bring much more. I would prefer to avoid it if possible. Me too. I don't really like the interface of LyXlex, but I think we should try to get rid of the whole class during the XML change rather than modifying it. Most of the patch is mechanical (due to the lex API change). That API change looks partly suspicious to me. I did only glance quickly over the patch, but I don't like int i = lex.getInt(str); at all (from memory). I think you misread something. In my patch, it's either: int i = lex.readInteger(); or lex.next(str); int i = lex.toInteger(str); Either you just want to convert str to an integer. Then you should use int i = convert(str); And that's exactly what toInt(str) does. The reason why it is a LyXLex member is that it does some checking and call LyXLex::printError() if needed: int LyXLex::toInteger(string const & buff) const { if (isStrInt(buff)) return convert(buff); pimpl_->printError(buff, "Bad integer `$$Token'"); return -1; } It I continue the cleanup I would also get rid of that method. Or you want to extract an integer from the lexer, then an interface like int i = lex.getInt(); where the integer is converted from an internal buffer of the lexer should be used. There is no internal buffer any more with my patch. Everything is written directly to the output. See above. Nothing to be afraid about. But it's true that it's more a clean up than an optimisation patch. If we are to switch to XML, I agree that it's maybe not worth it (even if I spend multiple hours doing it :-( ...) ??? We are going to XML, just not now. I know and that's why I said it's maybe not worth cleaning up something that is going to scratched anyway. Abdel.
Re: slow opening of docs
> "Abdelrazak" == Abdelrazak Younes <[EMAIL PROTECTED]> writes: Abdelrazak> But I do not trust cygwin much on this because it seems Abdelrazak> much quicker at the "normal" console. Could you try it on Abdelrazak> Linux. Unfortunately, most of my time is already taken by my bitching at others' work :) I'll try to have a look. JMarc
Re: slow opening of docs
Abdelrazak Younes wrote: > Jean-Marc Lasgouttes wrote: >>> "Abdelrazak" == Abdelrazak Younes >>> <[EMAIL PROTECTED]> writes: >> >> Abdelrazak> And got rid of this. So if this profile is correct, the >> Abdelrazak> attached patch will save more than 8% time at file >> Abdelrazak> reading. Could you try it out please Edwin? >> >> This looks like a very big patch for such a result. > > I said "at least 8%", I hope it will bring much more. > >> I would prefer to >> avoid it if possible. Me too. I don't really like the interface of LyXlex, but I think we should try to get rid of the whole class during the XML change rather than modifying it. > Most of the patch is mechanical (due to the lex API change). That API change looks partly suspicious to me. I did only glance quickly over the patch, but I don't like int i = lex.getInt(str); at all (from memory). Either you just want to convert str to an integer. Then you should use int i = convert(str); Or you want to extract an integer from the lexer, then an interface like int i = lex.getInt(); where the integer is converted from an internal buffer of the lexer should be used. > Nothing to > be afraid about. But it's true that it's more a clean up than an > optimisation patch. If we are to switch to XML, I agree that it's maybe > not worth it (even if I spend multiple hours doing it :-( ...) ??? We are going to XML, just not now. Georg
Re: slow opening of docs
Jean-Marc Lasgouttes wrote: "Abdelrazak" == Abdelrazak Younes <[EMAIL PROTECTED]> writes: Abdelrazak> And got rid of this. So if this profile is correct, the Abdelrazak> attached patch will save more than 8% time at file Abdelrazak> reading. Could you try it out please Edwin? This looks like a very big patch for such a result. I said "at least 8%", I hope it will bring much more. I would prefer to avoid it if possible. Most of the patch is mechanical (due to the lex API change). Nothing to be afraid about. But it's true that it's more a clean up than an optimisation patch. If we are to switch to XML, I agree that it's maybe not worth it (even if I spend multiple hours doing it :-( ...) In particular, one should not get too excited over gprof output, especially when file io and maybe memory allocation may get a big part of the time. These are not visible in the trace. I would propose to use "time" to get real-world timings. Indeed. On cygwin there's one second improvement (from 7s to 6s) when loading a really big file (4megs). I repeated the test multiple times to make sure that the file was already in the cache. But I do not trust cygwin much on this because it seems much quicker at the "normal" console. Could you try it on Linux. The big file in question is just the UserGuide copied and pasted multiple times. Abdel.
Re: slow opening of docs
> "Abdelrazak" == Abdelrazak Younes <[EMAIL PROTECTED]> writes: Abdelrazak> And got rid of this. So if this profile is correct, the Abdelrazak> attached patch will save more than 8% time at file Abdelrazak> reading. Could you try it out please Edwin? This looks like a very big patch for such a result. I would prefer to avoid it if possible. In particular, one should not get too excited over gprof output, especially when file io and maybe memory allocation may get a big part of the time. These are not visible in the trace. I would propose to use "time" to get real-world timings. JMarc
Re: slow opening of docs
> "Edwin" == Edwin Leuven <[EMAIL PROTECTED]> writes: Edwin> Jean-Marc Lasgouttes wrote: >>> "Edwin" == Edwin Leuven <[EMAIL PROTECTED]> writes: >> Edwin> Abdelrazak Younes wrote: Could you profile this instead: lyx -e text UserGuide.lyx >> Edwin> another try: >> Since you are using oprofile, you could try to obtain a call graph >> instead of a flat profile. This is possible if your linux is new >> enough. Edwin> i used gprof, but i will have a look... If you use gprof, you should be aware that you do not have a real view of time spent (file IO, for example). The top offenders may not be the one gprof points to. JMarc
Re: slow opening of docs
Jean-Marc Lasgouttes wrote: "Edwin" == Edwin Leuven <[EMAIL PROTECTED]> writes: Edwin> Abdelrazak Younes wrote: Could you profile this instead: lyx -e text UserGuide.lyx Edwin> another try: Since you are using oprofile, you could try to obtain a call graph instead of a flat profile. This is possible if your linux is new enough. i used gprof, but i will have a look...
Re: slow opening of docs
> "Edwin" == Edwin Leuven <[EMAIL PROTECTED]> writes: Edwin> Abdelrazak Younes wrote: >> Could you profile this instead: lyx -e text UserGuide.lyx Edwin> another try: Since you are using oprofile, you could try to obtain a call graph instead of a flat profile. This is possible if your linux is new enough. JMarc
Re: slow opening of docs
although loading and saving feels snappier, i find that selecting text (especially in a large doc like the userguide) is slow on linux, the selection lags a bit behind the mouse when i move the mouse quickly. if i just change the selection (with the mouse) in a single paragraph for a while (setting the selection and moving the mouse) i get the following profile: time seconds secondscalls ms/call ms/call name 21.74 0.30 0.30 2202370 0.00 0.00 QHashint>::findNode(wchar_t const&, unsigne d int*) const 5.07 0.37 0.07 1101181 0.00 0.00 lyx::frontend::GuiFontMetrics::width(wchar_t) const 5.07 0.44 0.07 160930 0.00 0.00 lyx::LyXText::getFont(lyx::Buffer const&, lyx::Paragr aph const&, int) const 3.62 0.49 0.05 1942532 0.00 0.00 lyx::LyX::application() 3.62 0.54 0.05 336956 0.00 0.00 lyx::LyXFont::LyXFont() 2.90 0.58 0.04 286721 0.00 0.00 lyx::LyXTextClass::load(std::string const&) const 2.17 0.61 0.03 1942532 0.00 0.00 lyx::theApp() 2.17 0.64 0.03 864733 0.00 0.00 lyx::LyXText::singleWidth(lyx::Paragraph const&, int, wchar_t, lyx::LyXFont const&) const 2.17 0.67 0.03 272689 0.00 0.00 lyx::Paragraph::getDepth() const 1.45 0.69 0.02 970628 0.00 0.00 lyx::theFontMetrics(lyx::LyXFont const&) 1.45 0.71 0.02 970628 0.00 0.00 lyx::frontend::GuiFontLoader::metrics(lyx::LyXFont co nst&) 1.45 0.73 0.02 496805 0.00 0.00 lyx::FontIterator::operator++() 1.45 0.75 0.02 286639 0.00 0.00 lyx::Paragraph::lookupChange(int) const
Re: slow opening of docs
Abdelrazak Younes wrote: Could you profile this instead: lyx -e text UserGuide.lyx another try: % cumulative self self total time seconds secondscalls ms/call ms/call name 16.00 0.04 0.0424961 0.00 0.00 lyx::LyXLex::Pimpl::nextToken() 12.00 0.07 0.03 184108 0.00 0.00 lyx::Paragraph::setFont(int, lyx::LyXFont const&) 8.00 0.09 0.02 180583 0.00 0.00 lyx::Paragraph::insertChar(int, wchar_t, lyx::LyXFont const&, lyx::Change const&) 8.00 0.11 0.0239984 0.00 0.00 lyx::LyXLex::getString() const 8.00 0.13 0.02 1148 0.02 0.02 lyx::LyXTextClass::LyXTextClass(lyx::LyXTextClass con st&) 4.00 0.14 0.01 183891 0.00 0.00 lyx::Changes::set(lyx::Change const&, int, int) 4.00 0.15 0.0114266 0.00 0.00 lyx::LyXLex::Pimpl::next(bool) 4.00 0.16 0.0112631 0.00 0.00 lyx::InsetBase::clone() const 4.00 0.17 0.01 9763 0.00 0.00 lyx::LyXFont::LyXFont() 4.00 0.18 0.01 9491 0.00 0.00 lyx::Paragraph::Pimpl::~Pimpl() 4.00 0.19 0.01 6765 0.00 0.00 std::vectorlocator >::operator=(std::vector llocator > const&) 4.00 0.20 0.01 4159 0.00 0.00 __gnu_cxx::__normal_iteratoryXLayout> const*, std::vector, std::allocatorayout> > > > std::__find_if<__gnu_cxx::__normal_iterator const*, std::vec tor, std::allocator > > >, lyx::(anonym ous namespace)::LayoutNamesEqual>(__gnu_cxx::__normal_iterator const*, st d::vector, std::allocator > > >, __gnu_ cxx::__normal_iterator const*, std::vectorut>, std::allocator > > >, lyx::(anonymous namespace)::LayoutNamesEqual, std::random_access_iterator_tag)
Re: slow opening of docs
Abdelrazak Younes wrote: Edwin Leuven wrote: Abdelrazak Younes wrote: Could you profile this instead: lyx -e text UserGuide.lyx then you get this: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 100.00 0.01 0.01110.0010.00 lyx::frontend::GuiWorkArea::doGreyOut(lyx::frontend:: QLPainter&) There is something wrong here, the GUI should not even be loaded with the '-e' option. Are you sure you passed the correct patch to the document? this was yesterday evenings svn. i agree it looks suspicious. will have another look tonight...
Re: slow opening of docs
Edwin Leuven wrote: Abdelrazak Younes wrote: Could you profile this instead: lyx -e text UserGuide.lyx then you get this: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 100.00 0.01 0.01110.0010.00 lyx::frontend::GuiWorkArea::doGreyOut(lyx::frontend:: QLPainter&) There is something wrong here, the GUI should not even be loaded with the '-e' option. Are you sure you passed the correct patch to the document? Abdel.
Re: slow opening of docs
Abdelrazak Younes wrote: Could you profile this instead: lyx -e text UserGuide.lyx then you get this: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 100.00 0.01 0.01110.0010.00 lyx::frontend::GuiWorkArea::doGreyOut(lyx::frontend:: QLPainter&) 0.00 0.01 0.00 232824 0.00 0.00 lyx::QLyXKeySym::operator==(lyx::LyXKeySym const&) co nst 0.00 0.01 0.0054206 0.00 0.00 char lyx::support::(anonymous namespace)::ascii_tolow er(char) 0.00 0.01 0.0039471 0.00 0.00 boost::filesystem::basic_path esystem::path_traits>::m_append(char) 0.00 0.01 0.0016650 0.00 0.00 lyx::support::lowercase(wchar_t) 0.00 0.01 0.0014757 0.00 0.00 lyx::support::token(std::basic_string har_traits, std::allocator > const&, wchar_t, int) 0.00 0.01 0.0012878 0.00 0.00 lyx::MenuItem::shortcut() const 0.00 0.01 0.0010314 0.00 0.00 lyx::support::compare_no_case(std::basic_string_t, std::char_traits, std::allocator > const&, std::basic_string s, std::allocator > const&) 0.00 0.01 0.00 8461 0.00 0.00 lyx::MenuItem::~MenuItem() 0.00 0.01 0.00 6961 0.00 0.00 lyx::support::compare_ascii_no_case(std::string const &, std::string const&) 0.00 0.01 0.00 6283 0.00 0.00 lyx::FuncStatus::enabled() const 0.00 0.01 0.00 5351 0.00 0.00 lyx::LyXLex::Pimpl::next(bool) 0.00 0.01 0.00 5305 0.00 0.00 lyx::LyX::ref() 0.00 0.01 0.00 5279 0.00 0.00 lyx::(anonymous namespace)::compare_tags::operator()( lyx::keyword_item const&, lyx::keyword_item const&) const 0.00 0.01 0.00 5029 0.00 0.00 lyx::LyXLex::Pimpl::getString() const 0.00 0.01 0.00 4585 0.00 0.00 lyx::frontend::WorkArea::bufferView() 0.00 0.01 0.00 4271 0.00 0.00 lyx::FuncStatus::unknown() const 0.00 0.01 0.00 3915 0.00 0.00 lyx::utf8_to_ucs4(std::string const&, std::basic_stri ng, std::allocator >&) 0.00 0.01 0.00 3915 0.00 0.00 lyx::from_utf8(std::string const&) 0.00 0.01 0.00 3661 0.00 0.00 lyx::LyXLex::next(bool) 0.00 0.01 0.00 3532 0.00 0.00 lyx::IconvProcessor::convert(char const*, unsigned in t, char*, unsigned int) 0.00 0.01 0.00 3265 0.00 0.00 lyx::LyXLex::getString() const 0.00 0.01 0.00 3104 0.00 0.00 lyx::utf8ToUcs4() 0.00 0.01 0.00 3104 0.00 0.00 lyx::LyX::iconvProcessor() 0.00 0.01 0.00 2788 0.00 0.00 lyx::FuncStatus::FuncStatus() 0.00 0.01 0.00 2628 0.00 0.00 lyx::Menu::addWithStatusCheck(lyx::MenuItem const&) 0.00 0.01 0.00 2421 0.00 0.00 lyx::QLyXKeySym::isOK() const 0.00 0.01 0.00 2364 0.00 0.00 lyx::kb_keymap::kb_key::~kb_key() 0.00 0.01 0.00 2363 0.00 0.00 std::_Rb_tree
Re: slow opening of docs
Edwin, is there any need to further optimize things? I still see some change tracking-related stuff on top of the reports but I wonder whether it really matters... Michael
Re: slow opening of docs
Abdelrazak Younes <[EMAIL PROTECTED]> writes: > > Each sample counts as 0.01 seconds. > > % cumulative self self total > > time seconds secondscalls ms/call ms/call name > > 7.41 0.02 0.02 268500 0.00 0.00 > > lyx::InsetBase::inMathed() const > I don't understand why this is so slow. Could you aded an 'inline' > keyword in insetbase.h:75 please: > inline virtual bool inMathed() const { return false; } > and report back. Not a chance! The compiler can't inline this function because it doesn't know what to inline. Some other class, unknown to the compiler when it's compiling insetbase.C, or, indeed, when it's compiling any file that #includes insetbase.h and which invokes inMathed through an insetbase pointer, may override the inMathed definition here. Only the linker has all the info to hand to decide whether the function can truly be inlined and even then, not always (the insetbase* may be initialized differently depending on different run time parameters for example). Angus
Re: slow opening of docs
Edwin Leuven wrote: copy/paste (using the clipboard) from konsole ;-) Thanks Edwin but I suspect that those number are not very meaningful because of the Gui loading etc. Could you profile this instead: lyx -e text UserGuide.lyx or Any other big file that you have. Abdel.
Re: slow opening of docs
copy/paste (using the clipboard) from konsole ;-) file open: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 9.09 0.02 0.02 184108 0.00 0.00 lyx::Paragraph::setFont(int, lyx::LyXFont const&) 9.09 0.04 0.0224378 0.00 0.00 lyx::support::compare_ascii_no_case(std::string const &, std::string const&) 4.55 0.05 0.01 232824 0.00 0.00 lyx::QLyXKeySym::operator==(lyx::LyXKeySym const&) co nst 4.55 0.06 0.01 181982 0.00 0.00 lyx::Paragraph::Pimpl::insertChar(int, wchar_t, lyx:: Change const&) 4.55 0.07 0.0154401 0.00 0.00 boost::filesystem::basic_path esystem::path_traits>::m_append(char) 4.55 0.08 0.0144055 0.00 0.00 lyx::LyXLex::getString() const 4.55 0.09 0.0126870 0.00 0.00 lyx::LyXLex::Pimpl::nextToken() 4.55 0.10 0.0126735 0.00 0.00 lyx::operator==(std::basic_string traits, std::allocator > const&, char const*) 4.55 0.11 0.0118532 0.00 0.00 lyx::DocIterator::lastpos() const 4.55 0.12 0.0118223 0.00 0.00 lyx::LyXLex::Pimpl::next(bool) 4.55 0.13 0.0115009 0.00 0.00 lyx::support::token(std::basic_string har_traits, std::allocator > const&, wchar_t, int) 4.55 0.14 0.0112068 0.00 0.00 lyx::InsetTabular::getText(int) const 4.55 0.15 0.0110405 0.00 0.00 std::vector >::_M_in sert_aux(__gnu_cxx::__normal_iteratorstd::allocator > >, wchar_t c onst&) 4.55 0.16 0.01 4412 0.00 0.00 __gnu_cxx::__normal_iteratoryXLayout> const*, std::vector, std::allocatorayout> > > > std::__find_if<__gnu_cxx::__normal_iterator const*, std::vec tor, std::allocator > > >, lyx::(anonym ous namespace)::LayoutNamesEqual>(__gnu_cxx::__normal_iterator const*, st d::vector, std::allocator > > >, __gnu_ cxx::__normal_iterator const*, std::vectorut>, std::allocator > > >, lyx::(anonymous namespace)::LayoutNamesEqual, std::random_access_iterator_tag) 4.55 0.17 0.01 2000 0.01 0.01 lyx::lookupFont(std::basic_string traits, std::allocator > const&) 4.55 0.18 0.01 1766 0.01 0.01 std::string const lyx::support::(anonymous namespace) ::doSplit(std::string const&, std::string&, char) 4.55 0.19 0.01 1148 0.01 0.01 lyx::LyXTextClass::LyXTextClass(lyx::LyXTextClass con st&) 4.55 0.20 0.01 331 0.03 0.03 lyx::support::addPath(std::string const&, std::string const&) 4.55 0.21 0.01 76 0.13 0.13 lyx::frontend::GuiFontMetrics::width(QString const&) const 4.55 0.22 0.01 42 0.24 0.25 lyx::support::getFormatFromContents(lyx::support::Fil eName const&) file save: ach sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 22.22 0.58 0.58 3276202 0.00 0.00 lyx::Paragraph::getFontSettings(lyx::BufferParams con st&, int) const 15.71 0.99 0.4134362 0.01 0.06 lyx::Paragraph::write(lyx::Buffer const&, std::ostrea m&, lyx::BufferParams const&, unsigned int&) const 9.58 1.24 0.25 3212568 0.00 0.00 std::vectorstd::allocator >::_M_insert_a ux(__gnu_cxx::__normal_iteratorstd::allocator > >, char const&) 7.28 1.43 0.19 3459077 0.00 0.00 lyx::operator==(lyx::LyXFont::FontBits const&, lyx::L yXFont::FontBits const&) 6.13 1.59 0.16 3310038 0.00 0.00 lyx::operator==(lyx::Change const&, lyx::Change const &) 5.75 1.74 0.15 3226130 0.00 0.00 std::vectorstd::allocator > lyx::(anonym ous namespace)::iconv_convert(lyx::IconvProcessor&, wchar_t const*, unsigned int) 4.21 1.85 0.11 3311128 0.00 0.00 lyx::Paragraph::Pimpl::lookupChange(int) const 3.83 1.95 0.10 3310038 0.00 0.00 lyx::Changes::lyxMarkChange(std::ostream&, int&, lyx: :Change const&, lyx::Change const&) 3.83 2.05 0.10 3239882 0.00 0.00 lyx::IconvProcessor::convert(char const*, unsigned in t, char*, unsigned int) 2.30 2.11 0.06 3311128 0.00 0.00 lyx::Changes::lookup(int) const 2.30 2.17 0.06 3212568 0.00 0.00 lyx::ucs4_to_utf8(wchar_t) 1.53 2.21 0.0426870 0.00 0.00 lyx::LyXLex::Pimpl::nextToken() 1.53 2.25 0.04 37 1.08 1.12 lyx::Buffer::buildMacros()
Re: slow opening of docs
Edwin Leuven wrote: Michael Gerz wrote: Edwin, could you please check whether the attached patch saves any time in lyx::Changes::lookup(int) const and lyx::Changes::merge() during opening/saving a file? this is open (save below): Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 7.41 0.02 0.02 268500 0.00 0.00 lyx::InsetBase::inMathed() const I don't understand why this is so slow. Could you aded an 'inline' keyword in insetbase.h:75 please: inline virtual bool inMathed() const { return false; } and report back. 7.41 0.04 0.0210948 0.00 0.00 lyx::support::compare_no_case(std::basic_stringstd::char_traits, std::allocator > const&, std::basic_string, std::allocator > const&) 3.70 0.05 0.01 236382 0.00 0.00 lyx::operator==(lyx::LyXKeySym const&, lyx::LyXKeySym const&) I've just pushed a fix for this one (hopefully). 3.70 0.06 0.01 191783 0.00 0.00 lyx::DocIterator::inTexted() const I've inline that. 3.70 0.07 0.01 182929 0.00 0.00 lyx::operator==(lyx::LyXFont::FontBits const&, lyx::LyXFont::FontBits const&) 3.70 0.08 0.01 181982 0.00 0.00 lyx::Paragraph::Pimpl::insertChar(int, wchar_t, lyx::Change const&) 3.70 0.09 0.01 180583 0.00 0.00 lyx::Paragraph::insertChar(int, wchar_t, lyx::LyXFont const&, lyx::Change const&) 3.70 0.10 0.01 151794 0.00 0.00 lyx::InsetText::getText(int) const 3.70 0.11 0.01 116494 0.00 0.00 lyx::DocIterator::inMathed() const And that. We can do some more inlining but please do another profile in order to make sure that there is a true saving. Thanks in advance. Abdel.
RE: slow opening of docs
> Ouch, 35%! I am sure this could be optimized! wrong profile. correct one here: http://article.gmane.org/gmane.editors.lyx.devel/75394
Re: slow opening of docs
> "Abdelrazak" == Abdelrazak Younes <[EMAIL PROTECTED]> writes: >> % cumulative self self total time seconds seconds calls ms/call >> ms/call name 35.43 0.79 0.79 2002198 0.00 0.00 >> lyx::Paragraph::getFontSettings(lyx::BufferParams const&, int) >> const Abdelrazak> Ouch, 35%! I am sure this could be optimized! Probably by using a FontIterator. JMarc
Re: slow opening of docs
Abdelrazak Younes wrote: is this linux with oprofile? yeah, mon péché mignon... ;-)
Re: slow opening of docs
Edwin Leuven wrote: Edwin Leuven wrote: Michael Gerz wrote: With optimizations or in debugging mode? aargh! it is compiling with --enable-optimization=-O2 now. will report What's that? A CMake settings? Or is this linux with oprofile? opening and saving the userguide takes about 1 sec opening profile: % cumulative self self total time seconds secondscalls ms/call ms/call name 10.34 0.03 0.0324962 0.00 0.00 lyx::LyXLex::Pimpl::nextToken() 6.90 0.05 0.02 183891 0.00 0.00 lyx::Changes::merge() saving profile: % cumulative self self total time seconds secondscalls ms/call ms/call name 35.43 0.79 0.79 2002198 0.00 0.00 lyx::Paragraph::getFontSettings(lyx::BufferParams const&, int) const Ouch, 35%! I am sure this could be optimized! 21.52 1.27 0.48 1963236 0.00 0.00 std::vectorstd::allocator >::_M_insert_aux(__gnu_cxx::__normal_iteratorstd::allocator > >, char const&) This too by preallocating the memory by calling reserve(), one needs to review all std::vector uses. 18.39 1.68 0.41 2023687 0.00 0.00 lyx::Changes::lookup(int) const (full profiles here: http://leuven.ecodip.net/lyx/profile.zip)
Re: slow opening of docs
Am Sonntag, 7. Januar 2007 19:42 schrieb Edwin Leuven: > Michael Gerz wrote: > > In other words: The speed-up is signficant, right? > > yeah, i'd suggest you put it in... If you do, please add a comment to the inlined functions that they are inlined because of profiler measurements. Georg
Re: slow opening of docs
Michael Gerz wrote: Edwin Leuven schrieb: Michael Gerz wrote: Edwin, could you please check whether the attached patch saves any time in lyx::Changes::lookup(int) const and lyx::Changes::merge() during opening/saving a file? this is open (save below): > In other words: The speed-up is signficant, right? yeah, i'd suggest you put it in...
Re: slow opening of docs
Edwin Leuven schrieb: Michael Gerz wrote: Edwin, could you please check whether the attached patch saves any time in lyx::Changes::lookup(int) const and lyx::Changes::merge() during opening/saving a file? this is open (save below): Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 7.41 0.02 0.02 268500 0.00 0.00 lyx::InsetBase::inMathed() const 7.41 0.04 0.0210948 0.00 0.00 lyx::support::compare_no_case(std::basic_stringstd::char_traits, std::allocator > const&, std::basic_string, std::allocator > const&) 3.70 0.05 0.01 236382 0.00 0.00 lyx::operator==(lyx::LyXKeySym const&, lyx::LyXKeySym const&) and this save: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 17.07 0.21 0.2115272 0.01 0.06 lyx::Paragraph::write(lyx::Buffer const&, std::ostream&, lyx::BufferParams const&, unsigned int&) const 9.76 0.33 0.12 1456198 0.00 0.00 lyx::Paragraph::getFontSettings(lyx::BufferParams const&, int) const 8.94 0.44 0.11 1427808 0.00 0.00 std::vector >::_M_insert_aux(__gnu_cxx::__normal_iteratorstd::allocator > >, char const&) 7.32 0.53 0.09 1437719 0.00 0.00 std::vector > lyx::(anonymous namespace)::iconv_convert(lyx::IconvProcessor&, wchar_t const*, unsigned int) 5.69 0.60 0.07 1638988 0.00 0.00 lyx::operator==(lyx::LyXFont::FontBits const&, lyx::LyXFont::FontBits const&) In other words: The speed-up is signficant, right? Michael
Re: slow opening of docs
Michael Gerz wrote: Edwin, could you please check whether the attached patch saves any time in lyx::Changes::lookup(int) const and lyx::Changes::merge() during opening/saving a file? this is open (save below): Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 7.41 0.02 0.02 268500 0.00 0.00 lyx::InsetBase::inMathed() const 7.41 0.04 0.0210948 0.00 0.00 lyx::support::compare_no_case(std::basic_stringstd::char_traits, std::allocator > const&, std::basic_string, std::allocator > const&) 3.70 0.05 0.01 236382 0.00 0.00 lyx::operator==(lyx::LyXKeySym const&, lyx::LyXKeySym const&) 3.70 0.06 0.01 191783 0.00 0.00 lyx::DocIterator::inTexted() const 3.70 0.07 0.01 182929 0.00 0.00 lyx::operator==(lyx::LyXFont::FontBits const&, lyx::LyXFont::FontBits const&) 3.70 0.08 0.01 181982 0.00 0.00 lyx::Paragraph::Pimpl::insertChar(int, wchar_t, lyx::Change const&) 3.70 0.09 0.01 180583 0.00 0.00 lyx::Paragraph::insertChar(int, wchar_t, lyx::LyXFont const&, lyx::Change const&) 3.70 0.10 0.01 151794 0.00 0.00 lyx::InsetText::getText(int) const 3.70 0.11 0.01 116494 0.00 0.00 lyx::DocIterator::inMathed() const 3.70 0.12 0.0164695 0.00 0.00 lyx::DocIterator::lastpos() const 3.70 0.13 0.0154501 0.00 0.00 lyx::CursorSlice::paragraph() const 3.70 0.14 0.0146416 0.00 0.00 lyx::DocIterator::paragraph() 3.70 0.15 0.0133274 0.00 0.00 lyx::InsetTabular::cell(unsigned int) const 3.70 0.16 0.0118226 0.00 0.00 lyx::LyXLex::Pimpl::next(bool) 3.70 0.17 0.01 9203 0.00 0.00 lyx::InsetBase::nargs() const 3.70 0.18 0.01 8752 0.00 0.00 lyx::MenuItem::~MenuItem() 3.70 0.19 0.01 6936 0.00 0.00 std::vectorstd::allocator > lyx::(anonymous namespace)::iconv_convertwchar_t>(lyx::IconvProcessor&, wchar_t const*, unsigned int) 3.70 0.20 0.01 1936 0.01 0.01 boost::re_detail::perl_matcher<__gnu_cxx::__normal_iteratorstd::string>, std::allocatorconst*, std::string> > >, boost::regex_traitsboost::cpp_regex_traits > >::match_start_line() 3.70 0.21 0.01 1329 0.01 0.01 std::_Rb_tree, std::_Select1st >, std::less, std::allocatorlyx::kb_action> > >::find(std::string const&) const 3.70 0.22 0.01 936 0.01 0.01 boost::signal2boost::last_value, int, std::less, boost::function()(std::string const&, lyx::InsetBase*), std::allocator > >::operator()(std::string const&, lyx::InsetBase*) 3.70 0.23 0.01 439 0.02 0.02 lyx::(anonymous namespace)::Parser::skipSpaceTokens(std::basic_istreamstd::char_traits >&, wchar_t) 3.70 0.24 0.01 18 0.56 0.56 lyx::LyXTabular::read(lyx::Buffer const&, lyx::LyXLex&) 3.70 0.25 0.01 10 1.00 1.55 lyx::InsetFloat::addToToc(lyx::TocList&, lyx::Buffer const&) const 3.70 0.26 0.012 5.0027.94 lyx::TocBackend::update() 3.70 0.27 0.01110.0040.27 lyx::Buffer::updateBibfilesCache() 0.00 0.27 0.00 205702 0.00 0.00 char lyx::support::(anonymous namespace)::ascii_tolower(char) 0.00 0.27 0.00 184108 0.00 0.00 lyx::Paragraph::setFont(int, lyx::LyXFont const&) 0.00 0.27 0.00 183891 0.00 0.00 lyx::Changes::set(lyx::Change const&, int, int) 0.00 0.27 0.00 183891 0.00 0.00 lyx::Changes::merge() 0.00 0.27 0.00 181982 0.00 0.00 lyx::Changes::insert(lyx::Change const&, int) and this save: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 17.07 0.21 0.2115272 0.01 0.06 lyx::Paragraph::write(lyx::Buffer const&, std::ostream&, lyx::BufferParams const&, unsigned int&) const 9.76 0.33 0.12 1456198 0.00 0.00 lyx::Paragraph::getFontSettings(lyx::BufferParams const&, int) const 8.94 0.44 0.11 1427808 0.00 0.00 std::vectorstd::allocator >::_M_insert_aux(__gnu_cxx::__normal_iteratorstd::allocator > >, char const&) 7.32 0.53 0.09 1437719 0.00 0.00 std::vectorstd::allocator > lyx::(anonymous namespace)::iconv_convertwchar_t>(lyx::IconvProcessor&, wchar_t const*, unsigned int) 5.69 0.60 0.07 1638988 0.00 0.00 lyx::operator==(lyx::LyXFont::FontBits const&, lyx::LyXFont::FontBits const&) 4.07 0.65 0.05 1471128 0.00 0.00 lyx::Changes::lyxMarkChange(std::ostream&, int&, lyx::Change const&, lyx::Change const&) 4.07 0.70 0.05 147
Re: slow opening of docs
Edwin, could you please check whether the attached patch saves any time in lyx::Changes::lookup(int) const and lyx::Changes::merge() during opening/saving a file? Michael Index: changes.C === --- changes.C (Revision 16573) +++ changes.C (Arbeitskopie) @@ -77,18 +77,6 @@ } -bool Changes::Range::contains(Range const & r) const -{ - return r.start >= start && r.end <= end; -} - - -bool Changes::Range::contains(pos_type const pos) const -{ - return pos >= start && pos < end; -} - - bool Changes::Range::intersects(Range const & r) const { return r.start < end && r.end > start; // end itself is not in the range! @@ -230,8 +218,10 @@ } -Change const Changes::lookup(pos_type const pos) const +Change const & Changes::lookup(pos_type const pos) const { + static Change const noChange = Change(Change::UNCHANGED); + ChangeTable::const_iterator it = table_.begin(); ChangeTable::const_iterator const end = table_.end(); @@ -240,7 +230,7 @@ return it->change; } - return Change(Change::UNCHANGED); + return noChange; } Index: changes.h === --- changes.h (Revision 16573) +++ changes.h (Arbeitskopie) @@ -67,7 +67,7 @@ /// /// return the change at the given pos - Change const lookup(pos_type pos) const; + Change const & lookup(pos_type pos) const; /// return true if there is a change in the given range (excluding end) bool isChanged(pos_type start, pos_type end) const; @@ -90,10 +90,14 @@ : start(s), end(e) {} // does this range contain r ? - bool contains(Range const & r) const; + bool contains(Range const & r) const { + return r.start >= start && r.end <= end; + } // does this range contain pos ? - bool contains(pos_type pos) const; + bool contains(pos_type pos) const { + return pos >= start && pos < end; + } // do the ranges intersect ? bool intersects(Range const & r) const;
Re: slow opening of docs
Edwin Leuven wrote: Michael Gerz wrote: With optimizations or in debugging mode? aargh! it is compiling with --enable-optimization=-O2 now. will report opening and saving the userguide takes about 1 sec opening profile: % cumulative self self total time seconds secondscalls ms/call ms/call name 10.34 0.03 0.0324962 0.00 0.00 lyx::LyXLex::Pimpl::nextToken() 6.90 0.05 0.02 183891 0.00 0.00 lyx::Changes::merge() saving profile: % cumulative self self total time seconds secondscalls ms/call ms/call name 35.43 0.79 0.79 2002198 0.00 0.00 lyx::Paragraph::getFontSettings(lyx::BufferParams const&, int) const 21.52 1.27 0.48 1963236 0.00 0.00 std::vectorstd::allocator >::_M_insert_aux(__gnu_cxx::__normal_iteratorstd::allocator > >, char const&) 18.39 1.68 0.41 2023687 0.00 0.00 lyx::Changes::lookup(int) const (full profiles here: http://leuven.ecodip.net/lyx/profile.zip)
Re: slow opening of docs
Michael Gerz wrote: With optimizations or in debugging mode? aargh! it is compiling with --enable-optimization=-O2 now. will report back...
Re: slow opening of docs
Edwin Leuven schrieb: Michael Gerz wrote: was wondering why lyx::Changes::set(lyx::Change const&, int, int) is called... Every time you insert a character, the corresponding change has to be set (even if it is unchanged, because it may be inserted in a region of deleted/inserted text). i was expecting that changes::set would be called only if change tracking is on. but i don't know anyting about this stuff, so you probably should ignore me... No, with 1.5.0, change tracking has been fully integrated, i.e., you can switch CT on and off whenever you like to without having to accept/reject changes. dunno. but opening is slow, especially under windows (it takes atm 8 secs to open the userguide on my 1.67Ghz dual core laptop). 10% is then almost a second... With optimizations or in debugging mode? Michael
Re: slow opening of docs
Michael Gerz wrote: was wondering why lyx::Changes::set(lyx::Change const&, int, int) is called... Every time you insert a character, the corresponding change has to be set (even if it is unchanged, because it may be inserted in a region of deleted/inserted text). i was expecting that changes::set would be called only if change tracking is on. but i don't know anyting about this stuff, so you probably should ignore me... For doc loading, this mechanism can be optimized. However, I like the sound approach that we have presently. Is 10% a critical factor? dunno. but opening is slow, especially under windows (it takes atm 8 secs to open the userguide on my 1.67Ghz dual core laptop). 10% is then almost a second...
Re: slow opening of docs
Edwin Leuven schrieb: the following is the profile i get when opening the user guide: (full profile here: http://leuven.ecodip.net/lyx/profile.zip) was wondering why lyx::Changes::set(lyx::Change const&, int, int) is called... Flat profile: Each sample counts as 0.01 seconds. % cumulative self self total time seconds secondscalls ms/call ms/call name 10.00 0.03 0.03 183891 0.00 0.00 lyx::Changes::set(lyx::Change const&, int, int) 3.33 0.11 0.01 181982 0.00 0.00 lyx::Paragraph::Pimpl::insertChar(int, wchar_t, lyx::Change const&) Every time you insert a character, the corresponding change has to be set (even if it is unchanged, because it may be inserted in a region of deleted/inserted text). For doc loading, this mechanism can be optimized. However, I like the sound approach that we have presently. Is 10% a critical factor? Michael