bug-gnu-emacs
[Top][All Lists]
Advanced
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

bug#39413: 26.2; Emacs gets hung

From: ISHIKAWA,chiaki
Subject: bug#39413: 26.2; Emacs gets hung
Date: Wed, 11 Aug 2021 16:22:21 +0900
User-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:78.0) Gecko/20100101 Thunderbird/78.12.0 
Hi,
Oops sorry, I forgot to attach the GC information dump when 2-min GC guru meditation time occurred. 
Here it is. A copy from *Messages* buffer.
I am afraid that I had to back track to older messages and I believe the ones I copied here are related to the timing of the long GC. 
But I could not exactly figure out which one.

Chiaki

<<< Type SPC or RET to bury the buffer list >>>
Mark set
[(388481492 12663 315852263 37859 252680715 12068535 8530128 217.751094438 931)  (390762053 12664 320601077 37859 254857509 12248048 8666125 219.633925136 932)  (393068244 12665 325413926 37859 257099914 12428854 8802846 221.552147241 933)  (402532085 12666 325423645 37859 257116197 12428863 8803027 223.487605937 934)  (411994601 12667 325425009 37859 257132482 12428865 8803207 225.406804595 935)  (414448248 12668 330538753 37859 259505987 12621465 8949175 227.343266966 936)  (424074389 12669 330548382 37859 259522285 12621478 8949356 229.348980796 937)  (433699244 12670 330549685 37859 259538585 12621481 8949536 231.351762205 938)  (436052588 12695 335564019 37860 262003952 12804062 9088033 233.29986785 939)  (437421791 12754 338433175 37860 263807816 12913522 9184089 241.951760306 940)  (438845632 12799 341601300 37860 265238759 13012817 9274435 243.55520882 941)  (440178606 12842 344865373 37860 266433618 13099621 9353887 245.138839078 942)  (441570556 12884 348132343 37860 267683757 13189878 9438753 246.769836844 943)  (442913777 12925 351504882 37860 268870526 13279030 9517477 248.360581202 944)  (444288336 12970 354793728 37860 270325980 13371631 9601867 249.986431307 945)  (445752850 13021 357867712 37860 271951417 13480694 9698259 251.625818749 946)  (447151863 13067 361600674 37860 273497660 13567563 9778153 253.259859431 947)  (448657655 13112 365067032 37860 275261240 13670086 9871747 254.994917854 948)  (450158914 13128 368163204 37860 276859198 13782657 9970119 256.633972618 949)  (451707980 13129 371342199 37860 278396622 13901166 10072262 258.313592942 950)  (453306224 13130 374620228 37860 279986655 14023233 10177572 260.026878125 951)  (464657341 13133 374630765 37860 280003882 14023235 10177761 261.742461495 952)  (476005819 13134 374631080 37860 280018058 14023235 10177809 263.587127108 953)  (477506723 13182 378534545 37862 281816769 14095140 10272953 265.478689001 954)  (478847002 13223 383581993 37862 283960864 14103107 10329518 267.316126049 955)  (479979175 13239 389369881 37862 285520586 14104493 10350952 269.874493833 956)  (481386726 13240 394330012 37862 287576346 14129844 10386458 272.129021279 957)  (483293142 13241 396849752 37862 290130666 14268679 10526833 274.668402532 958)  (485150904 13267 399531895 37862 292954354 14397053 10681026 276.994701437 959)  (520316838 13502 402388436 37862 368141808 16928818 10788359 279.346871091 960)] 

"Wed Aug 11 14:35:01 2021"
"[(388481492 12663 315852263 37859 252680715 12068535 8530128 217.751094438 931)  (390762053 12664 320601077 37859 254857509 12248048 8666125 219.633925136 932)  (393068244 12665 325413926 37859 257099914 12428854 8802846 221.552147241 933)  (402532085 12666 325423645 37859 257116197 12428863 8803027 223.487605937 934)  (411994601 12667 325425009 37859 257132482 12428865 8803207 225.406804595 935)  (414448248 12668 330538753 37859 259505987 12621465 8949175 227.343266966 936)  (424074389 12669 330548382 37859 259522285 12621478 8949356 229.348980796 937)  (433699244 12670 330549685 37859 259538585 12621481 8949536 231.351762205 938)  (436052588 12695 335564019 37860 262003952 12804062 9088033 233.29986785 939)  (437421791 12754 338433175 37860 263807816 12913522 9184089 241.951760306 940)  (438845632 12799 341601300 37860 265238759 13012817 9274435 243.55520882 941)  (440178606 12842 344865373 37860 266433618 13099621 9353887 245.138839078 942)  (441570556 12884 348132343 37860 267683757 13189878 9438753 246.769836844 943)  (442913777 12925 351504882 37860 268870526 13279030 9517477 248.360581202 944)  (444288336 12970 354793728 37860 270325980 13371631 9601867 249.986431307 945)  (445752850 13021 357867712 37860 271951417 13480694 9698259 251.625818749 946)  (447151863 13067 361600674 37860 273497660 13567563 9778153 253.259859431 947)  (448657655 13112 365067032 37860 275261240 13670086 9871747 254.994917854 948)  (450158914 13128 368163204 37860 276859198 13782657 9970119 256.633972618 949)  (451707980 13129 371342199 37860 278396622 13901166 10072262 258.313592942 950)  (453306224 13130 374620228 37860 279986655 14023233 10177572 260.026878125 951)  (464657341 13133 374630765 37860 280003882 14023235 10177761 261.742461495 952)  (476005819 13134 374631080 37860 280018058 14023235 10177809 263.587127108 953)  (477506723 13182 378534545 37862 281816769 14095140 10272953 265.478689001 954)  (478847002 13223 383581993 37862 283960864 14103107 10329518 267.316126049 955)  (479979175 13239 389369881 37862 285520586 14104493 10350952 269.874493833 956)  (481386726 13240 394330012 37862 287576346 14129844 10386458 272.129021279 957)  (483293142 13241 396849752 37862 290130666 14268679 10526833 274.668402532 958)  (485150904 13267 399531895 37862 292954354 14397053 10681026 276.994701437 959)  (520316838 13502 402388436 37862 368141808 16928818 10788359 279.346871091 960)] 
"
Mark set [2 times]
End of buffer
Beginning of buffer [2 times]
End of buffer
Beginning of buffer
End of buffer
<<< Type SPC or RET to bury the buffer list >>> [2 times]
Mark set
<<< Type SPC or RET to bury the buffer list >>>
Mark set [2 times]
ESC C-M-p is undefined
Mark set
Saved text from "
"Wed Aug 11 14:25:39 2021"
"[(377509160"
(New file)
Mark set [2 times]
Saving file /tmp/t.memory.txt...
Wrote /tmp/t.memory.txt
Making completion list...
Quit
[(390762053 12664 320601077 37859 254857509 12248048 8666125 219.633925136 932)  (393068244 12665 325413926 37859 257099914 12428854 8802846 221.552147241 933)  (402532085 12666 325423645 37859 257116197 12428863 8803027 223.487605937 934)  (411994601 12667 325425009 37859 257132482 12428865 8803207 225.406804595 935)  (414448248 12668 330538753 37859 259505987 12621465 8949175 227.343266966 936)  (424074389 12669 330548382 37859 259522285 12621478 8949356 229.348980796 937)  (433699244 12670 330549685 37859 259538585 12621481 8949536 231.351762205 938)  (436052588 12695 335564019 37860 262003952 12804062 9088033 233.29986785 939)  (437421791 12754 338433175 37860 263807816 12913522 9184089 241.951760306 940)  (438845632 12799 341601300 37860 265238759 13012817 9274435 243.55520882 941)  (440178606 12842 344865373 37860 266433618 13099621 9353887 245.138839078 942)  (441570556 12884 348132343 37860 267683757 13189878 9438753 246.769836844 943)  (442913777 12925 351504882 37860 268870526 13279030 9517477 248.360581202 944)  (444288336 12970 354793728 37860 270325980 13371631 9601867 249.986431307 945)  (445752850 13021 357867712 37860 271951417 13480694 9698259 251.625818749 946)  (447151863 13067 361600674 37860 273497660 13567563 9778153 253.259859431 947)  (448657655 13112 365067032 37860 275261240 13670086 9871747 254.994917854 948)  (450158914 13128 368163204 37860 276859198 13782657 9970119 256.633972618 949)  (451707980 13129 371342199 37860 278396622 13901166 10072262 258.313592942 950)  (453306224 13130 374620228 37860 279986655 14023233 10177572 260.026878125 951)  (464657341 13133 374630765 37860 280003882 14023235 10177761 261.742461495 952)  (476005819 13134 374631080 37860 280018058 14023235 10177809 263.587127108 953)  (477506723 13182 378534545 37862 281816769 14095140 10272953 265.478689001 954)  (478847002 13223 383581993 37862 283960864 14103107 10329518 267.316126049 955)  (479979175 13239 389369881 37862 285520586 14104493 10350952 269.874493833 956)  (481386726 13240 394330012 37862 287576346 14129844 10386458 272.129021279 957)  (483293142 13241 396849752 37862 290130666 14268679 10526833 274.668402532 958)  (485150904 13267 399531895 37862 292954354 14397053 10681026 276.994701437 959)  (520316838 13502 402388436 37862 368141808 16928818 10788359 279.346871091 960)  (520636475 13796 402726636 37868 370978420 16933589 10826355 422.114721386 961)] 

"Wed Aug 11 14:43:38 2021"
"[(390762053 12664 320601077 37859 254857509 12248048 8666125 219.633925136 932)  (393068244 12665 325413926 37859 257099914 12428854 8802846 221.552147241 933)  (402532085 12666 325423645 37859 257116197 12428863 8803027 223.487605937 934)  (411994601 12667 325425009 37859 257132482 12428865 8803207 225.406804595 935)  (414448248 12668 330538753 37859 259505987 12621465 8949175 227.343266966 936)  (424074389 12669 330548382 37859 259522285 12621478 8949356 229.348980796 937)  (433699244 12670 330549685 37859 259538585 12621481 8949536 231.351762205 938)  (436052588 12695 335564019 37860 262003952 12804062 9088033 233.29986785 939)  (437421791 12754 338433175 37860 263807816 12913522 9184089 241.951760306 940)  (438845632 12799 341601300 37860 265238759 13012817 9274435 243.55520882 941)  (440178606 12842 344865373 37860 266433618 13099621 9353887 245.138839078 942)  (441570556 12884 348132343 37860 267683757 13189878 9438753 246.769836844 943)  (442913777 12925 351504882 37860 268870526 13279030 9517477 248.360581202 944)  (444288336 12970 354793728 37860 270325980 13371631 9601867 249.986431307 945)  (445752850 13021 357867712 37860 271951417 13480694 9698259 251.625818749 946)  (447151863 13067 361600674 37860 273497660 13567563 9778153 253.259859431 947)  (448657655 13112 365067032 37860 275261240 13670086 9871747 254.994917854 948)  (450158914 13128 368163204 37860 276859198 13782657 9970119 256.633972618 949)  (451707980 13129 371342199 37860 278396622 13901166 10072262 258.313592942 950)  (453306224 13130 374620228 37860 279986655 14023233 10177572 260.026878125 951)  (464657341 13133 374630765 37860 280003882 14023235 10177761 261.742461495 952)  (476005819 13134 374631080 37860 280018058 14023235 10177809 263.587127108 953)  (477506723 13182 378534545 37862 281816769 14095140 10272953 265.478689001 954)  (478847002 13223 383581993 37862 283960864 14103107 10329518 267.316126049 955)  (479979175 13239 389369881 37862 285520586 14104493 10350952 269.874493833 956)  (481386726 13240 394330012 37862 287576346 14129844 10386458 272.129021279 957)  (483293142 13241 396849752 37862 290130666 14268679 10526833 274.668402532 958)  (485150904 13267 399531895 37862 292954354 14397053 10681026 276.994701437 959)  (520316838 13502 402388436 37862 368141808 16928818 10788359 279.346871091 960)  (520636475 13796 402726636 37868 370978420 16933589 10826355 422.114721386 961)] 
"
C-M-g is undefined
Quit
[(393068244 12665 325413926 37859 257099914 12428854 8802846 221.552147241 933)  (402532085 12666 325423645 37859 257116197 12428863 8803027 223.487605937 934)  (411994601 12667 325425009 37859 257132482 12428865 8803207 225.406804595 935)  (414448248 12668 330538753 37859 259505987 12621465 8949175 227.343266966 936)  (424074389 12669 330548382 37859 259522285 12621478 8949356 229.348980796 937)  (433699244 12670 330549685 37859 259538585 12621481 8949536 231.351762205 938)  (436052588 12695 335564019 37860 262003952 12804062 9088033 233.29986785 939)  (437421791 12754 338433175 37860 263807816 12913522 9184089 241.951760306 940)  (438845632 12799 341601300 37860 265238759 13012817 9274435 243.55520882 941)  (440178606 12842 344865373 37860 266433618 13099621 9353887 245.138839078 942)  (441570556 12884 348132343 37860 267683757 13189878 9438753 246.769836844 943)  (442913777 12925 351504882 37860 268870526 13279030 9517477 248.360581202 944)  (444288336 12970 354793728 37860 270325980 13371631 9601867 249.986431307 945)  (445752850 13021 357867712 37860 271951417 13480694 9698259 251.625818749 946)  (447151863 13067 361600674 37860 273497660 13567563 9778153 253.259859431 947)  (448657655 13112 365067032 37860 275261240 13670086 9871747 254.994917854 948)  (450158914 13128 368163204 37860 276859198 13782657 9970119 256.633972618 949)  (451707980 13129 371342199 37860 278396622 13901166 10072262 258.313592942 950)  (453306224 13130 374620228 37860 279986655 14023233 10177572 260.026878125 951)  (464657341 13133 374630765 37860 280003882 14023235 10177761 261.742461495 952)  (476005819 13134 374631080 37860 280018058 14023235 10177809 263.587127108 953)  (477506723 13182 378534545 37862 281816769 14095140 10272953 265.478689001 954)  (478847002 13223 383581993 37862 283960864 14103107 10329518 267.316126049 955)  (479979175 13239 389369881 37862 285520586 14104493 10350952 269.874493833 956)  (481386726 13240 394330012 37862 287576346 14129844 10386458 272.129021279 957)  (483293142 13241 396849752 37862 290130666 14268679 10526833 274.668402532 958)  (485150904 13267 399531895 37862 292954354 14397053 10681026 276.994701437 959)  (520316838 13502 402388436 37862 368141808 16928818 10788359 279.346871091 960)  (520636475 13796 402726636 37868 370978420 16933589 10826355 422.114721386 961)  (520702163 13807 402879841 38129 371108294 16933644 10830730 620.747356527 962)] 

"Wed Aug 11 14:58:00 2021"
"[(393068244 12665 325413926 37859 257099914 12428854 8802846 221.552147241 933)  (402532085 12666 325423645 37859 257116197 12428863 8803027 223.487605937 934)  (411994601 12667 325425009 37859 257132482 12428865 8803207 225.406804595 935)  (414448248 12668 330538753 37859 259505987 12621465 8949175 227.343266966 936)  (424074389 12669 330548382 37859 259522285 12621478 8949356 229.348980796 937)  (433699244 12670 330549685 37859 259538585 12621481 8949536 231.351762205 938)  (436052588 12695 335564019 37860 262003952 12804062 9088033 233.29986785 939)  (437421791 12754 338433175 37860 263807816 12913522 9184089 241.951760306 940)  (438845632 12799 341601300 37860 265238759 13012817 9274435 243.55520882 941)  (440178606 12842 344865373 37860 266433618 13099621 9353887 245.138839078 942)  (441570556 12884 348132343 37860 267683757 13189878 9438753 246.769836844 943)  (442913777 12925 351504882 37860 268870526 13279030 9517477 248.360581202 944)  (444288336 12970 354793728 37860 270325980 13371631 9601867 249.986431307 945)  (445752850 13021 357867712 37860 271951417 13480694 9698259 251.625818749 946) 

On 2021/08/11 15:07, ISHIKAWA,chiaki wrote:
(Sorry I am working from home and I have used my office e-mail address and personal e-mail address interchangeably.) 

Hi,
Good news. I could capture at least something that shows what happens when the Emacs seems to spend strangely large amount of time in GC and for all practical purposes it gets hung for a couple of minutes.
With the post-gc-hook, usually "Garbage collecting ..." is overwritten with the dump of array data that holds GC-related inforamtion. But if GC is spending long time, I see "Garbage collecting" and hung emacs window.
Just immediately after I wrote my previous e-mail, I noticed that the Mozilla repository corruption problem was finally solved. Official fix was announced. So I applied it and luckily I could compile and build mozilla thunderbird mail client for debugging again.
And yes, the strange emacs hung or rather "GC is spending too much CPU without visible change" happens again a few hours later, a few times. 

I am attaching two screen dump.
- One is the screen capture of Linux desktop.
   In it, you can see xosview window.
   (I marked it with red pen.)
   You can see memory is not used  up. Only about 11 GB of memory is used out of 16 GB. 
   No swapping should occur.
   Emacs is not responding at all since it is running wild in GC routine.
  Thus its window cannot be repainted. (Blue pen mark.)
   I had to move xosview window, etc. for better view and when the windows got repainted,    Emacs window was not repainted. Other windows and programs such as terminals are responding without any issue at all.
   I could not measure the exact time Emacs was not responding. I think it was like More thant1 min 30 seconds more likely over 2 minutes.
   xosview has a CPU usage window which shows one CPU, CPU4  was occupied hundred percent. 
   That was the CPU emacs uses.
   The full horizontal span of data window covers about 30 seconds. So you can see that GC (I think it is GC) runs more than 30 seconds by then. Actually, after more than 30 seconds, I drifted off to capture the screen, mark the captured image, etc. This more than 1 minute long GC  is really puzzling. 

- The other attachment  is Windows task manager memory information.
   Sorry the legends are in Japanese since I used Japanese Windows locale.    You can see I still have like 4.5 G of free memory out of 32 GB real memory.    Thus the host windows 10 is not feeling any problem and I can run browser, e-mail client, etc. without any issue at all while Emacs is running GC earnestly. 

I am attaching the GC dump data collected by my post-gc-hook function.
But it does not reveal much.
I probably should include the start of GC time and end of GC time in the array of information I collect for each GC run. Then we will know for sure how much time GC ran. 
But there does NOT seem to be a pre-gc-hook as opposed to post-gc-hook.
Hmm... I wonder how I record the start time of GC call.
Any suggestion on the last topic of how to record GC time at fine granularity will be appreciated. 

Chiaki

On 2021/08/11 10:08, ISHIKAWA,chiaki wrote:

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
reply via email to
[Prev in Thread] Current Thread [Next in Thread]