Re: slow opening of docs

[Andre Poenitz]

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

[Andre Poenitz]

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]

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

[Georg Baum]

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 = convertint(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]

 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]

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 = convertint(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 convertint(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

[Enrico Forestieri]

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]

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

[Abdelrazak Younes]

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

[Georg Baum]

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]

> "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]

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

[Enrico Forestieri]

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]

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

[Jean-Marc Lasgouttes]

 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

[Edwin Leuven]

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

[Jean-Marc Lasgouttes]

 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]

> "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

[Edwin Leuven]

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

[Jean-Marc Lasgouttes]

> "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

[Edwin Leuven]

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]

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::vectorlyx::Paragraph::Pimpl::FontTable, std::al
locatorlyx::Paragraph::Pimpl::FontTable 
::operator=(std::vectorlyx::Paragraph::Pimpl::FontTable, std::a

llocatorlyx::Paragraph::Pimpl::FontTable  const)
  4.00  0.20 0.01 4159 0.00 0.00 
__gnu_cxx::__normal_iteratorboost::shared_ptrlyx::L
yXLayout const*, std::vectorboost::shared_ptrlyx::LyXLayout, 
std::allocatorboost::shared_ptrlyx::LyXL
ayout
std::__find_if__gnu_cxx::__normal_iteratorboost::shared_ptrlyx::LyXLayout 
const*, std::vec
torboost::shared_ptrlyx::LyXLayout, 
std::allocatorboost::shared_ptrlyx::LyXLayout   , lyx::(anonym
ous 
namespace)::LayoutNamesEqual(__gnu_cxx::__normal_iteratorboost::shared_ptrlyx::LyXLayout 
const*, st
d::vectorboost::shared_ptrlyx::LyXLayout, 
std::allocatorboost::shared_ptrlyx::LyXLayout   , __gnu_
cxx::__normal_iteratorboost::shared_ptrlyx::LyXLayout const*, 
std::vectorboost::shared_ptrlyx::LyXLayo
ut, std::allocatorboost::shared_ptrlyx::LyXLayout   , 
lyx::(anonymous namespace)::LayoutNamesEqual,

std::random_access_iterator_tag)

Re: slow opening of docs

[Edwin Leuven]

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  QHashwchar_t, 
int::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

[Edwin Leuven]

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]

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::vector::operator=(std::vector const&)
  4.00  0.20 0.01 4159 0.00 0.00 
__gnu_cxx::__normal_iterator const*, std::vector > > > 
std::__find_if<__gnu_cxx::__normal_iterator > >, lyx::(anonym
ous 
namespace)::LayoutNamesEqual>(__gnu_cxx::__normal_iterator > >, __gnu_
cxx::__normal_iterator, std::allocator > >, 
lyx::(anonymous namespace)::LayoutNamesEqual,

std::random_access_iterator_tag)

Re: slow opening of docs

[Edwin Leuven]

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  QHash::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

[Jean-Marc Lasgouttes]

 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

[Leuven, E.]

 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 Younes]

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_stringwchar_t, 
std::char_traitswchar_t, std::allocatorwchar_t  const, 
std::basic_stringwchar_t, std::char_traitswchar_t, 
std::allocatorwchar_t  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

[Edwin Leuven]

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_pathstd::string, boost::fil

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_stringwchar_t, std::char_

traitswchar_t, std::allocatorwchar_t  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_stringwchar_t, std::c

har_traitswchar_t, std::allocatorwchar_t  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::vectorwchar_t, std::allocatorwchar_t ::_M_in
sert_aux(__gnu_cxx::__normal_iteratorwchar_t*, std::vectorwchar_t, 
std::allocatorwchar_t  , wchar_t c

onst)
  4.55  0.16 0.01 4412 0.00 0.00 
__gnu_cxx::__normal_iteratorboost::shared_ptrlyx::L
yXLayout const*, std::vectorboost::shared_ptrlyx::LyXLayout, 
std::allocatorboost::shared_ptrlyx::LyXL
ayout
std::__find_if__gnu_cxx::__normal_iteratorboost::shared_ptrlyx::LyXLayout 
const*, std::vec
torboost::shared_ptrlyx::LyXLayout, 
std::allocatorboost::shared_ptrlyx::LyXLayout   , lyx::(anonym
ous 
namespace)::LayoutNamesEqual(__gnu_cxx::__normal_iteratorboost::shared_ptrlyx::LyXLayout 
const*, st
d::vectorboost::shared_ptrlyx::LyXLayout, 
std::allocatorboost::shared_ptrlyx::LyXLayout   , __gnu_
cxx::__normal_iteratorboost::shared_ptrlyx::LyXLayout const*, 
std::vectorboost::shared_ptrlyx::LyXLayo
ut, std::allocatorboost::shared_ptrlyx::LyXLayout   , 
lyx::(anonymous namespace)::LayoutNamesEqual,

std::random_access_iterator_tag)
  4.55  0.17 0.01 2000 0.01 0.01 
lyx::lookupFont(std::basic_stringwchar_t, std::char_

traitswchar_t, std::allocatorwchar_t  const)
  4.55  0.18 0.01 1766 0.01 0.01  std::string const 
lyx::support::(anonymous namespace)

::doSplitstd::string, char(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::vectorchar, 
std::allocatorchar ::_M_insert_a
ux(__gnu_cxx::__normal_iteratorchar*, std::vectorchar, 
std::allocatorchar  , 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::vectorchar, 
std::allocatorchar  lyx::(anonym
ous namespace)::iconv_convertchar, wchar_t(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) 

Re: slow opening of docs

[Abdelrazak Younes]

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

[Angus Leeming]

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

[Michael Gerz]

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

[Edwin Leuven]

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

erchar(char)
  0.00  0.01 0.0039471 0.00 0.00 
boost::filesystem::basic_pathstd::string, boost::fil

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_stringwchar_t, std::c

har_traitswchar_t, std::allocatorwchar_t  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_stringwchar
_t, std::char_traitswchar_t, std::allocatorwchar_t  const, 
std::basic_stringwchar_t, std::char_trait

swchar_t, std::allocatorwchar_t  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

ngwchar_t, std::char_traitswchar_t, std::allocatorwchar_t )
  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_treelyx::kb_action, std::pairlyx

Re: slow opening of docs

[Abdelrazak Younes]

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

[Jean-Marc Lasgouttes]

> "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

[Leuven, E.]

> 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 Younes]

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_string const&, 
std::basic_string 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

[Edwin Leuven]

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::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 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 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_iterator >, wchar_t c

onst&)
  4.55  0.16 0.01 4412 0.00 0.00 
__gnu_cxx::__normal_iterator const*, std::vector > > > 
std::__find_if<__gnu_cxx::__normal_iterator > >, lyx::(anonym
ous 
namespace)::LayoutNamesEqual>(__gnu_cxx::__normal_iterator > >, __gnu_
cxx::__normal_iterator, 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 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::vector::_M_insert_a
ux(__gnu_cxx::__normal_iterator >, 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::vector 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 

Re: slow opening of docs

[Abdelrazak Younes]

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

[Angus Leeming]

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

[Michael Gerz]

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

[Edwin Leuven]

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::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 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 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&)
  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

[Abdelrazak Younes]

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.

slow opening of docs

[Edwin Leuven]

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)
  6.67  0.05 0.02   261898 0.00 0.00 
lyx::DocIterator::inTexted() const
  6.67  0.07 0.0242494 0.00 0.00 
lyx::DocIterator::forwardPos(bool)
  3.33  0.08 0.01   209766 0.00 0.00 
lyx::InsetText::getText(int) const
  3.33  0.09 0.01   184108 0.00 0.00 
lyx::Paragraph::setFont(int, lyx::LyXFont const)
  3.33  0.10 0.01   182921 0.00 0.00 
lyx::operator==(lyx::LyXFont::FontBits const, lyx::LyXFont::FontBits 
const)
  3.33  0.11 0.01   181982 0.00 0.00 
lyx::Paragraph::Pimpl::insertChar(int, wchar_t, lyx::Change const)
  3.33  0.12 0.0172431 0.00 0.00 
lyx::CursorSlice::paragraph() const
  3.33  0.13 0.0147480 0.00 0.00 
lyx::LyXTabular::getCellInset(unsigned int) const
  3.33  0.14 0.0147480 0.00 0.00 
lyx::InsetTabular::cell(unsigned int) const
  3.33  0.15 0.0124961 0.00 0.00 
lyx::LyXLex::Pimpl::nextToken()
  3.33  0.16 0.0124371 0.00 0.00 
lyx::support::compare_ascii_no_case(std::string const, std::string const)
  3.33  0.17 0.0118227 0.00 0.00 
lyx::LyXLex::Pimpl::next(bool)
  3.33  0.18 0.0114768 0.00 0.00 
lyx::support::token(std::basic_stringwchar_t, 
std::char_traitswchar_t, std::allocatorwchar_

t  const, wchar_t, int)
  3.33  0.19 0.0112471 0.00 0.01 
lyx::DocIterator::forwardPar()
  3.33  0.20 0.01 8798 0.00 0.00 
lyx::Paragraph::params() const
  3.33  0.21 0.01 2275 0.00 0.00 
lyx::LyXLex::Pimpl::eatLine()
  3.33  0.22 0.01 2000 0.01 0.01 
lyx::lookupFont(std::basic_stringwchar_t, std::char_traitswchar_t, 
std::allocatorwchar_t 

 const)
  3.33  0.23 0.01 1909 0.01 0.01  lyx::(anonymous 
namespace)::readParagraph(lyx::Buffer const, lyx::Paragraph, 
lyx::LyXLex, ly

x::ErrorList)
  3.33  0.24 0.01  918 0.01 0.01 
lyx::kb_keymap::defkey(lyx::kb_sequence*, lyx::FuncRequest const, 
unsigned int)
  3.33  0.25 0.01  480 0.02 0.03  bool 
lyx::sortedlyx::keyword_item*, lyx::(anonymous 
namespace)::compare_tags(lyx::keyword_ite

m*, lyx::keyword_item*, lyx::(anonymous namespace)::compare_tags)
  3.33  0.26 0.01   79 0.13 0.13 
lyx::LyXLayout::LyXLayout(lyx::LyXLayout const)
  3.33  0.27 0.016 1.67 1.67 
lyx::frontend::QLFontInfo::QLFontInfo(lyx::LyXFont const)
  3.33  0.28 0.013 3.3316.52 
lyx::TocBackend::update()
  3.33  0.29 0.013 3.3336.27 
lyx::updateLabels(lyx::Buffer const, bool)
  3.33  0.30 0.01110.00   264.76 
lyx::LyXFunc::dispatch(lyx::FuncRequest const)

Re: slow opening of docs

[Michael Gerz]

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

Re: slow opening of docs

[Edwin Leuven]

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

[Michael Gerz]

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

[Edwin Leuven]

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]

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::vectorchar, 
std::allocatorchar 
::_M_insert_aux(__gnu_cxx::__normal_iteratorchar*, std::vectorchar, 
std::allocatorchar  , 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]

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]

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_stringwchar_t, 
std::char_traitswchar_t, std::allocatorwchar_t  const, 
std::basic_stringwchar_t, std::char_traitswchar_t, 
std::allocatorwchar_t  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::vectorchar, 
std::allocatorchar  lyx::(anonymous namespace)::iconv_convertchar, 
wchar_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_iteratorchar const*, 
std::string, 
std::allocatorboost::sub_match__gnu_cxx::__normal_iteratorchar 
const*, std::string  , boost::regex_traitschar, 
boost::cpp_regex_traitschar  ::match_start_line()
  3.70  0.21 0.01 1329 0.01 0.01 
std::_Rb_treestd::string, std::pairstd::string const, lyx::kb_action, 
std::_Select1ststd::pairstd::string const, lyx::kb_action , 
std::lessstd::string, std::allocatorstd::pairstd::string const, 
lyx::kb_action  ::find(std::string const) const
  3.70  0.22 0.01  936 0.01 0.01 
boost::signal2void, std::string const, lyx::InsetBase*, 
boost::last_valuevoid, int, std::lessint, boost::functionvoid 
()(std::string const, lyx::InsetBase*), std::allocatorvoid  
::operator()(std::string const, lyx::InsetBase*)
  3.70  0.23 0.01  439 0.02 0.02  lyx::(anonymous 
namespace)::Parser::skipSpaceTokens(std::basic_istreamwchar_t, 
std::char_traitswchar_t , 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_tolowerchar(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::vectorchar, 
std::allocatorchar 
::_M_insert_aux(__gnu_cxx::__normal_iteratorchar*, std::vectorchar, 
std::allocatorchar  , char const)
  7.32  0.53 0.09  1437719 0.00 0.00  std::vectorchar, 
std::allocatorchar  lyx::(anonymous 

Re: slow opening of docs

[Michael Gerz]

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_stringwchar_t, 
std::char_traitswchar_t, std::allocatorwchar_t  const, 
std::basic_stringwchar_t, std::char_traitswchar_t, 
std::allocatorwchar_t  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::vectorchar, std::allocatorchar 
::_M_insert_aux(__gnu_cxx::__normal_iteratorchar*, std::vectorchar, 
std::allocatorchar  , char const)
  7.32  0.53 0.09  1437719 0.00 0.00  
std::vectorchar, std::allocatorchar  lyx::(anonymous 
namespace)::iconv_convertchar, wchar_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)



In other words: The speed-up is signficant, right?

Michael

Re: slow opening of docs

[Edwin Leuven]

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

[Georg Baum]

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

[Abdelrazak Younes]

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::vectorchar, 
std::allocatorchar 
 ::_M_insert_aux(__gnu_cxx::__normal_iteratorchar*, std::vectorchar, 
std::allocatorchar  , 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

[Edwin Leuven]

Abdelrazak Younes wrote:

is this linux with oprofile?


yeah, mon péché mignon... ;-)

slow opening of docs

[Edwin Leuven]

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)
  6.67  0.05 0.02   261898 0.00 0.00 
lyx::DocIterator::inTexted() const
  6.67  0.07 0.0242494 0.00 0.00 
lyx::DocIterator::forwardPos(bool)
  3.33  0.08 0.01   209766 0.00 0.00 
lyx::InsetText::getText(int) const
  3.33  0.09 0.01   184108 0.00 0.00 
lyx::Paragraph::setFont(int, lyx::LyXFont const&)
  3.33  0.10 0.01   182921 0.00 0.00 
lyx::operator==(lyx::LyXFont::FontBits const&, lyx::LyXFont::FontBits 
const&)
  3.33  0.11 0.01   181982 0.00 0.00 
lyx::Paragraph::Pimpl::insertChar(int, wchar_t, lyx::Change const&)
  3.33  0.12 0.0172431 0.00 0.00 
lyx::CursorSlice::paragraph() const
  3.33  0.13 0.0147480 0.00 0.00 
lyx::LyXTabular::getCellInset(unsigned int) const
  3.33  0.14 0.0147480 0.00 0.00 
lyx::InsetTabular::cell(unsigned int) const
  3.33  0.15 0.0124961 0.00 0.00 
lyx::LyXLex::Pimpl::nextToken()
  3.33  0.16 0.0124371 0.00 0.00 
lyx::support::compare_ascii_no_case(std::string const&, std::string const&)
  3.33  0.17 0.0118227 0.00 0.00 
lyx::LyXLex::Pimpl::next(bool)
  3.33  0.18 0.0114768 0.00 0.00 
lyx::support::token(std::basic_string > const&, wchar_t, int)
  3.33  0.19 0.0112471 0.00 0.01 
lyx::DocIterator::forwardPar()
  3.33  0.20 0.01 8798 0.00 0.00 
lyx::Paragraph::params() const
  3.33  0.21 0.01 2275 0.00 0.00 
lyx::LyXLex::Pimpl::eatLine()
  3.33  0.22 0.01 2000 0.01 0.01 
lyx::lookupFont(std::basic_string

 const&)
  3.33  0.23 0.01 1909 0.01 0.01  lyx::(anonymous 
namespace)::readParagraph(lyx::Buffer const&, lyx::Paragraph&, 
lyx::LyXLex&, ly

x::ErrorList&)
  3.33  0.24 0.01  918 0.01 0.01 
lyx::kb_keymap::defkey(lyx::kb_sequence*, lyx::FuncRequest const&, 
unsigned int)
  3.33  0.25 0.01  480 0.02 0.03  bool 
lyx::sorted(lyx::keyword_ite

m*, lyx::keyword_item*, lyx::(anonymous namespace)::compare_tags)
  3.33  0.26 0.01   79 0.13 0.13 
lyx::LyXLayout::LyXLayout(lyx::LyXLayout const&)
  3.33  0.27 0.016 1.67 1.67 
lyx::frontend::QLFontInfo::QLFontInfo(lyx::LyXFont const&)
  3.33  0.28 0.013 3.3316.52 
lyx::TocBackend::update()
  3.33  0.29 0.013 3.3336.27 
lyx::updateLabels(lyx::Buffer const&, bool)
  3.33  0.30 0.01110.00   264.76 
lyx::LyXFunc::dispatch(lyx::FuncRequest const&)

Re: slow opening of docs

[Michael Gerz]

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

Re: slow opening of docs

[Edwin Leuven]

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

[Michael Gerz]

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

[Edwin Leuven]

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]

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::vector::_M_insert_aux(__gnu_cxx::__normal_iterator >, 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]

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]

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_string const&, 
std::basic_string 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::vector lyx::(anonymous namespace)::iconv_convert(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::allocator > >, boost::regex_traits >::match_start_line()
  3.70  0.21 0.01 1329 0.01 0.01 
std::_Rb_tree, 
std::less, std::allocator > >::find(std::string const&) const
  3.70  0.22 0.01  936 0.01 0.01 
boost::signal2 
>::operator()(std::string const&, lyx::InsetBase*)
  3.70  0.23 0.01  439 0.02 0.02  lyx::(anonymous 
namespace)::Parser::skipSpaceTokens(std::basic_istream&, 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::vector::_M_insert_aux(__gnu_cxx::__normal_iterator >, 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 

Re: slow opening of docs

[Michael Gerz]

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_string const&, 
std::basic_string 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_iterator >, 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

[Edwin Leuven]

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

[Georg Baum]

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

[Abdelrazak Younes]

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::vector::_M_insert_aux(__gnu_cxx::__normal_iterator >, 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

[Edwin Leuven]

Abdelrazak Younes wrote:

is this linux with oprofile?


yeah, mon péché mignon... ;-)