bug#14518: C and Emacs Lisp code parts

[Eli Zaretskii]

[Please don't cross-post between the bug list and emacs-deve.]

> From: Andreas Röhler <andreas.roehler@online.de>
> Date: Wed, 6 Jul 2016 09:25:54 +0200
> Cc: Eli Zaretskii <eliz@gnu.org>
> 
> abbrev--describe               36050       15.224345396 0.0004223119
> abbrev-edit-save-buffer        1           8.034011581   8.034011581
> abbrev-edit-save-to-file       1           8.033998314   8.033998314
> abbrev--write                  18025       5.8414600190 0.0003240754
> define-abbrevs                 1           1.334075568   1.334075568
> abbrev-get                     107835      0.5151135200 4.776...e-06
> abbrev-table-get               36964       0.1173239610 3.174...e-06
> abbrev-table-put               18320       0.0690998279 3.771...e-06
> abbrev-table-empty-p           584         0.010703864 1.832...e-05
> abbrev-table-p                 584         0.0050513859 8.649...e-06
> abbreviate-file-name           91          0.002899625 3.186...e-05
> abbrev-table-name              2           0.000254252   0.000127126
> abbrev-mode                    1           1.4463e-05    1.4463e-05

Thanks.

It is better to use profiler.el, because it doesn't change the code
being profiled, and also can profile primitives.  If you can produce a
profile using profiler.el, and present it in fully expanded form,
please do.

Also, I'm not sure how to read the above (and the elp documentation
doesn't really help).  What was the total elapsed time it took to run
this scenario?  Is it the sum of all the numbers in the first column,
i.e. about 37 sec?  Or does the elapsed time for each function include
all of its callers?  Either way, the numbers look strange: why did it
take abbrev-edit-save-to-file, whose body is almost empty, 8 sec,
whereas abbrev--describe took 15 sec?  What am I missing?

Anyway, I looked at the v22 C implementation of the relevant
functions, and I see that the Lisp implementation is essentially
identical to C.  For example, here's the Lisp implementation of
abbrev--describe:

  (defun abbrev--describe (sym)
    (when (symbol-value sym)
      (prin1 (symbol-name sym))
      (if (null (abbrev-get sym :system))
          (indent-to 15 1)
        (insert " (sys)")
        (indent-to 20 1))
      (prin1 (abbrev-get sym :count))
      (indent-to 20 1)
      (prin1 (symbol-value sym))
      (when (symbol-function sym)
        (indent-to 45 1)
        (prin1 (symbol-function sym)))
      (terpri)))

and here's what we had in Emacs 22:

  static void
  describe_abbrev (sym, stream)
       Lisp_Object sym, stream;
  {
    Lisp_Object one, count, system_flag;

    if (INTEGERP (XSYMBOL (sym)->plist))
      {
        count = XSYMBOL (sym)->plist;
        system_flag = Qnil;
      }
    else
      {
        count = Fget (sym, Qcount);
        system_flag = Fget (sym, Qsystem_type);
      }

    if (NILP (SYMBOL_VALUE (sym)))
      return;

    one = make_number (1);
    Fprin1 (Fsymbol_name (sym), stream);

    if (!NILP (system_flag))
      {
        insert_string (" (sys)");
        Findent_to (make_number (20), one);
      }
    else
      Findent_to (make_number (15), one);

    Fprin1 (count, stream);
    Findent_to (make_number (20), one);
    Fprin1 (SYMBOL_VALUE (sym), stream);
    if (!NILP (XSYMBOL (sym)->function))
      {
        Findent_to (make_number (45), one);
        Fprin1 (XSYMBOL (sym)->function, stream);
      }
    Fterpri (stream);
  }

As you see, both versions call the same primitives and do little
else.

I see the same basic picture with all the functions which are hot
spots according to the elp profile.  So if indeed the Lisp version is
significantly slower, the only way I can explain that is that we have
some very basic inefficiency in the byte-code interpreter, something
that, if true, is completely unrelated to abbrev.el itself.

So please do the same as you did here with Emacs 22.3, and with the
same abbrevs list, and tell how much elapsed time this takes on the
same system.  We should anyway analyze this comparatively, not in
absolute terms.  (Alternatively, post here the list of the abbrevs you
used in your experiment, then others could do these measurements,
compare them, and maybe provide more information/investigate deeper.)

Thanks.