another example of org being slow, with some analysis

another example of org being slow, with some analysis

[Eric S Fraga]

Hello,

there have been a few threads recently mentioning poor
performance.  Although some of these have been resolved (e.g. the use of
=linum=), I wonder if I could add a data point.

I have a medium (for me) sized (385 kB) org file with all of my "tasks"
in a date-tree structure.  One of the tasks requires me to edit a small
table every day for a couple of weeks (see below for the table).  Asking
for a recalculation of the table (C-u C-c C-c) takes 17 seconds on a new
laptop (16 GB RAM, SSD, i7 cpu, Debian linux testing) which is quite
fast at most other tasks.

The output of the ELP profiler is here:

--8<---------------cut here---------------start------------->8---
org-ctrl-c-ctrl-c                   1    17.655796272  17.655796272
org-table-recalculate               1    17.652738791  17.652738791
org-table-get-range                 14   13.166332242  0.940452303
org-table-eval-formula              19   13.101183716  0.6895359851
org-goto-line                       104  10.761145733  0.1034725551
org-table-copy-region               13   7.362366204   0.5663358618
org-current-line                    66   6.8422078910  0.1036698165
org-table-get-descriptor-line       28   1.659497877   0.0592677813
org-table-align                     1    0.415633428   0.415633428
org-table-get-specials              1    0.206756703   0.206756703
org-table-expand-lhs-ranges         1    0.103551707   0.103551707
org-element--parse-to               6    0.0031655370  0.0005275895
org-babel-execute-safely-maybe      1    0.002872891   0.002872891
org-babel-execute-maybe             1    0.002870729   0.002870729
org-babel-execute-src-block-maybe   1    0.002846968   0.002846968
org-element-at-point                3    0.0028012790  0.0009337596
org-babel-where-is-src-block-head   1    0.002664822   0.002664822
org-element--cache-compare          303  0.0025883040  8.542...e-06
org-table-current-column            119  0.002235665   1.878...e-05
--8<---------------cut here---------------end--------------->8---

The table, for completeness, is here:

#+begin_src org
  | date             | TBD | Victoria | London Bridge | Blackfriars | City | Farrindgon | St Pancras | Totals | Miles |
  |                  | 2.5 |        5 |           4.8 |         3.2 |  2.9 |          5 |        1.6 |        |       |
  |------------------+-----+----------+---------------+-------------+------+------------+------------+--------+-------|
  | [2015-06-08 Mon] |   2 |          |               |             |    1 |            |          1 |    9.5 |   5.9 |
  | [2015-06-12 Fri] |   2 |          |               |           1 |      |            |          1 |    9.8 |   6.0 |
  | [2015-06-15 Mon] |   2 |          |             1 |             |      |            |          1 |   11.4 |   7.0 |
  | [2015-06-17 Wed] |   2 |          |               |           1 |      |            |          1 |    9.8 |   6.0 |
  | [2015-06-18 Thu] |   1 |          |               |           1 |      |            |            |    5.7 |   3.5 |
  |------------------+-----+----------+---------------+-------------+------+------------+------------+--------+-------|
  | Totals           |   9 |        0 |             1 |           3 |    1 |          0 |          4 |   46.2 |  28.5 |
  ,#+TBLFM: @>$2..@>$>>=vsum(@I..@II)::$9=($2..$>>>)*(@<<$2..@<<$>>>);EN::$10=$9/1.62;%.1f
#+end_src

If I change, for instance, the entry in the TBD column for today from 1
to 2, in the original file, it takes 17 seconds.  If I do it in this
email buffer (changing mode to org etc.), it is essentially
instantaneous.

Large buffers seem to be causing problems with org.  I've noticed this
elsewhere as I do tend to work with org files that are often 0.25-1 MB
in size.  Having looked at the profiler output, my gut feeling was that
the buffer is being repeatedly parsed (or some similar activity) given
where the time is being spent.  So... as the table is currently 99% of
the way into the buffer, I have copied the table to the start of the
same large document and, lo and behold, the table recalculation on the
copy is instantaneous!

(the moral of the story, for me, may be to use a reverse date-tree
structure for my tasks, if such were possible... maybe it is, given the
hidden gems in org! ;-)

I would be happy to instrument more than just org, if it would help.  I
should add that the above profile was done using emacs -Q so no
customisations.

I have no real issue with the performance of org overall but I thought
I'd add a data point in case it helps.

thanks,
eric

-- 
: Eric S Fraga (0xFFFCF67D), Emacs 24.4.1, Org release_8.3beta-1216-gb856f6

Re: another example of org being slow, with some analysis

[Nick Dokos]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:


> The output of the ELP profiler is here:
>
> ...
> org-goto-line                       104  10.761145733  0.1034725551
> ..
> org-current-line                    66   6.8422078910  0.1036698165
> ...

I find these two difficult to explain: they account for the vast
majority of the time, they don't call anything other than basic emacs
lisp functions (which should be very fast) and they take an unbelievably
long 0.1 s/call - I did a profile of a single call of each in a file
where wc reports these stats:

  12961  270362 4317977 /home/nick/lib/notes/notes.org

and I got 0.002s for the first (going to line 6000, about the middle of
the file) and 0.0004s for the second: a factor of 50 smaller for the
first and a factor of 250 smaller for the second.

Maybe it's an artifact of profiling, but maybe you can try instrumenting
these two functions and doing something similar.  Do you still get 0.1s
for each call?

Nick

Re: another example of org being slow, with some analysis

[Daniel Bausch]

Hi!

Nick Dokos <ndokos@gmail.com> writes:

> Eric S Fraga <e.fraga@ucl.ac.uk> writes:
>
>
>> The output of the ELP profiler is here:
>>
>> ...
>> org-goto-line                       104  10.761145733  0.1034725551
>> ..
>> org-current-line                    66   6.8422078910  0.1036698165
>> ...
>
> I find these two difficult to explain: they account for the vast
> majority of the time, they don't call anything other than basic emacs
> lisp functions (which should be very fast) and they take an unbelievably
> long 0.1 s/call - I did a profile of a single call of each in a file
> where wc reports these stats:
>
>   12961  270362 4317977 /home/nick/lib/notes/notes.org
>
> and I got 0.002s for the first (going to line 6000, about the middle of
> the file) and 0.0004s for the second: a factor of 50 smaller for the
> first and a factor of 250 smaller for the second.
>
> Maybe it's an artifact of profiling, but maybe you can try instrumenting
> these two functions and doing something similar.  Do you still get 0.1s
> for each call?

Line 6000 is indeed quite "lame".  I have similar problems like Eric.  A
table recalculation at line 43868 takes about a minute at my quite fast
machine.  I also tracked that down to org-current-line.  One interesting
detail is that this depends on the buffer encoding.  With ASCII the
recalculation takes less than a second, with utf-8 about a minute.

I think it actually is not an org-mode problem but depends on how
(count-lines 1 (point)) works, as it is using regex searches for the
line endings.  I can imagine that the regex parser for utf-8 can be
inefficient.

Regards,
Daniel
-- 
MSc. Daniel Bausch
Research Assistant (Computer Science)
Technische Universität Darmstadt
http://www.dvs.tu-darmstadt.de/staff/dbausch

Re: another example of org being slow, with some analysis

[Daniel Bausch]

Daniel Bausch <bausch@dvs.tu-darmstadt.de> writes:

> I think it actually is not an org-mode problem but depends on how
> (count-lines 1 (point)) works, as it is using regex searches for the
> line endings.  I can imagine that the regex parser for utf-8 can be
> inefficient.

I just looked again at Eric's profile output.  Why does count-lines not
show up there at all?  Could it be goto-char, bolp, or even
save-excursion instead?  I suspected count-lines because it is really
doing heavy lifting.

Regards,
Daniel
-- 
MSc. Daniel Bausch
Research Assistant (Computer Science)
Technische Universität Darmstadt
http://www.dvs.tu-darmstadt.de/staff/dbausch

Re: another example of org being slow, with some analysis

[Nicolas Goaziou]

Hello,

Daniel Bausch <bausch@dvs.tu-darmstadt.de> writes:

> Line 6000 is indeed quite "lame".  I have similar problems like Eric.  A
> table recalculation at line 43868 takes about a minute at my quite fast
> machine.  I also tracked that down to org-current-line.  One interesting
> detail is that this depends on the buffer encoding.  With ASCII the
> recalculation takes less than a second, with utf-8 about a minute.
>
> I think it actually is not an org-mode problem but depends on how
> (count-lines 1 (point)) works, as it is using regex searches for the
> line endings.  I can imagine that the regex parser for utf-8 can be
> inefficient.

Actually `org-count-lines' and `org-goto-line' are inefficient
functions. Unfortunately, Org Table overuses the latter. Functions
calling it should be refactored to use, e.g., `goto-char' instead.

However, this might require some deep changes in the library.


Regards,

-- 
Nicolas Goaziou

Re: another example of org being slow, with some analysis

[Eric S Fraga]

On Friday, 19 Jun 2015 at 08:19, Daniel Bausch wrote:

[...]

> Line 6000 is indeed quite "lame".  I have similar problems like Eric.  A
> table recalculation at line 43868 takes about a minute at my quite fast
> machine.  I also tracked that down to org-current-line.  One interesting
> detail is that this depends on the buffer encoding.  With ASCII the
> recalculation takes less than a second, with utf-8 about a minute.

Adding some data: my table is at line 8438 in the buffer but character
position 398345 (I have very long lines as I use visual-line-mode in org
exclusively with org-indent).  I do use utf-8 encoding.

I have just tried updating the table on a different laptop (i7-2760, 8
cores, 8 GB RAM, Ubuntu) and it was very fast.  

The two laptops are running different versions of emacs (tracking latest
emacs developments on Ubuntu and Debian testing lead to different
versions unfortunately) so my gut feeling is that there is an emacs
issue here and possibly one related to utf-8 as Daniel suggests.

I'll try to do more instrumenting on my other laptop when I get a
chance.

thanks all,
eric

-- 
: Eric S Fraga (0xFFFCF67D), Emacs 25.0.50.1, Org release_8.3beta-1147-g0e5069.dirty

Re: another example of org being slow, with some analysis

[Daniel Bausch]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> On Friday, 19 Jun 2015 at 08:19, Daniel Bausch wrote:
>
> [...]
>
>> Line 6000 is indeed quite "lame".  I have similar problems like Eric.  A
>> table recalculation at line 43868 takes about a minute at my quite fast
>> machine.  I also tracked that down to org-current-line.  One interesting
>> detail is that this depends on the buffer encoding.  With ASCII the
>> recalculation takes less than a second, with utf-8 about a minute.
>
> Adding some data: my table is at line 8438 in the buffer but character
> position 398345 (I have very long lines as I use visual-line-mode in org
> exclusively with org-indent).  I do use utf-8 encoding.
>
> I have just tried updating the table on a different laptop (i7-2760, 8
> cores, 8 GB RAM, Ubuntu) and it was very fast.  
>
> The two laptops are running different versions of emacs (tracking latest
> emacs developments on Ubuntu and Debian testing lead to different
> versions unfortunately) so my gut feeling is that there is an emacs
> issue here and possibly one related to utf-8 as Daniel suggests.

Maybe it is related (and maybe not - just some thoughts): Since some
months I keep having a problem with my preferred encoding.  Gentoo
changed some things how the LC_... variables are set during boot.  Now
emacs daemon starts with "no encoding".  I tried to fix that by
inserting (prefer-coding-system 'utf-8) into mit ~/.emacs file, but that
does not help.  I still need to manually execute prefer-coding-system by
hand and revert my org-file (which is automatically opened during login)
with C-x RET r utf-8 every day.  But if I remember correctly, I started
observing the slowness of the table recalculation long before that
change in Gentoo.  Maybe it got worse since then but that might also be
just because the file grew further.  If anyone could give me a hint how
to reliably set the preferred (or internal) encoding I could check
wether it might have something to do with the system locale.  (I can
imagine that in some constellations there could be some otherwise
unnecessary conversion happening.  E.g. maybe utf-8 support is faster if
the system locale is also utf-8.)  Is there anything like an internal
encoding in emacs at all?  As far as I know I can type any character in
any buffer regardless of the buffer encoding.  I just cannot save the
buffer if the encoding does not support a character.  How is then a
utf-8 *buffer* different from a buffer with no encoding (until being
saved).  Does goto-char work on bytes or really on characters?  How does
it maybe deal different with characters made up of multiple bytes in the
on-disk encoding of the buffer?

Regards,
Daniel
-- 
MSc. Daniel Bausch
Research Assistant (Computer Science)
Technische Universität Darmstadt
http://www.dvs.tu-darmstadt.de/staff/dbausch

Re: another example of org being slow, with some analysis

[Eric S Fraga]

On Friday, 19 Jun 2015 at 10:28, Daniel Bausch wrote:

[...]

> If anyone could give me a hint how to reliably set the preferred (or
> internal) encoding I could check wether it might have something to do
> with the system locale.

I have (only) the following encoding related settings in my
initialisation, some of which are very historical and may or may not be
needed...

#+begin_src emacs-lisp
  (prefer-coding-system 'utf-8)
  (set-charset-priority 'unicode)
  (setq default-process-coding-system '(utf-8-unix . utf-8-unix))
#+end_src

I think the first one is the most important.

-- 
: Eric S Fraga (0xFFFCF67D), Emacs 25.0.50.1, Org release_8.3beta-1231-ga0a883

Re: another example of org being slow, with some analysis

[Daniel Bausch]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> On Friday, 19 Jun 2015 at 10:28, Daniel Bausch wrote:
>
> [...]
>
>> If anyone could give me a hint how to reliably set the preferred (or
>> internal) encoding I could check wether it might have something to do
>> with the system locale.
>
> I have (only) the following encoding related settings in my
> initialisation, some of which are very historical and may or may not be
> needed...
>
> #+begin_src emacs-lisp
>   (prefer-coding-system 'utf-8)
>   (set-charset-priority 'unicode)
>   (setq default-process-coding-system '(utf-8-unix . utf-8-unix))
> #+end_src
>
> I think the first one is the most important.

Thank you for the code, but unfortunately it does not help.  The first
line I already had and adding the other two did not help either.
Executing M-x prefer-coding-system interactively works and that is what
I am doing each day.  Maybe I will look again how to set the expected
LC_... environment variables for emacs daemon.

Regards,
Daniel
-- 
MSc. Daniel Bausch
Research Assistant (Computer Science)
Technische Universität Darmstadt
http://www.dvs.tu-darmstadt.de/staff/dbausch

Re: another example of org being slow, with some analysis

[Eric S Fraga]

On Monday, 22 Jun 2015 at 08:48, Daniel Bausch wrote:

[...]

> I am doing each day.  Maybe I will look again how to set the expected
> LC_... environment variables for emacs daemon.

This may be the way forward.  My LC related environment variables are
all set to en_GB.UTF-8.

This seems to be set in /etc/default/locale on my systems.

-- 
: Eric S Fraga (0xFFFCF67D), Emacs 25.0.50.1, Org release_8.3beta-1231-ga0a883

Re: another example of org being slow, with some analysis

[Nick Dokos]

Eric S Fraga <e.fraga@ucl.ac.uk> writes:

> On Friday, 19 Jun 2015 at 08:19, Daniel Bausch wrote:
>
> [...]
>
>> Line 6000 is indeed quite "lame".  I have similar problems like Eric.  A
>> table recalculation at line 43868 takes about a minute at my quite fast
>> machine.  I also tracked that down to org-current-line.  One interesting
>> detail is that this depends on the buffer encoding.  With ASCII the
>> recalculation takes less than a second, with utf-8 about a minute.
>
> Adding some data: my table is at line 8438 in the buffer but character
> position 398345 (I have very long lines as I use visual-line-mode in org
> exclusively with org-indent).  I do use utf-8 encoding.
>
> I have just tried updating the table on a different laptop (i7-2760, 8
> cores, 8 GB RAM, Ubuntu) and it was very fast.  
>
> The two laptops are running different versions of emacs (tracking latest
> emacs developments on Ubuntu and Debian testing lead to different
> versions unfortunately) so my gut feeling is that there is an emacs
> issue here and possibly one related to utf-8 as Daniel suggests.
>
> I'll try to do more instrumenting on my other laptop when I get a
> chance.
>
What is the setting of cache-long-scans you are using? Does it differ
on the two laptops?

Ivan Andrus suggested setting it to nil, but it seems that for this
case, leaving it at t (the default) should be much faster. But there
may be a bug in the cache code.

-- 
Nick

Re: another example of org being slow, with some analysis

[Eric S Fraga]

On Friday, 19 Jun 2015 at 09:53, Nick Dokos wrote:

[...]

> What is the setting of cache-long-scans you are using? Does it differ
> on the two laptops?
>
> Ivan Andrus suggested setting it to nil, but it seems that for this
> case, leaving it at t (the default) should be much faster. But there
> may be a bug in the cache code.

It's the default (t) in both cases.  My emacs initialisation is the same
on all of my systems and I didn't even know about this setting!

-- 
: Eric S Fraga (0xFFFCF67D), Emacs 25.0.50.1, Org release_8.3beta-1231-ga0a883

Re: another example of org being slow, with some analysis

[Jacob Nielsen]

Nick Dokos <ndokos@gmail.com> writes:

> Eric S Fraga <e.fraga@ucl.ac.uk> writes:
>
>> On Friday, 19 Jun 2015 at 08:19, Daniel Bausch wrote:
>>
>> [...]
>>
>>> Line 6000 is indeed quite "lame".  I have similar problems like Eric.  A
>>> table recalculation at line 43868 takes about a minute at my quite fast
>>> machine.  I also tracked that down to org-current-line.  One interesting
>>> detail is that this depends on the buffer encoding.  With ASCII the
>>> recalculation takes less than a second, with utf-8 about a minute.
>>
>> Adding some data: my table is at line 8438 in the buffer but character
>> position 398345 (I have very long lines as I use visual-line-mode in org
>> exclusively with org-indent).  I do use utf-8 encoding.
>>
>> I have just tried updating the table on a different laptop (i7-2760, 8
>> cores, 8 GB RAM, Ubuntu) and it was very fast.  
>>
>> The two laptops are running different versions of emacs (tracking latest
>> emacs developments on Ubuntu and Debian testing lead to different
>> versions unfortunately) so my gut feeling is that there is an emacs
>> issue here and possibly one related to utf-8 as Daniel suggests.
>>
>> I'll try to do more instrumenting on my other laptop when I get a
>> chance.
>>
> What is the setting of cache-long-scans you are using? Does it differ
> on the two laptops?
>
> Ivan Andrus suggested setting it to nil, but it seems that for this
> case, leaving it at t (the default) should be much faster. But there
> may be a bug in the cache code.

It *should* be faster but it isn't :-( At least not when using org mode.

I've had this in my org file where I recalculate tables regularly.

# -*- cache-long-scans: nil; -*-
# This makes forward-line much faster and thus org-goto-line and thus org-table-sum (C-c +)

Before it took forever to recalculate tables; now it's fast :-)

Org mode file with 10500 lines. The tables I recalculate are at the
bottom. Current org mode version is 8.2.10 (org-plus-contrib 20150601)

Best regards,
Jacob

Re: another example of org being slow, with some analysis

[Ivan Andrus]

[-- Attachment #1: Type: text/plain, Size: 5003 bytes --]

I’m jumping into the middle of the thread, but have you tried

    (setq cache-long-scans nil)

That solved some performance issues for me.  I can’t remember where
I got the advice.

-Ivan

On Jun 18, 2015, at 10:28 AM, Eric S Fraga <e.fraga@ucl.ac.uk> wrote:

Hello,

there have been a few threads recently mentioning poor
performance.  Although some of these have been resolved (e.g. the use of
=linum=), I wonder if I could add a data point.

I have a medium (for me) sized (385 kB) org file with all of my "tasks"
in a date-tree structure.  One of the tasks requires me to edit a small
table every day for a couple of weeks (see below for the table).  Asking
for a recalculation of the table (C-u C-c C-c) takes 17 seconds on a new
laptop (16 GB RAM, SSD, i7 cpu, Debian linux testing) which is quite
fast at most other tasks.

The output of the ELP profiler is here:

--8<---------------cut here---------------start------------->8---
org-ctrl-c-ctrl-c                   1    17.655796272  17.655796272
org-table-recalculate               1    17.652738791  17.652738791
org-table-get-range                 14   13.166332242  0.940452303
org-table-eval-formula              19   13.101183716  0.6895359851
org-goto-line                       104  10.761145733  0.1034725551
org-table-copy-region               13   7.362366204   0.5663358618
org-current-line                    66   6.8422078910  0.1036698165
org-table-get-descriptor-line       28   1.659497877   0.0592677813
org-table-align                     1    0.415633428   0.415633428
org-table-get-specials              1    0.206756703   0.206756703
org-table-expand-lhs-ranges         1    0.103551707   0.103551707
org-element--parse-to               6    0.0031655370  0.0005275895
org-babel-execute-safely-maybe      1    0.002872891   0.002872891
org-babel-execute-maybe             1    0.002870729   0.002870729
org-babel-execute-src-block-maybe   1    0.002846968   0.002846968
org-element-at-point                3    0.0028012790  0.0009337596
org-babel-where-is-src-block-head   1    0.002664822   0.002664822
org-element--cache-compare          303  0.0025883040  8.542...e-06
org-table-current-column            119  0.002235665   1.878...e-05
--8<---------------cut here---------------end--------------->8---

The table, for completeness, is here:

#+begin_src org
 | date             | TBD | Victoria | London Bridge | Blackfriars | City |
Farrindgon | St Pancras | Totals | Miles |
 |                  | 2.5 |        5 |           4.8 |         3.2 |  2.9 |
         5 |        1.6 |        |       |
 |------------------+-----+----------+---------------+-------------+------+------------+------------+--------+-------|
 | [2015-06-08 Mon] |   2 |          |               |             |    1 |
           |          1 |    9.5 |   5.9 |
 | [2015-06-12 Fri] |   2 |          |               |           1 |      |
           |          1 |    9.8 |   6.0 |
 | [2015-06-15 Mon] |   2 |          |             1 |             |      |
           |          1 |   11.4 |   7.0 |
 | [2015-06-17 Wed] |   2 |          |               |           1 |      |
           |          1 |    9.8 |   6.0 |
 | [2015-06-18 Thu] |   1 |          |               |           1 |      |
           |            |    5.7 |   3.5 |
 |------------------+-----+----------+---------------+-------------+------+------------+------------+--------+-------|
 | Totals           |   9 |        0 |             1 |           3 |    1 |
         0 |          4 |   46.2 |  28.5 |
 ,#+TBLFM: @>$2..@>$>>=vsum(@I..@II)::$9=($2..$>>>)*(@<<$2..@
<<$>>>);EN::$10=$9/1.62;%.1f
#+end_src

If I change, for instance, the entry in the TBD column for today from 1
to 2, in the original file, it takes 17 seconds.  If I do it in this
email buffer (changing mode to org etc.), it is essentially
instantaneous.

Large buffers seem to be causing problems with org.  I've noticed this
elsewhere as I do tend to work with org files that are often 0.25-1 MB
in size.  Having looked at the profiler output, my gut feeling was that
the buffer is being repeatedly parsed (or some similar activity) given
where the time is being spent.  So... as the table is currently 99% of
the way into the buffer, I have copied the table to the start of the
same large document and, lo and behold, the table recalculation on the
copy is instantaneous!

(the moral of the story, for me, may be to use a reverse date-tree
structure for my tasks, if such were possible... maybe it is, given the
hidden gems in org! ;-)

I would be happy to instrument more than just org, if it would help.  I
should add that the above profile was done using emacs -Q so no
customisations.

I have no real issue with the performance of org overall but I thought
I'd add a data point in case it helps.

thanks,
eric

-- 
: Eric S Fraga (0xFFFCF67D), Emacs 24.4.1, Org release_8.3beta-1216-gb856f6

[-- Attachment #2: Type: text/html, Size: 6016 bytes --]