bug#44326: 27.1.50; busy loop in lisp_free_align

[Aaron Jensen]

Some more information that is hopefully helpful.

My Emacs memory usage is currently around 2.5GB.

Lisp Stack trace from busy loop:

(unsigned char *) $2 = 0x00000001003f48c6 “timer-event-handler”
(unsigned char *) $3 = 0x00000001003f074c “apply”
(unsigned char *) $4 = 0x00000001191ba690 “gcmh-idle-garbage-collect”
(unsigned char *) $5 = 0x00000001003ee2fe “garbage-collect”

GC Stats during busy loop. These don't seem to increase, it stays busy
in lisp_align_free, though with different blocks over time.

(lldb) p num_used
(object_ct) $8 = 2924
(lldb) p num_free
(object_ct) $9 = 13506

Here is a macOS sample from activity monitor:

Physical footprint:         2.5G
Physical footprint (peak):  3.2G
----

Call graph:
    2102 Thread_6786366   DispatchQueue_1: com.apple.main-thread  (serial)
    + 2102 start  (in libdyld.dylib) + 1  [0x7fff6a33dcc9]
    +   2102 main  (in emacs) + 6980  [0x100161764]  emacs.c:2066
    +     2102 Frecursive_edit  (in emacs) + 313  [0x100164299]  keyboard.c:786
    +       2102 recursive_edit_1  (in emacs) + 192  [0x100163f50]
keyboard.c:714
    +         2102 command_loop  (in emacs) + 202  [0x1001640ca]
keyboard.c:1070
    +           2102 internal_catch  (in emacs) + 74  [0x1002614ba]  eval.c:1117
    +             2102 command_loop_2  (in emacs) + 44  [0x10017ce8c]
keyboard.c:1091
    +               2102 internal_condition_case  (in emacs) + 127
[0x100261b4f]  eval.c:1356
    +                 2102 command_loop_1  (in emacs) + 1449
[0x100165139]  keyboard.c:1350
    +                   2102 read_key_sequence  (in emacs) + 1897
[0x100166719]  keyboard.c:9554
    +                     2102 read_char  (in emacs) + 5298
[0x10016b5e2]  keyboard.c:2738
    +                       2102 sit_for  (in emacs) + 750
[0x100008f8e]  dispnew.c:6056
    +                         2102 wait_reading_process_output  (in
emacs) + 5631  [0x1002edbaf]  process.c:5707
    +                           2102 detect_input_pending_run_timers
(in emacs) + 54  [0x10016d056]  keyboard.c:10368
    +                             2102 get_input_pending  (in emacs) +
64  [0x100170960]  keyboard.c:6807
    +                               2102 readable_events  (in emacs) +
31  [0x10016e44f]  keyboard.c:3397
    +                                 2102 timer_check  (in emacs) +
168  [0x100170aa8]  keyboard.c:4398
    +                                   2102 timer_check_2  (in emacs)
+ 1695  [0x1001711bf]  keyboard.c:4336
    +                                     2102 call1  (in emacs) + 63
[0x100268d2f]  eval.c:2655
    +                                       2102 Ffuncall  (in emacs)
+ 542  [0x10026824e]  eval.c:2797
    +                                         2102 funcall_lambda  (in
emacs) + 508  [0x10026985c]  eval.c:2990
    +                                           2102 exec_byte_code
(in emacs) + 8766  [0x1002d951e]  bytecode.c:633
    +                                             2102 Ffuncall  (in
emacs) + 468  [0x100268204]  eval.c:2795
    +                                               2102 funcall_subr
(in emacs) + 267  [0x10026930b]  eval.c:2848
    +                                                 2102 Fapply  (in
emacs) + 138  [0x1002649ca]  eval.c:2378
    +                                                   2102 Ffuncall
(in emacs) + 542  [0x10026824e]  eval.c:2797
    +                                                     2102
funcall_lambda  (in emacs) + 508  [0x10026985c]  eval.c:2990
    +                                                       2102
exec_byte_code  (in emacs) + 8766  [0x1002d951e]  bytecode.c:633
    +                                                         2102
Ffuncall  (in emacs) + 468  [0x100268204]  eval.c:2795
    +                                                           2102
funcall_subr  (in emacs) + 454  [0x1002693c6]  eval.c:2866
    +                                                             2102
Fgarbage_collect  (in emacs) + 60  [0x10021f7ec]  alloc.c:6056
    +
2102 garbage_collect  (in emacs) + 867  [0x10021e623]  alloc.c:5984
    +
2102 gc_sweep  (in emacs) + 14  [0x10021f58e]  alloc.c:7013
    +
 2090 sweep_conses  (in emacs) + 652  [0x10022424c]  alloc.c:6786
    +
 ! 2034 lisp_align_free  (in emacs) + 274,270,...
[0x10021c692,0x10021c68e,...]  alloc.c:1245
    +
 ! 32 lisp_align_free  (in emacs) + 300,280,...
[0x10021c6ac,0x10021c698,...]  alloc.c:1247
    +
 ! 9 lisp_align_free  (in emacs) + 376  [0x10021c6f8]  alloc.c:1260
    +
 ! : 7 free_small  (in libsystem_malloc.dylib) + 1464
[0x7fff6a4f7d9e]
    +
 ! : | 6 mvm_madvise_free  (in libsystem_malloc.dylib) + 87
[0x7fff6a4fe93e]
    +
 ! : | + 6 madvise  (in libsystem_kernel.dylib) + 10  [0x7fff6a48104a]
    +
 ! : | 1 mvm_madvise_free  (in libsystem_malloc.dylib) + 8
[0x7fff6a4fe8ef]
    +
 ! : 1 free  (in libsystem_malloc.dylib) + 107  [0x7fff6a4f4a1c]
    +
 ! : | 1 szone_size  (in libsystem_malloc.dylib) + 73
[0x7fff6a4f73a1]
    +
 ! : |   1 small_size  (in libsystem_malloc.dylib) + 144
[0x7fff6a4f7636]
    +
 ! : 1 free_small  (in libsystem_malloc.dylib) + 2090
[0x7fff6a4f8010]
    +
 ! :   1 small_free_scan_madvise_free  (in libsystem_malloc.dylib) +
451  [0x7fff6a501e54]
    +
 ! :     1 mvm_madvise_free  (in libsystem_malloc.dylib) + 87
[0x7fff6a4fe93e]
    +
 ! :       1 madvise  (in libsystem_kernel.dylib) + 10
[0x7fff6a48104a]
    +
 ! 7 lisp_align_free  (in emacs) + 348,352  [0x10021c6dc,0x10021c6e0]
alloc.c:1253
    +
 ! 5 lisp_align_free  (in emacs) + 86  [0x10021c5d6]  alloc.c:1228
    +
 ! : 5 mem_find  (in emacs) + 109  [0x10021ceed]  alloc.c:3960
    +
 ! 3 lisp_align_free  (in emacs) + 94  [0x10021c5de]  alloc.c:1228
    +
 !   3 mem_delete  (in emacs) + 399  [0x10022200f]  alloc.c:4220
    +
 !     2 xfree  (in emacs) + 64  [0x100210a70]  alloc.c:768
    +
 !     | 1 free_tiny  (in libsystem_malloc.dylib) + 459
[0x7fff6a4f8d8b]
    +
 !     | + 1 tiny_free_no_lock  (in libsystem_malloc.dylib) + 1111
[0x7fff6a4f92d6]
    +
 !     | +   1 tiny_free_list_add_ptr  (in libsystem_malloc.dylib) +
478  [0x7fff6a4f9ac8]
    +
 !     | 1 free_tiny  (in libsystem_malloc.dylib) + 479
[0x7fff6a4f8d9f]
    +
 !     1 xfree  (in emacs) + 37  [0x100210a55]  alloc.c:765
    +
 !       1 pdumper_object_p  (in emacs) + 59  [0x100210abb]
pdumper.h:148
    +
 3 sweep_conses  (in emacs) + 294,339,...
[0x1002240e6,0x100224113,...]  alloc.c:6761
    +
 2 sweep_conses  (in emacs) + 146  [0x100224052]  alloc.c:6739
    +
 2 sweep_conses  (in emacs) + 389  [0x100224145]  alloc.c:6764
    +
 2 sweep_conses  (in emacs) + 420  [0x100224164]  alloc.c:6766
    +
 ! 2 dead_object  (in emacs) + 18  [0x10021aa32]  lisp.h:1304
    +
 !   2 make_lisp_ptr  (in emacs) + 0,8  [0x100219e90,0x100219e98]
lisp.h:1284
    +
 1 sweep_conses  (in emacs) + 276  [0x1002240d4]  alloc.c:6759
    +
 1 sweep_conses  (in emacs) + 261  [0x1002240c5]  alloc.c:6760
    +
 1 sweep_conses  (in emacs) + 401  [0x100224151]  alloc.c:6765


Aaron

On Fri, Oct 30, 2020 at 6:18 AM Aaron Jensen <aaronjensen@gmail.com> wrote:
>
> This should probably be merged into a reopened #30322
>
> I'm seeing a busy loop in lisp_free_align often on Emacs 27. It does
> eventually recover, but it takes a minute or more.
>
> * thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
>     frame #0: 0x000000010021c692
> emacs`lisp_align_free(block=0x0000000291d2d400) at alloc.c:1245:7
>    1242       struct ablock **tem = &free_ablock;
>    1243       struct ablock *atop = &abase->blocks[aligned ?
> ABLOCKS_SIZE : ABLOCKS_SIZE - 1];
>    1244
> -> 1245       while (*tem)
>    1246         {
>    1247           if (*tem >= (struct ablock *) abase && *tem < atop)
>    1248             {
>
> I'm running gcmh-mode, and the last time it hung it was a gcmh-mode
> idle collection. Not sure if that makes any difference.
>
> Aaron