bug#42911: 28.0.50; write_region sometimes extremely very slow

bug#42911: 28.0.50; write_region sometimes extremely very slow

[Tino Calancha]

X-Debbugs-Cc: uyennhi.qm@gmail.com

Verified in both emacs-27 and emacs-master

Recipe:
emacs -Q ~/save-buffer-slow.txt
;; insert few characters and run
M-: (benchmark-run nil (save-buffer))

;; Repeat several times: sometimes it takes a reasonable time, but
;; in others it takes huge time
;; (6-10 s to save a buffer with less that 50 characters)

It happens randomly.
I have been observed this maybe 1 week.  I don't recall to see this in
my other laptio runinning Debian 10, so it might be OS related?


In GNU Emacs 28.0.50 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.21, cairo version 1.16.0)
 of 2020-08-18 built on localhost.example.com
Repository revision: 9905001e4b0c9dc0a90cefdd9530a90d07a17b99
Repository branch: master
Windowing system distributor 'The X.Org Foundation', version 11.0.12008000
System Description: openSUSE Tumbleweed
uname -a: Linux localhost.example.com 5.7.11-1-default #1 SMP Wed Jul 29 09:32:21 UTC 2020 (5015994) x86_64 x86_64 x86_64 GNU/Linux


Recent messages:
You can run the command ‘erase-buffer’ with M-x era RET
user-error: Beginning of history; no preceding item
Saving file /home/calancha/save-buffer-slow.txt...
Wrote /home/calancha/save-buffer-slow.txt
(6.688615679 0 0.0)
Saving file /home/calancha/save-buffer-slow.txt...
Wrote /home/calancha/save-buffer-slow.txt
(0.076871944 0 0.0)
Saving file /home/calancha/save-buffer-slow.txt...
Wrote /home/calancha/save-buffer-slow.txt
(10.659738934 0 0.0)
Configured using:
 'configure --with-x-toolkit=gtk3'

Configured features:
XPM JPEG TIFF GIF PNG CAIRO SOUND DBUS GSETTINGS GLIB NOTIFY INOTIFY
LIBSELINUX GNUTLS LIBXML2 FREETYPE HARFBUZZ ZLIB TOOLKIT_SCROLL_BARS
GTK3 X11 XDBE XIM MODULES THREADS PDUMPER

Important settings:
  value of $LC_ALL: 
  value of $LC_COLLATE: en_US.UTF-8
  value of $LC_CTYPE: en_US.UTF-8
  value of $LC_MESSAGES: en_US.UTF-8
  value of $LC_MONETARY: en_US.UTF-8
  value of $LC_NUMERIC: en_US.UTF-8
  value of $LC_TIME: en_US.UTF-8
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: @im=ibus
  locale-coding-system: utf-8-unix

Major mode: Text

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message rmc puny dired dired-loaddefs
rfc822 mml mml-sec password-cache epa derived epg epg-config gnus-util
rmail rmail-loaddefs text-property-search mm-decode mm-bodies mm-encode
mail-parse rfc2231 mailabbrev gmm-utils mailheader sendmail rfc2047
rfc2045 ietf-drums mm-util mail-prsvr mail-utils cl-extra seq byte-opt
gv bytecomp byte-compile cconv help-mode easymenu novice time-date
subr-x cl-loaddefs cl-lib benchmark tooltip eldoc electric uniquify
ediff-hook vc-hooks lisp-float-type mwheel term/x-win x-win
term/common-win x-dnd tool-bar dnd fontset image regexp-opt fringe
tabulated-list replace newcomment text-mode elisp-mode lisp-mode
prog-mode register page tab-bar menu-bar rfn-eshadow isearch timer
select scroll-bar mouse jit-lock font-lock syntax facemenu font-core
term/tty-colors frame minibuffer cl-generic cham georgian utf-8-lang
misc-lang vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms
cp51932 hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese composite charscript charprop case-table epa-hook
jka-cmpr-hook help simple abbrev obarray cl-preloaded nadvice loaddefs
button faces cus-face macroexp files text-properties overlay sha1 md5
base64 format env code-pages mule custom widget hashtable-print-readable
backquote threads dbusbind inotify dynamic-setting system-font-setting
font-render-setting cairo move-toolbar gtk x-toolkit x multi-tty
make-network-process emacs)

Memory information:
((conses 16 47888 6325)
 (symbols 48 6098 1)
 (strings 32 16202 1003)
 (string-bytes 1 529670)
 (vectors 16 11018)
 (vector-slots 8 152947 12719)
 (floats 8 33 40)
 (intervals 56 201 0)
 (buffers 992 13))

bug#42911: 28.0.50; write_region sometimes extremely very slow

[Eli Zaretskii]

> From: Tino Calancha <tino.calancha@gmail.com>
> Date: Tue, 18 Aug 2020 11:46:13 +0200
> Cc: uyennhi.qm@gmail.com
> 
> Recipe:
> emacs -Q ~/save-buffer-slow.txt
> ;; insert few characters and run
> M-: (benchmark-run nil (save-buffer))
> 
> ;; Repeat several times: sometimes it takes a reasonable time, but
> ;; in others it takes huge time
> ;; (6-10 s to save a buffer with less that 50 characters)
> 
> It happens randomly.

Did you check that GC doesn't kick in when the "slow" saving happens?

bug#42911: 28.0.50; write_region sometimes extremely very slow

[Tino Calancha]

Eli Zaretskii <eliz@gnu.org> writes:

>> Recipe:
>> emacs -Q ~/save-buffer-slow.txt
>> ;; insert few characters and run
>> M-: (benchmark-run nil (save-buffer))
>> 
>> ;; Repeat several times: sometimes it takes a reasonable time, but
>> ;; in others it takes huge time
>> ;; (6-10 s to save a buffer with less that 50 characters)
>> 
>> It happens randomly.
>
> Did you check that GC doesn't kick in when the "slow" saving happens?
`benchmark-run` lets you know teh number of GC and the time used by them
while running the form.  The reported slowliness was happening even
without GC.
I was curious if someone runnning opensuse Tumbleweed was seeing something similar.

I suspect this might be a problem of my OS (probably it was under heavy stress).
Now I am in vacation, and the computer seems more relax (same like me).  I have also
upgraded the OS and got a new kernel.

The following is data right now running this:
emacs -Q /tmp/save-slow-buffer.txt
;; evaluate the following key binding:

(global-set-key (kbd "<f5>") (lambda () (interactive) (print
(benchmark-run nil (save-buffer)) (current-buffer))))

;; now push <f5> slowly several times
;; Still seems a bit slow sometimes (~0.1 s) but it is acceptable for my needs:

(0.058208321 0 0.0)
(0.10882129 1 0.025746066999999928)
(0.051934588 0 0.0)
(0.068579962 0 0.0)
(0.066899402 0 0.0)
(0.078017127 0 0.0)
(0.078926675 0 0.0)
(0.117405042 0 0.0)
(0.04960965 0 0.0)
(0.043352053 0 0.0)
(0.086415222 0 0.0)
(0.064884219 0 0.0)
(0.06522908 0 0.0)
(0.058116398 0 0.0)
(0.109880304 0 0.0)
(0.049452437 0 0.0)
(0.10265914 0 0.0)
(0.080930332 0 0.0)
(0.298022584 0 0.0)
(0.067618432 0 0.0)
(0.059602676 0 0.0)
(0.0712565 0 0.0)
(0.066321402 0 0.0)
(0.062397403 0 0.0)
(0.16588965 0 0.0)
(0.123642695 0 0.0)
(0.055607216 0 0.0)
(0.070665992 0 0.0)
(0.087962897 0 0.0)
(0.179056865 0 0.0)
(0.084647328 0 0.0)
(0.152946603 0 0.0)
(0.074221478 0 0.0)
(0.0797594 0 0.0)
(0.117525087 0 0.0)
(0.068923711 0 0.0)
(0.074521989 0 0.0)
(0.074681374 0 0.0)
(0.202450873 0 0.0)
(0.102854426 0 0.0)
(0.083368982 0 0.0)
(0.074109755 0 0.0)
(0.070000116 0 0.0)
(0.065221696 0 0.0)
(0.077440244 0 0.0)

bug#42911: 28.0.50; write_region sometimes extremely very slow

[Eli Zaretskii]

> From: Tino Calancha <tino.calancha@gmail.com>
> Cc: uyennhi.qm@gmail.com,  42911@debbugs.gnu.org
> Date: Tue, 25 Aug 2020 18:04:17 +0200
> 
> > Did you check that GC doesn't kick in when the "slow" saving happens?
> `benchmark-run` lets you know teh number of GC and the time used by them
> while running the form.  The reported slowliness was happening even
> without GC.
> I was curious if someone runnning opensuse Tumbleweed was seeing something similar.
> 
> I suspect this might be a problem of my OS (probably it was under heavy stress).
> Now I am in vacation, and the computer seems more relax (same like me).  I have also
> upgraded the OS and got a new kernel.
> 
> The following is data right now running this:
> emacs -Q /tmp/save-slow-buffer.txt
> ;; evaluate the following key binding:
> 
> (global-set-key (kbd "<f5>") (lambda () (interactive) (print
> (benchmark-run nil (save-buffer)) (current-buffer))))
> 
> ;; now push <f5> slowly several times
> ;; Still seems a bit slow sometimes (~0.1 s) but it is acceptable for my needs:

If it isn't GC, then my suggestion would be to run Emacs under 'perf'
and see what the profile tells us.

bug#42911: 28.0.50; write_region sometimes extremely very slow

[Tino Calancha]

Tino Calancha <tino.calancha@gmail.com> writes:

> Recipe:
> emacs -Q ~/save-buffer-slow.txt
> ;; insert few characters and run
> M-: (benchmark-run nil (save-buffer))
>
> ;; Repeat several times: sometimes it takes a reasonable time, but
> ;; in others it takes huge time
> ;; (6-10 s to save a buffer with less that 50 characters)

It has been almost a year since I reported this problem.
Since that time, I haven't seen this issue anymore.
Closing it.