bug#39413: 26.2; Emacs gets hung

[ISHIKAWA,chiaki]

On 2021/08/11 1:09, Lars Ingebrigtsen wrote:
> chiaki-ishikawa-thunderbird-account <chiaki.ishikawa@ubin.jp> writes:
>
> > Stay tuned. I am really interested in WHERE/WHY this long pause
> > occurs.: maybe Windows 10 memory allocation/ Virtual Box
> > emulation/Linux kernel memory allocation, and AMD Ryzen CPU's cache
> > replacement policy all add up.
> This was a year ago -- are you still seeing these hangs, and if so, have
> you confirmed that they don't happen because the machine (client or
> host) is swapping?

Hi,

Thank you for your follow-up.

I still think there is a problem with memory allocator in the later Emacs 
versions. I can't figure out exactly when this happens. I have been using Emacs 
in this setup for quite sometime and yet I had NOT experienced this strange 
long pause before.

Now, it is true that I do use much memory while running mozilla thunderbird 
compilation
WITHIN shell window which I open M-x shell.
But again, I used to do this for the last 8-9 years.

One thing I notice is that running compilation script of mozilla thunderbird
outputs a pattern of longish lines and then a few short lines very frequently.
Yes, they amount to a lot of memory, but I suspect that
they may cause a somewhat inefficient handling by string allocator.

I used the following post-GC-hook to record the behavior of emacs GC.

After the code snippet, I attach the output from such a call.

;;;

;;; GC behavior monitor
;;;
;;; Record some key information for GC in the GC post-hook so that I
;;; can learn something about the behavior and performance of GC with
;;; concrete data.

(setq my-gc-statistics (make-vector 30 nil))

;;; The element is
;;; (append (memory-use-counts) (list gc-elapsed gcs-done))
;;; Each time the following function is called, the
;;; elements in the array is shifted toward the end.
;;; Use (message "%S" my-gc-statistics) to force the
;;; recording of my-gc-statistics value in *Messages* buffer for later 
analysis.


(defun update-my-gc-statistics ()
  (let ((i 28))
    (progn
     ;;; very unlike Lisp
     (while (<= 0 i)
       (progn (aset my-gc-statistics (+ 1 i) (aref my-gc-statistics i))
             (setq i (- i 1) )))
     (aset my-gc-statistics 0
           (append (memory-use-counts) (list gc-elapsed gcs-done)))
     ;;; print the latest one last so that I can see the glimpse in the 
narrow
     ;;; output window.
     (message "%S\n%S" (current-time-string) (pp (reverse 
my-gc-statistics))))))

(setq post-gc-hook 'update-my-gc-statistics)

---
Normal behavior. Not much pause.

[(19051645 7445 43993805 36764 42521186 286669 1176042 13.581105925 320)
 (19117025 7446 44152747 36764 42547677 287685 1177518 13.624215366 321)
 (19174133 7469 44332450 36765 42585061 288281 1178955 13.667294932 322)
 (19238776 7470 44504363 36765 42620253 289199 1180384 13.714802148 323)
 (19303795 7484 44666173 36767 42649518 289786 1181923 13.756323136 324)
 (19365595 7485 44837589 36767 42676862 290659 1183423 13.807570787 325)
 (19425828 7486 45007513 36767 42712688 291410 1184879 13.847687952 326)
 (19482572 7488 45186533 36769 42753576 291969 1186503 13.905988177 327)
 (19539282 7489 45365763 36769 42782042 292534 1188002 13.947620008 328)
 (19610699 7526 45530194 36769 42832733 293078 1189542 13.98705147 329)
 (19677333 7536 45705015 36769 42861041 293694 1190941 14.041105235 330)
 (19736527 7537 45875148 36769 42896534 294340 1192316 14.082710146 331)
 (19799864 7538 46047037 36769 42922173 295201 1193738 14.126554401 332)
 (19865128 7542 46209994 36769 42949055 295876 1195133 14.167501197 333)
 (19924904 7564 46377456 36769 43008388 296531 1196605 14.207478738 334)
 (19986717 7674 46546221 36770 43035046 296928 1197955 14.249106813 335)
 (20046726 7675 46716423 36770 43060757 297558 1199338 14.302346074 336)
 (20107508 7678 46888051 36772 43097195 298290 1200743 14.342108851 337)
 (20172065 7680 47061015 36774 43126993 298770 1202285 14.383165327 338)
 (20235780 7681 47221594 36774 43153041 299635 1203754 14.423942963 339)
 (20294623 7682 47405064 36774 43202163 300434 1205260 14.473857509 340)
 (20353428 7692 47574958 36778 43250345 300773 1207056 14.528225012 341)
 (20427274 7778 47679351 36778 43337331 303690 1212437 14.570319341 342)
 (20501106 7941 47776024 36778 43443248 307419 1218097 14.610816267 343)
 (20566988 7996 47933001 36778 43490727 309071 1221003 14.675236804 344)
 (20637587 8078 48085242 36778 43532391 309493 1222405 14.716701768 345)
 (20697606 8127 48240788 36778 43601564 310907 1225370 14.759790056 346)
 (20762697 8186 48384470 36778 43646718 312881 1228282 14.799301233 347)
 (20816911 8199 48566522 36778 43672496 313533 1229651 14.863568335 348)
 (20885113 8221 48719120 36778 43710277 314237 1231072 14.904231536 349)]


Well, due to a build issue (corrupt repository caused by MERCURIAL bug.
https://bugzilla.mozilla.org/show_bug.cgi?id=1720302
I have not been able to do much build and debug work on mozilla TB for 
the last few weeks.

But when I do run the compilation, etc. I still see the strange 
pause/hang from time to time.
Only Emacs is affected. Other programs within virtualbox responds,.
Repainting of emacs does not happen.
Also, Windows 10 host is running smoothly. So I suspect Emacs is running 
CPU wildly when this happens. Yes, I have seen CPU usage go up using 
xosview.

There may be some unexpected inefficiency ( a coding error that may 
cause an extra loop over a gigabyte of memoyr?)

When I try to analyze the issue, it is always (well, it seems to me) 
related to string allocation.

I have no idea where to look for the issue. As I said, the particular 
pattern of allocation by shell-mode and a lot of output from compilation 
script (with short and long lines mixed)  may cause some strange 
inefficiency in memory access behavior.

Chiaki