Re: 22.1.50; insert-file-contents is slow under tramp

[Stephen Berman]

On Thu, 23 Aug 2007 19:49:39 +0200 martin rudalics <address@hidden> wrote:

>> It doesn't make a very big difference: it takes 17 seconds to open
>> ChangeLog.12 as opposed to 20 seconds without the patch.  (I assume I
>> did it right: applied the patch and ran make in emacs/src to rebuild
>> the emacs executable, without recompiling the lisp files.)
>
> I suppose you don't want to run insert-file-contents with gdb.

See below.

> Could you try to edebug format-decode and tell whether the 17 secs are
> spent before calling it, while running it, or after calling it.

The 17 seconds elapse before format-decode is called.

On Thu, 23 Aug 2007 22:25:15 +0200 martin rudalics <address@hidden> wrote:

>> I think this has nothing to do with it: Tramp implements insert-file-contents
>> in Elisp.
>
> I was puzzled because according to the OP
>
>>> ... the slowdown occurs when insert-file-contents is
>>> called in find-file-noselect-1.
>
> Stephen could you tell us how this relates to tramp.

Stefan is right, and I was wrong, but didn't see it until running
under gdb, as you suggested.  I set a breakpoint at fileio.c:3689 (the
beginning of the insert-file-contents DEFUN).  After going through the
tramp stuff and typing RET on ChangeLog.12, execution stopped at the
breakpoint:

Breakpoint 3, Finsert_file_contents (filename=142792571, visit=137492729,
    beg=137492681, end=137492681, replace=137492681) at fileio.c:3714
3714    {
(gdb) n
3720      int count = SPECPDL_INDEX ();
(gdb) n
3733      Lisp_Object old_Vdeactivate_mark = Vdeactivate_mark;
(gdb) n
3714    {
(gdb) n
3720      int count = SPECPDL_INDEX ();
(gdb) n
3736      if (current_buffer->base_buffer && ! NILP (visit))
(gdb) n
3720      int count = SPECPDL_INDEX ();
(gdb) n
3733      Lisp_Object old_Vdeactivate_mark = Vdeactivate_mark;
(gdb) n
3736      if (current_buffer->base_buffer && ! NILP (visit))
(gdb) n
3739      if (!NILP (current_buffer->read_only))
(gdb) n
3742      val = Qnil;
(gdb) n
3749      CHECK_STRING (filename);
(gdb) n
3742      val = Qnil;
(gdb) n
3749      CHECK_STRING (filename);
(gdb) n
3750      filename = Fexpand_file_name (filename, Qnil);
(gdb) n
3754      handler = Ffind_file_name_handler (filename, Qinsert_file_contents);
(gdb) n
3755      if (!NILP (handler))
(gdb) n
3754      handler = Ffind_file_name_handler (filename, Qinsert_file_contents);
(gdb) n
3755      if (!NILP (handler))
(gdb) n
3757          val = call6 (handler, Qinsert_file_contents, filename,
(gdb) n
Warning:
Cannot insert breakpoint -129.
Error accessing memory address 0x9317cb93: Input/output error.

Then I typed `c' and got the 17 second interval where emacs consumed
almost all the CPU, then the breakpoint stopped execution again and I
got the following backtrace:

#0  Finsert_file_contents (filename=143060787, visit=137492681, beg=137492681,
    end=137492681, replace=137492681) at fileio.c:3714
#1  0x0815eadf in Ffuncall (nargs=6, args=0xbfd47f60) at eval.c:3040
#2  0x0818992d in Fbyte_code (bytestr=139911115, vector=142565700,
    maxdepth=<value optimized out>) at bytecode.c:679
#3  0x0815e4fa in funcall_lambda (fun=142194052, nargs=5, arg_vector=0xbfd480a4)
    at eval.c:3213
#4  0x0815e901 in Ffuncall (nargs=6, args=0xbfd480a0) at eval.c:3083
#5  0x08160226 in Fapply (nargs=2, args=0xbfd48164) at eval.c:2514
#6  0x0815ec25 in Ffuncall (nargs=3, args=0xbfd48160) at eval.c:3007
#7  0x0818992d in Fbyte_code (bytestr=139908699, vector=142139364,
    maxdepth=<value optimized out>) at bytecode.c:679
#8  0x0815e4fa in funcall_lambda (fun=142170892, nargs=6, arg_vector=0xbfd48284)
    at eval.c:3213
#9  0x0815e901 in Ffuncall (nargs=7, args=0xbfd48280) at eval.c:3083
#10 0x08160226 in Fapply (nargs=3, args=0xbfd48344) at eval.c:2514
#11 0x0815ec25 in Ffuncall (nargs=4, args=0xbfd48340) at eval.c:3007
#12 0x0818992d in Fbyte_code (bytestr=139908827, vector=142220436,
    maxdepth=<value optimized out>) at bytecode.c:679
#13 0x0815e4fa in funcall_lambda (fun=142655764, nargs=6, arg_vector=0xbfd48464)
    at eval.c:3213
#14 0x0815e901 in Ffuncall (nargs=7, args=0xbfd48460) at eval.c:3083
#15 0x0815ec49 in call6 (fn=138355337, arg1=137611529, arg2=142719987,
    arg3=137492729, arg4=137492681, arg5=137492681, arg6=137492681) at 
eval.c:2931
#16 0x08129b28 in Finsert_file_contents (filename=142719987, visit=137492729,
    beg=137492681, end=137492681, replace=137492681) at fileio.c:3757
#17 0x0815eadf in Ffuncall (nargs=3, args=0xbfd5cbd0) at eval.c:3040
#18 0x0818992d in Fbyte_code (bytestr=136198155, vector=136198180,
    maxdepth=<value optimized out>) at bytecode.c:679
#19 0x0815dfb5 in Feval (form=136198141) at eval.c:2363
#20 0x0816063f in internal_lisp_condition_case (var=137492681, 
bodyform=136198141,
    handlers=136198213) at eval.c:1433
#21 0x08188c25 in Fbyte_code (bytestr=136197731, vector=136197748,
    maxdepth=<value optimized out>) at bytecode.c:869
#22 0x0815e4fa in funcall_lambda (fun=136197660, nargs=6, arg_vector=0xbfd5cef4)
    at eval.c:3213
#23 0x0815e901 in Ffuncall (nargs=7, args=0xbfd5cef0) at eval.c:3083
#24 0x0818992d in Fbyte_code (bytestr=136196795, vector=136196812,
    maxdepth=<value optimized out>) at bytecode.c:679
#25 0x0815e4fa in funcall_lambda (fun=136196724, nargs=4, arg_vector=0xbfd5d024)
    at eval.c:3213
#26 0x0815e901 in Ffuncall (nargs=5, args=0xbfd5d020) at eval.c:3083
#27 0x0818992d in Fbyte_code (bytestr=136192091, vector=136192108,
    maxdepth=<value optimized out>) at bytecode.c:679
#28 0x0815e4fa in funcall_lambda (fun=136192036, nargs=1, arg_vector=0xbfd5d154)
---Type <return> to continue, or q <return> to quit---
    at eval.c:3213
#29 0x0815e901 in Ffuncall (nargs=2, args=0xbfd5d150) at eval.c:3083
#30 0x0818992d in Fbyte_code (bytestr=139566787, vector=142412436,
    maxdepth=<value optimized out>) at bytecode.c:679
#31 0x0815e4fa in funcall_lambda (fun=142412572, nargs=0, arg_vector=0xbfd5d274)
    at eval.c:3213
#32 0x0815e901 in Ffuncall (nargs=1, args=0xbfd5d270) at eval.c:3083
#33 0x08160379 in apply1 (fn=142392345, arg=137492681) at eval.c:2767
#34 0x0815ba00 in Fcall_interactively (function=142392345, 
record_flag=137492681,
    keys=137533996) at callint.c:406
#35 0x080fac73 in Fcommand_execute (cmd=142392345, record_flag=137492681,
    keys=137492681, special=137492681) at keyboard.c:10119
#36 0x0810684b in command_loop_1 () at keyboard.c:1873
#37 0x0815d492 in internal_condition_case (bfun=0x81064d0 <command_loop_1>,
    handlers=137538137, hfun=0x8100e20 <cmd_error>) at eval.c:1488
#38 0x08100263 in command_loop_2 () at keyboard.c:1329
#39 0x0815d54a in internal_catch (tag=137531321, func=0x8100240 
<command_loop_2>,
    arg=137492681) at eval.c:1229
#40 0x08100c5c in command_loop () at keyboard.c:1308
#41 0x08100ffb in recursive_edit_1 () at keyboard.c:1006
#42 0x081010e6 in Frecursive_edit () at keyboard.c:1067
#43 0x080f6dd0 in main (argc=2, argv=0xbfd5db14) at emacs.c:1774

Lisp Backtrace:
"insert-file-contents" (0x886ef33)
"tramp-handle-insert-file-contents" (0x881bbf3)
"apply" (0x88013b9)
"tramp-sh-file-name-handler" (0x833c909)
"apply" (0x88014c1)
"tramp-file-name-handler" (0x833c909)
"insert-file-contents" (0x883cdfb)
"byte-code" (0x81e380b)
"find-file-noselect-1" (0x884a17c)
"find-file-noselect" (0x883ffab)
"find-file" (0x883ffab)
"dired-advertised-find-file" (0x831f8c9)
"call-interactively" (0x87cbc19)

So the slowdown is at insert-file-contents, but the invocation is from
tramp, which I did not see when using edebug before.  I tried
edebugging in tramp but could not get any further than
tramp-file-name-handler.  Hopefully someone else (Michael Albinus?)
can.

Steve Berman