From mboxrd@z Thu Jan 1 00:00:00 1970 From: Aaron Ecay Subject: Re: Discussion request: 15m tangle time, details follow Date: Tue, 17 Jun 2014 22:41:54 -0400 Message-ID: <87ppi76irx.fsf@gmail.com> References: Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" Return-path: Received: from eggs.gnu.org ([2001:4830:134:3::10]:50520) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Wx5pA-000688-JW for emacs-orgmode@gnu.org; Tue, 17 Jun 2014 22:42:14 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Wx5oz-0000un-PH for emacs-orgmode@gnu.org; Tue, 17 Jun 2014 22:42:08 -0400 Received: from mail-qa0-x22a.google.com ([2607:f8b0:400d:c00::22a]:46392) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Wx5oz-0000sZ-Ic for emacs-orgmode@gnu.org; Tue, 17 Jun 2014 22:41:57 -0400 Received: by mail-qa0-f42.google.com with SMTP id dc16so194048qab.1 for ; Tue, 17 Jun 2014 19:41:56 -0700 (PDT) In-Reply-To: List-Id: "General discussions about Org-mode." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: emacs-orgmode-bounces+geo-emacs-orgmode=m.gmane.org@gnu.org Sender: emacs-orgmode-bounces+geo-emacs-orgmode=m.gmane.org@gnu.org To: Grant Rettke , "emacs-orgmode@gnu.org" --=-=-= Content-Type: text/plain Hi Grant, 2014ko ekainak 17an, Grant Rettke-ek idatzi zuen: > > Good evening, > > Over the past few months I've been working on the same literate > document. It has been a learning > experience for me, trial and error has abounded. The key tenet that > I've adhered too though is to truly > embrace literate programming, and the more I learn the more it makes > sense. The document has > grown quite organically and it has been and continues to be a > wonderful experience. What I need > help, feedback, discussion, and more on is the build time. > > The average build takes 15m. Here you mean time to tangle, correct? (As opposed to exporting to HTML/LaTeX/etc.) I can confirm very long times to tangle a document with a structure like yours. I ran the emacs profiler while tangling the document for 30 secs, then interrupted with C-g and generated a report. That is attached. --=-=-= Content-Type: text/plain Content-Disposition: attachment; filename=profile.txt - ... 29140 96% - org-babel-expand-noweb-references 27746 92% - let* 27746 92% - let 27746 92% - save-current-buffer 27746 92% - unwind-protect 27746 92% - progn 27746 92% - while 27746 92% - funcall 27746 92% - save-current-buffer 27746 92% - save-restriction 27746 92% - mapconcat 27746 92% - split-string 27746 92% - if 27746 92% - or 27746 92% - let 27743 92% - save-excursion 27743 92% - if 27743 92% - let* 27743 92% - let 27743 92% - unwind-protect 27743 92% - progn 27743 92% - while 27743 92% - if 27696 92% - progn 27475 91% - let 27457 91% - let 27411 91% - org-babel-get-src-block-info 27218 90% - org-babel-parse-src-block-match 27093 90% - org-babel-params-from-properties 26595 88% - let 26595 88% - unwind-protect 26592 88% - progn 26585 88% - list 26585 88% - let 26218 87% - org-babel-parse-multiple-vars 26218 87% - delq 26212 87% - mapcar 26205 87% - org-babel-params-from-properties-inner1 26184 86% - let 26178 86% - and 26175 86% - setq 26152 86% - org-entry-get 26135 86% - let 26119 86% - save-excursion 26095 86% - save-excursion 26051 86% - if 26041 86% - org-entry-get-with-inheritance 25257 83% - byte-code 25179 83% - org-entry-get 20968 69% - let 20951 69% - save-excursion 20898 69% - save-excursion 20859 69% - if 20834 69% - if 20821 69% - save-excursion 20699 68% - save-restriction 20674 68% - let 20640 68% - org-get-property-block 18232 60% - byte-code 15555 51% + org-back-to-heading 2511 8% outline-next-heading 2105 6% org-before-first-heading-p 1764 5% + if 2325 7% + goto-char 3 0% + org-up-heading-safe 4078 13% + org-back-to-heading 8 0% + and 14 0% goto-char 3 0% if 6 0% cons 11 0% + mapcar 12 0% mapc 6 0% + if 198 0% + org-babel-parse-header-arguments 169 0% + apply 188 0% + byte-code 163 0% generate-new-buffer 61 0% + org-do-remove-indentation 29 0% + org-unescape-code-in-string 22 0% org-babel-where-is-src-block-head 15 0% last 3 0% + if 73 0% + org-babel-active-location-p 221 0% + save-excursion 3 0% Automatic GC 1394 4% + command-execute 900 2% + timer-event-handler 63 0% --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable I did two non-standard things to this profile. The first was: (setq profiler-report-cpu-line-format '((100 left) ;; The 100 above is increased from the default of 50 ;; to allow the deeply nested call tree to be seen (24 right ((19 right) (5 right))))) The second was to convert an anonymous lambda found in org-babel-params-from-properties into a named function, so that it would show up in the profiling results on its own line: (defun org-babel-params-from-properties-inner1 (header-arg) (let (val) (and (setq val (org-entry-get (point) header-arg t)) (cons (intern (concat ":" header-arg)) (org-babel-read val))))) The profile shows that most of the slowdown is in org-entry-get. Indeed, org-babel-params-from-properties calls this function ~30 times per source block. When called with the inherit arg set to t (as here), this function takes time (at least) proportional to the number of headings dominating the source block, which in your document can be up to 5. I think there are two problems here. The first is the situation where babel needs to fetch 30 properties per source block. Indeed, this is marked =E2=80=9Cdeprecated=E2=80=9D in the source, in favor of a system whe= re there is only one header arg. This has been marked deprecated for almost exactly a year in the code (Achim=E2=80=99s commit 90b16870 of 2013-06-23), but I d= on=E2=80=99t know of any prominent announcement of the deprecation. So I doubt the old slow code could be removed without breaking many people=E2=80=99s setup= s, although possibly a customization variable could be introduced to allow users to opt in to the new, faster system. You=E2=80=99d then have to upda= te your file: :PROPERTIES: :exports: none :tangle: no :END: becomes :PROPERTIES: :header-args: :exports none :tangle no :END: The new system is also a bit inferior, in that it doesn=E2=80=99t allow hea= der arg inheritance as easily. So with the one-prop-per-arg system the following works as expected: * foo :PROPERTIES: :exports: none :END: ** bar :PROPERTIES: :tangle: no :END: (src block here) On the other hand, in the new system there=E2=80=99s no way to specify some header args at foo and some at bar; the lowest header-args property wins. (At least as far as I can see) The second issue is that it=E2=80=99s desirable to memoize calls to org-entry-get. Probably the easiest way to do this is to use the org-element cache. Indeed, a quick and hacky test that I did seemed to confirm that this yields some speedup. There are conceptual issues though =E2=80=93 org-element forces all property keys to be uppercase, wher= eas org-entry-get (as near as I can tell...) follows the user=E2=80=99s customization of case-fold-search to determine its case sensitivity. So one has to think carefully about how a rewrite to use org-element might affect the case-sensitivity of the property API (although code relying on the API to be sensitive to case of property keys might be rare in practice). TL;DR: 1. I see the same slowness you report 2. It seems like an architectural issue rather than one of (mis)configuration 3. There are broad fixes available, but they require potentially compatibility-breaking changes to Org 4. (maybe with this analysis someone can come up with a more targeted fix for your use case) Hope this is helpful, --=20 Aaron Ecay --=-=-=--