High memory usage resulting in frequent pauses for garbage collection
stsquad opened this issue · 1 comments
stsquad commented
I'm not sure if this is circe's fault or a result of a weird interaction with something else. However I'm seeing regular pauses while IRC is up and running. The CPU profiler pointed to GC being the main culprit so I enabled the memory profiler and got the following output:
- command-execute 876,484,018 74%
- call-interactively 876,417,198 74%
- funcall-interactively 876,416,142 74%
- counsel-M-x 814,754,398 69%
- ivy-read 814,565,050 69%
- read-from-minibuffer 813,003,998 69%
- irc--filter 810,769,895 69%
- if 810,767,583 69%
- progn 810,767,583 69%
- let 810,761,397 69%
- while 810,761,397 69%
- let 810,721,525 69%
- irc--handle-line 810,653,341 69%
- apply 810,423,043 69%
- irc-event-emit 810,421,987 69%
- apply 810,268,961 69%
- irc-handler-run 810,268,961 69%
- apply 810,268,961 69%
- irc-handle-ctcp--privmsg 690,714,752 59%
- irc-event-emit 690,707,424 59%
- apply 688,782,214 58%
- irc-handler-run 688,775,878 58%
- apply 688,775,878 58%
- circe--irc-display-event 688,411,318 58%
- apply 688,286,658 58%
- circe-display-PRIVMSG 688,286,658 58%
- circe-display 607,517,623 51%
- lui-insert 598,346,065 51%
- lui-insert-with-text-properties 596,867,775 51%
- lui-read-only 524,100,101 44%
- add-text-properties 523,996,381 44%
- flycheck-handle-change 67,079,237 5%
string-match 385,803 0%
- flycheck-buffer-automatically 37,688 0%
flycheck-may-check-automatically 33,464 0%
- lui-buttonize 30,907,929 2%
- lui-buttonize-urls 26,718,977 2%
- regexp-opt 22,526,257 1%
- regexp-opt-group 15,710,397 1%
- regexp-opt-group 11,997,346 1%
- regexp-opt-group 10,478,454 0%
- regexp-opt-group 8,864,490 0%
+ regexp-opt-group 7,293,602 0%
+ mapcar 789,192 0%
+ mapcar 826,988 0%
+ mapcar 777,860 0%
mapcar 859,740 0%
try-completion 2,167 0%
#<compiled 0x157b68a241e9> 4,334 0%
+ bounds-of-thing-at-point 1,477,226 0%
For one thing considering the time I've been running it seems like a large amount of total memory. I think it's attributed to command-execute because that is when the process filter executes. I've attempted to add some additional instrumentation to see if I could see anything obvious but it's hard to tell:
(defun irc--filter (proc data)
"Handle data from the process."
(irc-connection-put proc :conn-data
(concat (or (irc-connection-get proc :conn-data)
"")
data))
(when (not irc--filter-running-p)
(message "irc--filter start: %s -> %d" (memory-use-counts) gcs-done)
(let ((irc--filter-running-p t)
(data (irc-connection-get proc :conn-data)))
(while (string-match "\r?\n" data)
(let ((line (substring data 0 (match-beginning 0)))
(dstart (length data)))
(setq data (substring data (match-end 0)))
(let ((dend (length data))
(lenl (length line)))
(when (or (> dend 0)
(> lenl 0))
(message "irc--filter: processing %d->%d->%d"
dstart lenl dend)))
(irc-connection-put proc :conn-data data)
(irc--handle-line proc line)
(setq data (irc-connection-get proc :conn-data)))))
(message "irc--filter done: %s -> %d" (memory-use-counts) gcs-done)
(message nil)))
One such example showing how often GC collection was triggered:
irc--filter start: (64055407 129072 13905542 73517 1819192665 2763455 6125750) -> 584
irc--filter: processing 4096->70->4024
irc--filter: processing 4024->251->3771
irc--filter: processing 3771->193->3576
irc--filter: processing 3576->183->3391
irc--filter: processing 3391->147->3242
irc--filter: processing 3242->78->3162
irc--filter: processing 3162->117->3043
irc--filter: processing 3043->167->2874
irc--filter: processing 2874->220->2652
irc--filter: processing 2652->153->2497
irc--filter: processing 2497->243->2252
irc--filter: processing 2252->78->2172
irc--filter: processing 2172->366->1804
irc--filter: processing 1804->285->1517
irc--filter: processing 1517->95->1420
irc--filter: processing 1420->177->1241
irc--filter: processing 1241->110->1129
irc--filter: processing 1129->97->1030
irc--filter: processing 1030->208->820
irc--filter: processing 820->128->690
irc--filter: processing 690->124->564
irc--filter: processing 564->194->368
irc--filter: processing 368->288->78
irc--filter done: (66911687 129134 13960439 73517 1821361221 2899141 6197227) -> 592
But it's hard to know if I'm biasing those results with adding extra logging. Any pointers to better ways to debug what is going on would be appreciated.