bug#39413: 26.2; Emacs gets hung

[ISHIKAWA,chiaki]

Hi,

Sorry, I might have picked up too early dumps in my previous e-mail.

What about the dump below, which was in the *Messages* buffer following 
dump I sent.
I am afraid I picked up the wrong dump in my previous e-mail.

Now, is "gc-elapsed" the elapsed time spent in the GC routine?
If so, the two samples at the end of the dump here certainly look 
suspicious.
Actually, I saw a very long GC and after that,
I manually invoked GC by M-X garbage-collect and to my surprise THAT 
also turned out to take a long time to finish. I was hoping the first GC 
somehow aligned memory structure in a neat order, but that did not seem 
to be the case.

But as far as the amount of memory consumed does not differ much from 
other short-lived GC.
Or for whatever the reason, a small amount of memory increase may have
an unexpected effect on this CPU, AMD Ryzen 7 1700 Eight-Core Processor 
3.00 GHz?
Again, this is very unlikely. I have not seen this slow GC until about a 
year ago which forced me to file a bug report. Also, the attached dump 
shows that there are two tandem GC which took a long time, but other GCs 
that follow are short-lived.

I am still suspecting a certain  form of inefficiency due to allocation 
pattern of strings [I am assuming that strings are allocated and then 
added to the shell buffer, maybe I am wrong. It may be a long repetitoon 
of realloc?]  to store  longish output lines and then short lines 
produced by the particular compile/build process into the Shell buffer 
(M-X shell) in which I ran largish compilation/link process for mozilla 
thunderbird.

This could be purely due to excessive cache misses caused by particular 
memory access patterns during GC to handle my particular memory 
allocation patterns. But I have no idea.
I may have to find out the cache miss #.

Chiaki

Here is the suspect:  the last two lines look very suspicious.

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)] <=

and a couple of hours later.: I did not do a lot during this time.

Mark set
Auto-saving...done
Saving file /home/ishikawa/Dropbox/todo-memo-home.txt...
Wrote /home/ishikawa/Dropbox/todo-memo-home.txt
Saving file /home/ishikawa/Dropbox/todo-memo-home.txt...
Wrote /home/ishikawa/Dropbox/todo-memo-home.txt
Saving file /home/ishikawa/Dropbox/todo-memo-home.txt...
[(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) <=
 (520801350 13855 402954201 38197 371207595 16935253 10837272 
620.862288325 963)
 (520860834 13895 403094379 38257 371361488 16936922 10844603 
620.954004521 964)
 (520960277 14286 403145781 38257 371718646 16938526 10849771 
621.0046367 965)
 (521023418 14444 403221395 38259 372414726 16940131 10857263 
621.049176975 966)
 (521071758 14508 403310401 38260 373187220 16940139 10866947 
621.097972876 967)
 (521097606 14509 403398321 38260 374994158 16940147 10867991 
621.156022718 968)]

On 2021/08/11 20:47, Eli Zaretskii wrote:
> > Cc: Noam Postavsky <npostavs@gmail.com>, Eli Zaretskii <eliz@gnu.org>,
> >   39413@debbugs.gnu.org,
> >   chiaki-ishikawa-thunderbird-account <chiaki.ishikawa@ubin.jp>
> > From: "ISHIKAWA,chiaki" <ishikawa@yk.rim.or.jp>
> > Date: Wed, 11 Aug 2021 15:07:26 +0900
> >
> > 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.
> I don't see this in the data you sent:
>
> > [(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)]
> Look at the 2 last numbers in each sample: the count of GC cycles goes
> up by one, and the elapsed accumulated time spent in GC goes up by 2.5
> sec for each GC cycle.  That's nowhere near the couple of minutes
> value you report.  Could it be that the Emacs process doesn't get CPU
> resources?