Painfully Slow Export

Painfully Slow Export

[Ken Mankoff]

I'm trying to export a file to LaTeX. It takes about one minute. The
file is 12000 lines long and has 200 code blocks. I have set:

#+PROPERTY: header-args :eval never-export

which means, I think, no babel blocks should evaluate.

(setq org-export-use-babel t) seems to be the culprit. If I set it to nil then export is sub-second.

However, I would like some #+RESULTS: blocks to export (w/o eval). This requires o-e-o-b t.

Is there a way to speed up exporting?

Thanks,

  -k.

Re: Painfully Slow Export

[Chris]

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

Hello, Ken!

Ken Mankoff (mankoff@gmail.com) 2018-06-12:
> Is there a way to speed up exporting?

I may be jumping to conclusions here, and if so, please excuse me. Have
you tried profiling the export? (As in M-x profiler-start, run the
export, then M-x profiler-report?) This can shed a surprising amount of
light on why things are slow. (In my case, exporting was slow because of
a slow hook that got triggered multiple times during the exportage.)

Regards,
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 227 bytes --]

Re: Painfully Slow Export

[Ken Mankoff]

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

Hi Chris,

Thanks for the hint. I didn't think to profile. This may be useful, but I'm
not sure how to interpret the results, which are:

- command-execute                                               15852  79%
 - call-interactively                                           15852  79%
  - funcall-interactively                                       15666  78%
   - org-export-dispatch                                        15392  77%
    - org-latex-export-to-latex                                 15291  76%
     - org-export-to-file                                       15289  76%
      - org-export-as                                           15245  76%
       - org-babel-exp-process-buffer                           14762  74%
        - org-babel-exp-src-block                               14676  73%
         - org-babel-exp-do-export                              10049  50%
          - org-babel-exp-results                                9324  46%
           - org-babel-expand-noweb-references                   9200  46%
            - org-babel-get-src-block-info                       8247  41%
             - org-babel-params-from-properties                  6799  34%
              - org-entry-get                                    6618  33%
               - org-entry-get-with-inheritance                  6579  33%
                - org-up-heading-safe                            5466  27%



On Tue, Jun 12, 2018 at 5:09 PM Chris <a@xkqr.org> wrote:

> Hello, Ken!
>
> Ken Mankoff (mankoff@gmail.com) 2018-06-12:
> > Is there a way to speed up exporting?
>
> I may be jumping to conclusions here, and if so, please excuse me. Have
> you tried profiling the export? (As in M-x profiler-start, run the
> export, then M-x profiler-report?) This can shed a surprising amount of
> light on why things are slow. (In my case, exporting was slow because of
> a slow hook that got triggered multiple times during the exportage.)
>
> Regards,
> Chris
>

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

Re: Painfully Slow Export

[Berry, Charles]

> On Jun 12, 2018, at 7:01 AM, Ken Mankoff <mankoff@gmail.com> wrote:
> 
> I'm trying to export a file to LaTeX. It takes about one minute. The
> file is 12000 lines long and has 200 code blocks. I have set:
> 
> #+PROPERTY: header-args :eval never-export
> 

That is the right idiom.  Of course, you have to refresh the local setup after typing that (C-c C-c with point in the PROPERTY line) or it will have no effect until you save and re-open the file.

It is good to check that you have refreshed and that there are no typos or hidden chars in the line, so go to a src block and type

C-c C-v C-i

and verify that you see something like this

,----
| Lang: R
| Properties:
| 	:header-args 	:eval never-export
| 	:header-args:R 	nil
| Header Arguments:
| 	:cache		no
| 	:eval		never-export
| 	:exports	code
| 	:hlines		no
| 	:noweb		no
| 	:results	replace
| 	:session	none
| 	:tangle		no
`----

You should see both the :header-args line as you typed it and the :eval line showing never-export.

> which means, I think, no babel blocks should evaluate.
> 
> (setq org-export-use-babel t) seems to be the culprit. 

Leave it set to `t'.

Chuck

Re: Painfully Slow Export

[Ken Mankoff]

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

Hi Chuck,

It looks fine to me. I see:

Name: fig:foo
Lang: python
Properties:
:header-args :eval never-export
:header-args:python nil
Header Arguments:
:cache no
:eval never-export
:exports results
:hlines no
:noweb yes
:results file replace
:session discharge_ts
:tangle no


  -k.


On Tue, Jun 12, 2018 at 5:51 PM Berry, Charles <ccberry@ucsd.edu> wrote:

>
>
> > On Jun 12, 2018, at 7:01 AM, Ken Mankoff <mankoff@gmail.com> wrote:
> >
> > I'm trying to export a file to LaTeX. It takes about one minute. The
> > file is 12000 lines long and has 200 code blocks. I have set:
> >
> > #+PROPERTY: header-args :eval never-export
> >
>
> That is the right idiom.  Of course, you have to refresh the local setup
> after typing that (C-c C-c with point in the PROPERTY line) or it will have
> no effect until you save and re-open the file.
>
> It is good to check that you have refreshed and that there are no typos or
> hidden chars in the line, so go to a src block and type
>
> C-c C-v C-i
>
> and verify that you see something like this
>
> ,----
> | Lang: R
> | Properties:
> |       :header-args    :eval never-export
> |       :header-args:R  nil
> | Header Arguments:
> |       :cache          no
> |       :eval           never-export
> |       :exports        code
> |       :hlines         no
> |       :noweb          no
> |       :results        replace
> |       :session        none
> |       :tangle         no
> `----
>
> You should see both the :header-args line as you typed it and the :eval
> line showing never-export.
>
> > which means, I think, no babel blocks should evaluate.
> >
> > (setq org-export-use-babel t) seems to be the culprit.
>
> Leave it set to `t'.
>
> Chuck
>
>
>
>

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

Re: Painfully Slow Export

[Berry, Charles]

> On Jun 12, 2018, at 12:41 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> 
> Hi Chuck,
> 
> It looks fine to me. I see:
> 
> Name: fig:foo
> Lang: python
> Properties:
> 	:header-args 	:eval never-export
> 	:header-args:python 	nil
> Header Arguments:
> 	:cache		no
> 	:eval		never-export
> 	:exports	results
> 	:hlines		no
> 	:noweb		yes
> 	:results	file replace
> 	:session	discharge_ts
> 	:tangle		no
> 
>  

And still the src blocks execute?

Try this. Use the following in an org buffer:


--8<---------------cut here---------------start------------->8---
#+PROPERTY: header-args :eval never-export

#+begin_src emacs-lisp :exports results
"BBB"
#+end_src

#+RESULTS:
: AA

--8<---------------cut here---------------end--------------->8---

C-c C-c on the PROPERTY line and confirm as above that the header-args are rightly set.

Then `C-c C-e C-b t A' should give a buffer like this:

--8<---------------cut here---------------start------------->8---
,----
| AA
`----
--8<---------------cut here---------------end--------------->8---

Which you can see implies that the src-block did not run, but the results were properly exported.

This works for me on a brand new copy of master (9.1.13).

If it fails for you, then you need to check your org setup.

If it succeeds, but exporting your file still fails then there has to be something amiss in your file. I'd instrument `org-babel-execute-src-block' and see what the line with `(org-babel-check-evaluate info)' returns. It should be `nil'. If not you need to see what is in `info'.

HTH,

Chuck 

Re: Painfully Slow Export

[Ken Mankoff]

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

On Tue, Jun 12, 2018 at 11:07 PM Berry, Charles <ccberry@ucsd.edu> wrote:

>
> > On Jun 12, 2018, at 12:41 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> >
> > Hi Chuck,
> >
> > It looks fine to me. I see:
> >
> > Name: fig:foo
> > Lang: python
> > Properties:
> >       :header-args    :eval never-export
> >       :header-args:python     nil
> > Header Arguments:
> >       :cache          no
> >       :eval           never-export
> >       :exports        results
> >       :hlines         no
> >       :noweb          yes
> >       :results        file replace
> >       :session        discharge_ts
> >       :tangle         no
> >
> >
>
> And still the src blocks execute?
>
>
No. The source blocks never execute. It just takes an entire minute to
export the file with 200 source blocks. If they executed it would probably
take a few hours.

   -k.

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

Re: Painfully Slow Export

[Ken Mankoff]

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

As an MWE, I can test with "emacs -Q" and the following org file:








#+PROPERTY: header-args :eval never-export
# (setq org-export-use-babel t)

#+BEGIN_SRC emacs-lisp :results none
(org-babel-do-load-languages
 'org-babel-load-languages
 '((shell . t)))
#+END_SRC

#+BEGIN_SRC sh :results org raw
for i in $(seq 200); do
echo ""
echo "#+BEGIN_SRC sh :results output :exports results"
echo "echo 'hello, world'"
echo "#+END_SRC"
echo "#+RESULTS:"
echo ": goodbye"
done
#+END_SRC
#+RESULTS:



Execute the first code block to allow execution of the second. Execute the
second code block to generate 200 more. Export. It takes ~6 seconds on my
machine, which seems long but is bearable. Based on the profiling, I think
the reason it takes 1 minute is because the code blocks use <<noweb>>
blocks?. I can verify this with the following MWE:


#+PROPERTY: header-args :eval never-export
# (setq org-export-use-babel t)

#+NAME: foo
#+BEGIN_SRC sh :results verbatim
ls
#+END_SRC
#+RESULTS:

#+NAME: bar
#+BEGIN_SRC sh :results verbatim :noweb yes
<<foo>>
#+END_SRC
#+RESULTS:

#+NAME: baz
#+BEGIN_SRC sh :results verbatim :noweb yes
<<bar>>
#+END_SRC
#+RESULTS:

Repeat the BAZ block with the <<bar>> about 100 times and export this, and
it takes a long time. I killed it after ~30 seconds, because I think I have
my evidence that :noweb yes is the culprit for the slow export.



On Tue, Jun 12, 2018 at 11:15 PM Ken Mankoff <mankoff@gmail.com> wrote:

>
> On Tue, Jun 12, 2018 at 11:07 PM Berry, Charles <ccberry@ucsd.edu> wrote:
>
>>
>> > On Jun 12, 2018, at 12:41 PM, Ken Mankoff <mankoff@gmail.com> wrote:
>> >
>> > Hi Chuck,
>> >
>> > It looks fine to me. I see:
>> >
>> > Name: fig:foo
>> > Lang: python
>> > Properties:
>> >       :header-args    :eval never-export
>> >       :header-args:python     nil
>> > Header Arguments:
>> >       :cache          no
>> >       :eval           never-export
>> >       :exports        results
>> >       :hlines         no
>> >       :noweb          yes
>> >       :results        file replace
>> >       :session        discharge_ts
>> >       :tangle         no
>> >
>> >
>>
>> And still the src blocks execute?
>>
>>
> No. The source blocks never execute. It just takes an entire minute to
> export the file with 200 source blocks. If they executed it would probably
> take a few hours.
>
>    -k.
>

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

Re: Painfully Slow Export

[Berry, Charles]

> On Jun 12, 2018, at 2:30 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> 
> Based on the profiling, I think the reason it takes 1 minute is because the code blocks use <<noweb>> blocks?


I do not see this.

It takes a bit longer to run the noweb example you gave with 200 `baz' src blocks, but nothing crazy - like 10 seconds versus 5 for your other example. I used `C-c C-e l L' for each.

And the profiler gives `org-babel-expand-noweb-references' about 2% of the total.

You are using a recent version of org, right?
            

Chuck

Re: Painfully Slow Export

[Ken Mankoff]

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

On Wed, Jun 13, 2018 at 12:12 AM Berry, Charles <ccberry@ucsd.edu> wrote:

> > On Jun 12, 2018, at 2:30 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> >
> > Based on the profiling, I think the reason it takes 1 minute is because
> the code blocks use <<noweb>> blocks?
>
> I do not see this.
>
> It takes a bit longer to run the noweb example you gave with 200 `baz' src
> blocks, but nothing crazy - like 10 seconds versus 5 for your other
> example. I used `C-c C-e l L' for each.
>
> And the profiler gives `org-babel-expand-noweb-references' about 2% of the
> total.
>
> You are using a recent version of org, right?
>

Yes: 9.1.13-elpa or org-20180604.
Emacs-mac 26.1 port on OSX from Macports.
Or Emacs 25.3 downloaded from https://emacsformacosx.com/builds

Are you sure you hd 200 baz blocks? I'm not actually able to test with that
many. 10 takes 1 second. 20 takes 10 seconds. 30 takes 30 seconds. It seems
to grow exponentially. I don't have the patience to debug how long 100
takes.

   -k.

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

Re: Painfully Slow Export

[Berry, Charles]

> On Jun 12, 2018, at 10:32 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> 
> 
> 
> On Wed, Jun 13, 2018 at 12:12 AM Berry, Charles <ccberry@ucsd.edu> wrote:
> > On Jun 12, 2018, at 2:30 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> > 
> > Based on the profiling, I think the reason it takes 1 minute is because the code blocks use <<noweb>> blocks?
> 
> I do not see this.
> 
> It takes a bit longer to run the noweb example you gave with 200 `baz' src blocks, but nothing crazy - like 10 seconds versus 5 for your other example. I used `C-c C-e l L' for each.
> 
> And the profiler gives `org-babel-expand-noweb-references' about 2% of the total.
> 
> You are using a recent version of org, right?
>  
> Yes: 9.1.13-elpa or org-20180604.
> Emacs-mac 26.1 port on OSX from Macports.
> Or Emacs 25.3 downloaded from https://emacsformacosx.com/builds
> 
> Are you sure you hd 200 baz blocks? I'm not actually able to test with that many. 10 takes 1 second. 20 takes 10 seconds. 30 takes 30 seconds. It seems to grow exponentially. I don't have the patience to debug how long 100 takes.

So here it is again - using your ECM. 

Use this block to record the timing and count the number of named src blocks:

#+begin_src emacs-lisp :eval never-export
  (let ((sb (length (org-babel-src-block-names)))
	(st-time (time-to-seconds (get-internal-run-time))))
    (org-latex-export-as-latex)
    (format
     "# of src block names: %d\n Number of Seconds: %10.4f"
     sb  (-
	  (time-to-seconds (get-internal-run-time))
	  st-time)))
#+end_src

Now run it, add more src blocks after each run, and paste the results elsewhere (argh! I should have used `:results append'):

#+RESULTS:
: # of src block names: 3
:  Number of Seconds:     0.0498


#+RESULTS:
: # of src block names: 68
:  Number of Seconds:     2.1021

#+RESULTS:
: # of src block names: 200
:  Number of Seconds:    15.4018


#+RESULTS:
: # of src block names: 266
:  Number of Seconds:    26.6689

#+RESULTS:
: # of src block names: 332
:  Number of Seconds:    41.2211


So my mental count of 10 seconds for 200 blocks was a bit off.

And the time is very nearly quadratic in the number of named src blocks:

#+begin_src R :results output

  x <- c(3, 68, 200, 266, 332)
  y <- c(0.0498, 2.10, 15.40, 26.67, 41.22)
  fit <- lm(y ~ x + I( x^2 ))
  summary(fit)

#+end_src

#+RESULTS:
#+begin_example

Call:
lm(formula = y ~ x + I(x^2))

Residuals:
       1        2        3        4        5 
-0.02650  0.04187  0.01194 -0.05929  0.03197 

Coefficients:
             Estimate Std. Error t value Pr(>|t|)    
(Intercept) 5.783e-02  5.584e-02   1.036   0.4092    
x           5.083e-03  8.755e-04   5.805   0.0284 *  
I(x^2)      3.578e-04  2.579e-06 138.762 5.19e-05 ***
---
Signif. codes:  0 ‘***’ 0.001 ‘**’ 0.01 ‘*’ 0.05 ‘.’ 0.1 ‘ ’ 1

Residual standard error: 0.05973 on 2 degrees of freedom
Multiple R-squared:      1,	Adjusted R-squared:      1 
F-statistic: 1.67e+05 on 2 and 2 DF,  p-value: 5.986e-06

#+end_example

This is on my late-2012 MacBook Pro. MacOS 10.13.5, Emacs 25.3.1, org 9.1.13. So this sounds almost exactly like your setup.

Maybe time to try a minimal init file to see if something you have customized is bogging things down. 

HTH,

Chuck

Re: Painfully Slow Export

[Ken Mankoff]

Hi Chuck,

Thanks for your continued help and interest in this issue.

Here are the results from the timing test using your code:

| # Blocks | w/o noweb | noweb | NESTED  noweb |
|----------+-----------+-------+---------------|
|        3 |      0.05 |       |          0.33 |
|       13 |     0.155 |   1.9 |          3.76 |
|       23 |      0.27 |   6.8 |         16.95 |
|       33 |      0.40 |  16.8 |         37.96 |
|       43 |      0.62 |       |         81.92 |
|      143 |      4.06 |       |               |


On 2018-06-13 at 19:55 +02, Berry, Charles <ccberry@ucsd.edu> wrote:
> This is on my late-2012 MacBook Pro. MacOS 10.13.5, Emacs 25.3.1, org
> 9.1.13. So this sounds almost exactly like your setup.

I'm on a 2014 MBP, 10.12.6, same Emacs and Org, and 16 GB RAM.

> Maybe time to try a minimal init file to see if something you have
> customized is bogging things down.

I've been doing this in "Emacs -Q" the whole time.

I'm not sure why this works on your system and not mine, but this is my first foray into noweb. I'll return to my old methods for now, or at least separate the code and text I'm about to begin writing into separate Org docs so that the text export is not impacted by this issue.

  -k.

Re: Painfully Slow Export

[Ken Mankoff]

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

On Wed, Jun 13, 2018 at 7:56 PM Berry, Charles <ccberry@ucsd.edu> wrote:

> #+RESULTS:
> : # of src block names: 3
> :  Number of Seconds:     0.0498
>
>
> #+RESULTS:
> : # of src block names: 68
> :  Number of Seconds:     2.1021
>
> #+RESULTS:
> : # of src block names: 200
> :  Number of Seconds:    15.4018
>
>
> #+RESULTS:
> : # of src block names: 266
> :  Number of Seconds:    26.6689
>
> #+RESULTS:
> : # of src block names: 332
> :  Number of Seconds:    41.2211
>
> So my mental count of 10 seconds for 200 blocks was a bit off.
>
> And the time is very nearly quadratic in the number of named src blocks:
>
>

One more thought - even if your system is significantly faster for some
unknown reason - why is export taking ~15 seconds for 200 blocks *when you
aren't exporting any of the code*.
 Why is <<noweb>> expansion occurring if ":eval never-export" is set? There
seems to be something inefficient going on here.

   -k.

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

BUG? WAS: Re: Painfully Slow Export

[Berry, Charles]

tl;dr: `:exports results :noweb no-export :eval never-export' needlessly expands <<noweb>> code causing massive slowdowns on export. 

> On Jun 13, 2018, at 9:42 PM, Ken Mankoff <mankoff@gmail.com> wrote:
> 
> One more thought - even if your system is significantly faster for some unknown reason - why is export taking ~15 seconds for 200 blocks *when you aren't exporting any of the code*. 
>  Why is <<noweb>> expansion occurring if ":eval never-export" is set? There seems to be something inefficient going on here.
> 
>   

Using your ECM, C-c C-v C-i on your `baz' block. Note `:exports code'

,----
| Name: baz
| Lang: sh
| Properties:
| 	:header-args 	:eval never-export
| 	:header-args:sh 	nil
| Header Arguments:
| 	:cache		no
| 	:eval		never-export
| 	:exports	code
| 	:hlines		no
| 	:noweb		yes
| 	:results	verbatim replace
| 	:session	none
| 	:tangle		no
`----

Setting `:exports none' speeds things up a bit more. 

Looking back at your earlier posts, I see that you had `:exports results' for your python block but not in your ECM. i.e. you need these header args:

#+PROPERTY: header-args :eval never-export :exports results :noweb no-export

to show how bad things can be in your ECM.

The `:exports results'  will *really* slow things down. And this *may* be considered a bug. Babel isn't quite smart enough to sort out that you want results, but do not need to eval the src block nor check the hash in `org-babel-sha1-hash'.

Making matters a bit more complicated, I'd have thought that this

	:noweb (if org-export-current-backend "no" "yes")

would be enough to fix things, but it fails on recursive noweb expansions if you try to execute a src block interactively. And maybe that is a bug, too. 

HTH,

Chuck

Re: BUG? WAS: Re: Painfully Slow Export

[Nicolas Goaziou]

Hello,

"Berry, Charles" <ccberry@ucsd.edu> writes:

> tl;dr: `:exports results :noweb no-export :eval never-export' needlessly expands <<noweb>> code causing massive slowdowns on export. 

I think this is now fixed.

Thank you.

Regards,

-- 
Nicolas Goaziou

Re: BUG? WAS: Re: Painfully Slow Export

[Berry, Charles]

> On Jun 23, 2018, at 2:06 PM, Nicolas Goaziou <mail@nicolasgoaziou.fr> wrote:
> 
> Hello,
> 
> "Berry, Charles" <ccberry@ucsd.edu> writes:
> 
>> tl;dr: `:exports results :noweb no-export :eval never-export' needlessly expands <<noweb>> code causing massive slowdowns on export. 
> 
> I think this is now fixed.

I think so, too.

Thanks,

Chuck

Re: BUG? WAS: Re: Painfully Slow Export

[Ken Mankoff]

Hello,

I was waiting for Org to update in elpa. This appears fixed. Thank you
Charles for helping define the problem better.

  -k.

On 6/24/18, Berry, Charles <ccberry@ucsd.edu> wrote:
>
>
>> On Jun 23, 2018, at 2:06 PM, Nicolas Goaziou <mail@nicolasgoaziou.fr>
>> wrote:
>>
>> Hello,
>>
>> "Berry, Charles" <ccberry@ucsd.edu> writes:
>>
>>> tl;dr: `:exports results :noweb no-export :eval never-export' needlessly
>>> expands <<noweb>> code causing massive slowdowns on export.
>>
>> I think this is now fixed.
>
> I think so, too.
>
> Thanks,
>
> Chuck
>