Re: Emacs uses 100% cpu time

[Tassilo Horn]

Richard Stallman <address@hidden> writes:

Hello Richard,

> The way to find out where a program is running during a long operation
> is to stop the program several times, making a backtrace each time.
> When you see a pattern start to emerge, then please report it.

Ok, all backtraces have this bottom part, although the arguments may
vary a bit:

#32 0x0818b2e8 in wait_reading_process_output (time_limit=30, microsecs=0,
    read_kbd=-1, do_display=1, wait_for_cell=137459913, wait_proc=0x0,
    just_wait_proc=0) at process.c:4343
#33 0x08056488 in sit_for (timeout=240, reading=1, do_display=1)
    at dispnew.c:6548
#34 0x080ff846 in read_char (commandflag=1, nmaps=4, maps=0xbf806180,
    prev_event=137459913, used_mouse_menu=0xbf806228, end_time=0x0)
---Type <return> to continue, or q <return> to quit---
    at keyboard.c:2865
#35 0x081016e2 in read_key_sequence (keybuf=0xbf8062d4, bufsize=30,
    prompt=137459913, dont_downcase_last=0, can_return_switch_frame=1,
    fix_current_buffer=1) at keyboard.c:8956
#36 0x08103195 in command_loop_1 () at keyboard.c:1601
#37 0x08158e5b in internal_condition_case (bfun=0x8103000 <command_loop_1>,
    handlers=137504617, hfun=0x80fda50 <cmd_error>) at eval.c:1477
#38 0x080fce2e in command_loop_2 () at keyboard.c:1326
#39 0x08158f1c in internal_catch (tag=137500825,
    func=0x80fce00 <command_loop_2>, arg=137459913) at eval.c:1218
#40 0x080fd89e in command_loop () at keyboard.c:1305
#41 0x080fdc28 in recursive_edit_1 () at keyboard.c:1003
#42 0x080fdd16 in Frecursive_edit () at keyboard.c:1064
#43 0x080f3dd2 in main (argc=Cannot access memory at address 0x4
) at emacs.c:1794

Above this part, there's nothing all backtraces have in common.

> If the pattern you see involves lots of calls to Ffuncall, that means
> it is running Lisp code.  In that case only, you need to use
> `xbacktrace' in order to look at the Lisp-level backtrace.

I have made several backtraces without calls to Ffuncall at all.

> Once you see the pattern, you should follow the instructions in
> etc/DEBUG to figure out which of the frames is actually looping.

According point "** If the symptom of the bug is that Emacs fails to
respond" I stopped emacs with C-z in the terminal GDB is running in and
typed finish till the call didn't return anymore. That was in
wait_reading_process_output. So I pressed C-z again and stepped through
that frame with next:

(gdb) finish
Run till exit from #0  0x0818b2e8 in wait_reading_process_output (
    time_limit=30, microsecs=0, read_kbd=-1, do_display=1,
    wait_for_cell=137459913, wait_proc=0x0, just_wait_proc=0) at process.c:4343

Program received signal SIGTSTP, Stopped (user).
0x08141c3c in mark_object (arg=151918113) at alloc.c:5447
5447    {
(gdb) next

Program received signal SIGTSTP, Stopped (user).
0x08141c3c in mark_object (arg=151918113) at alloc.c:5447
5447    {
(gdb) next
5457      if (PURE_POINTER_P (XPNTR (obj)))
(gdb) next
5460      last_marked[last_marked_index++] = obj;
(gdb) next
5461      if (last_marked_index == LAST_MARKED_SIZE)
(gdb) next
5460      last_marked[last_marked_index++] = obj;
(gdb) next
5461      if (last_marked_index == LAST_MARKED_SIZE)
(gdb) next
5503      switch (SWITCH_ENUM_CAST (XGCTYPE (obj)))
(gdb) next
5700            register struct Lisp_Symbol *ptr = XSYMBOL (obj);
(gdb) next
5703            if (ptr->gcmarkbit) break;
(gdb) next
5842    }
(gdb) next
mark_object (arg=153342668) at alloc.c:5693
5693              for (i = 0; i < size; i++) /* and then mark its elements */
(gdb) next
5694                mark_object (ptr->contents[i]);
(gdb) next
5693              for (i = 0; i < size; i++) /* and then mark its elements */
(gdb) next
5694                mark_object (ptr->contents[i]);
[...]

It seems I could do this ad infimum...

Then I continued and stopped emacs again. It didn't finish the same
frame as before, but seemes to be stuck in another loop:

(gdb)
5964              if (!CONS_MARKED_P (&cblk->conses[i]))
(gdb)
5976                  CONS_UNMARK (&cblk->conses[i]);
(gdb)
5963            for (i = 0; i < lim; i++)
(gdb)
5976                  CONS_UNMARK (&cblk->conses[i]);
(gdb)
5975                  num_used++;
(gdb)
5963            for (i = 0; i < lim; i++)
(gdb)
5976                  CONS_UNMARK (&cblk->conses[i]);
(gdb)
5963            for (i = 0; i < lim; i++)
(gdb)
5964              if (!CONS_MARKED_P (&cblk->conses[i]))
(gdb)
5976                  CONS_UNMARK (&cblk->conses[i]);
(gdb)
5963            for (i = 0; i < lim; i++)
(gdb)
5976                  CONS_UNMARK (&cblk->conses[i]);
(gdb)
5975                  num_used++;
(gdb)

> Of course, if people think this is a bug that is already fixed, it is
> worth checking that first before you spend the time to do the
> debugging described above.

My checkout is one day old now, so it may be related but definitely not
fixed.

Bye,
Tassilo