Timeout during background ESS command ?

[vspinu]

When I do C-c C-d C-e on a relatively large object I am getting Timeout during background ESS command (implemented in ee0266e)

I don't think 1s global default timeout is a good idea. "instantaneous" is a relative concept. It can easily span > 1 s on remote machines and it almost always spans > 1s for C-c C-d C-e

I think the default should be 30s. C-g should do the job and it's up to the developer to decide whether to use shorter delays. For eldoc completion, like the cause of #1062, it can be 1s indeed, but then some calls will never be cached, so no completion. Not ideal either.

Debugger entered--Lisp error: (error #("Timeout during background ESS command ‘str(jsons, ..." 43 48 (tb-index 10 fontified t)))
  signal(error (#("Timeout during background ESS command ‘str(jsons, ..." 43 48 (tb-index 10 fontified t))))
  error("Timeout during background ESS command `%s'" #("str(jsons, list.len=1000)" 4 9 (fontified t tb-index 10)))
  (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" (ess--strip-final-newlines cmd)))
  (if no-prompt-check (sleep-for 0.02) (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" (ess--strip-final-newlines cmd))) (goto-char (point-max)) (delete-region (point-at-bol) (point-max)))
  (save-current-buffer (set-buffer out-buffer) (ess-setq-vars-local proc-alist) (setq buffer-read-only nil) (erase-buffer) (set-marker (process-mark proc) (point-min)) (inferior-ess-mark-as-busy proc) (process-send-string proc rich-cmd) (if no-prompt-check (sleep-for 0.02) (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" (ess--strip-final-newlines cmd))) (goto-char (point-max)) (delete-region (point-at-bol) (point-max))))
  (progn (if use-sentinel (progn (process-put proc 'ess-output-sentinel sentinel))) (set-process-buffer proc out-buffer) (set-process-filter proc 'inferior-ess-ordinary-filter) (save-current-buffer (set-buffer out-buffer) (ess-setq-vars-local proc-alist) (setq buffer-read-only nil) (erase-buffer) (set-marker (process-mark proc) (point-min)) (inferior-ess-mark-as-busy proc) (process-send-string proc rich-cmd) (if no-prompt-check (sleep-for 0.02) (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" (ess--strip-final-newlines cmd))) (goto-char (point-max)) (delete-region (point-at-bol) (point-max)))) (setq early-exit nil))
  (unwind-protect (progn (if use-sentinel (progn (process-put proc 'ess-output-sentinel sentinel))) (set-process-buffer proc out-buffer) (set-process-filter proc 'inferior-ess-ordinary-filter) (save-current-buffer (set-buffer out-buffer) (ess-setq-vars-local proc-alist) (setq buffer-read-only nil) (erase-buffer) (set-marker (process-mark proc) (point-min)) (inferior-ess-mark-as-busy proc) (process-send-string proc rich-cmd) (if no-prompt-check (sleep-for 0.02) (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" (ess--strip-final-newlines cmd))) (goto-char (point-max)) (delete-region (point-at-bol) (point-max)))) (setq early-exit nil)) (if early-exit (progn (save-current-buffer (set-buffer out-buffer) (goto-char (point-min)) (if (and use-sentinel (not (re-search-forward ... nil t))) (progn (process-put proc 'ess-output-sentinel nil))) (goto-char (point-max)) (ess-interrupt)))) (process-put proc 'ess-output-sentinel nil) (set-process-buffer proc oldpb) (set-process-filter proc oldpf) (set-marker (process-mark proc) oldpm))
  (let ((proc-alist (list (cons 'ess-local-process-name ess-local-process-name) (cons 'inferior-ess-primary-prompt inferior-ess-primary-prompt))) (oldpb (process-buffer proc)) (oldpf (process-filter proc)) (oldpm (marker-position (process-mark proc))) (use-sentinel (alist-get 'use-sentinel ess-format-command-alist)) (rich-cmd (let* ((cmd-fun (and t (alist-get ... ess-format-command-alist)))) (if cmd-fun (funcall cmd-fun (ess--strip-final-newlines cmd) (cons 'output-sentinel sentinel)) cmd))) (early-exit t)) (ess-if-verbose-write (format "(ess-command %s ..)" cmd)) (unwind-protect (progn (if use-sentinel (progn (process-put proc 'ess-output-sentinel sentinel))) (set-process-buffer proc out-buffer) (set-process-filter proc 'inferior-ess-ordinary-filter) (save-current-buffer (set-buffer out-buffer) (ess-setq-vars-local proc-alist) (setq buffer-read-only nil) (erase-buffer) (set-marker (process-mark proc) (point-min)) (inferior-ess-mark-as-busy proc) (process-send-string proc rich-cmd) (if no-prompt-check (sleep-for 0.02) (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" (ess--strip-final-newlines cmd))) (goto-char (point-max)) (delete-region (point-at-bol) (point-max)))) (setq early-exit nil)) (if early-exit (progn (save-current-buffer (set-buffer out-buffer) (goto-char (point-min)) (if (and use-sentinel (not ...)) (progn (process-put proc ... nil))) (goto-char (point-max)) (ess-interrupt)))) (process-put proc 'ess-output-sentinel nil) (set-process-buffer proc oldpb) (set-process-filter proc oldpf) (set-marker (process-mark proc) oldpm)))
  (save-current-buffer (set-buffer (process-buffer proc)) (let ((proc-alist (list (cons 'ess-local-process-name ess-local-process-name) (cons 'inferior-ess-primary-prompt inferior-ess-primary-prompt))) (oldpb (process-buffer proc)) (oldpf (process-filter proc)) (oldpm (marker-position (process-mark proc))) (use-sentinel (alist-get 'use-sentinel ess-format-command-alist)) (rich-cmd (let* ((cmd-fun (and t ...))) (if cmd-fun (funcall cmd-fun (ess--strip-final-newlines cmd) (cons ... sentinel)) cmd))) (early-exit t)) (ess-if-verbose-write (format "(ess-command %s ..)" cmd)) (unwind-protect (progn (if use-sentinel (progn (process-put proc 'ess-output-sentinel sentinel))) (set-process-buffer proc out-buffer) (set-process-filter proc 'inferior-ess-ordinary-filter) (save-current-buffer (set-buffer out-buffer) (ess-setq-vars-local proc-alist) (setq buffer-read-only nil) (erase-buffer) (set-marker (process-mark proc) (point-min)) (inferior-ess-mark-as-busy proc) (process-send-string proc rich-cmd) (if no-prompt-check (sleep-for 0.02) (if (ess-wait-for-process proc nil wait force-redisplay timeout) nil (error "Timeout during background ESS command `%s'" ...)) (goto-char (point-max)) (delete-region (point-at-bol) (point-max)))) (setq early-exit nil)) (if early-exit (progn (save-current-buffer (set-buffer out-buffer) (goto-char (point-min)) (if (and use-sentinel ...) (progn ...)) (goto-char (point-max)) (ess-interrupt)))) (process-put proc 'ess-output-sentinel nil) (set-process-buffer proc oldpb) (set-process-filter proc oldpf) (set-marker (process-mark proc) oldpm))))
  (let ((out-buffer (or out-buffer (get-buffer-create " *ess-command-output*"))) (proc (ess-command--get-proc proc no-prompt-check)) (sentinel (inferior-ess--output-sentinel)) (timeout (or timeout 1))) (save-current-buffer (set-buffer (process-buffer proc)) (let ((proc-alist (list (cons 'ess-local-process-name ess-local-process-name) (cons 'inferior-ess-primary-prompt inferior-ess-primary-prompt))) (oldpb (process-buffer proc)) (oldpf (process-filter proc)) (oldpm (marker-position (process-mark proc))) (use-sentinel (alist-get 'use-sentinel ess-format-command-alist)) (rich-cmd (let* ((cmd-fun ...)) (if cmd-fun (funcall cmd-fun ... ...) cmd))) (early-exit t)) (ess-if-verbose-write (format "(ess-command %s ..)" cmd)) (unwind-protect (progn (if use-sentinel (progn (process-put proc ... sentinel))) (set-process-buffer proc out-buffer) (set-process-filter proc 'inferior-ess-ordinary-filter) (save-current-buffer (set-buffer out-buffer) (ess-setq-vars-local proc-alist) (setq buffer-read-only nil) (erase-buffer) (set-marker (process-mark proc) (point-min)) (inferior-ess-mark-as-busy proc) (process-send-string proc rich-cmd) (if no-prompt-check (sleep-for 0.02) (if ... nil ...) (goto-char ...) (delete-region ... ...))) (setq early-exit nil)) (if early-exit (progn (save-current-buffer (set-buffer out-buffer) (goto-char ...) (if ... ...) (goto-char ...) (ess-interrupt)))) (process-put proc 'ess-output-sentinel nil) (set-process-buffer proc oldpb) (set-process-filter proc oldpf) (set-marker (process-mark proc) oldpm)))) out-buffer)
  ess-command(#("str(jsons, list.len=1000)\n" 4 9 (fontified t tb-index 10)) #<buffer *ess-describe*>)
  (let* ((com (format (car (car-safe (prog1 ess--descr-o-a-p-commands (setq ess--descr-o-a-p-commands ...)))) objname)) (buf (get-buffer-create "*ess-describe*")) pos) (if (eq ess-describe-at-point-method 'tooltip) nil (display-buffer buf)) (sit-for 0.01) (ess-command (concat com "\n") buf) (save-current-buffer (set-buffer buf) (goto-char (point-min)) (insert (propertize (format "%s:\n\n" com) 'face 'font-lock-string-face)) (forward-line -1) (setq pos (point)) (special-mode) (let ((inhibit-read-only t)) (ansi-color-apply-on-region (point-min) (point-max)))) (if (eq ess-describe-at-point-method 'tooltip) (ess-tooltip-show-at-point (save-current-buffer (set-buffer buf) (buffer-string)) 0 30) (display-buffer buf) (set-window-point (get-buffer-window buf) pos) buf))
  ess--describe-object-at-point(5 jsons)
  funcall(ess--describe-object-at-point 5 jsons)
  (and command (funcall command ev objname))
  (setq out (and command (funcall command ev objname)))
  (if nil nil (setq out (and command (funcall command ev objname))))
  (if (not (or nil command)) (message "%s is undefined" (key-description (this-command-keys))) (if nil nil (setq out (and command (funcall command ev objname)))) (while (and (not exit) (setq command (lookup-key map (vector (setq ev (read-event ...)))))) (setq out (funcall command ev objname)) (sleep-for 0.01) (setq exit nil)) (if exit nil (setq unread-command-events (cons ev unread-command-events))) out)
  (let* ((ev last-command-event) (command (lookup-key map (vector ev))) out exit) (if (not (or nil command)) (message "%s is undefined" (key-description (this-command-keys))) (if nil nil (setq out (and command (funcall command ev objname)))) (while (and (not exit) (setq command (lookup-key map (vector (setq ev ...))))) (setq out (funcall command ev objname)) (sleep-for 0.01) (setq exit nil)) (if exit nil (setq unread-command-events (cons ev unread-command-events))) out))
  (let* ((inhibit-quit t) (buf (let* ((ev last-command-event) (command (lookup-key map (vector ev))) out exit) (if (not (or nil command)) (message "%s is undefined" (key-description (this-command-keys))) (if nil nil (setq out (and command ...))) (while (and (not exit) (setq command ...)) (setq out (funcall command ev objname)) (sleep-for 0.01) (setq exit nil)) (if exit nil (setq unread-command-events (cons ev unread-command-events))) out))) (keys (read-key-sequence-vector "")) (command (and keys (key-binding keys)))) (if (and (commandp command) (bufferp buf) (or (not (symbolp command)) (not (string-match "window" (symbol-name command))))) (progn (kill-buffer buf))) (setq unread-command-events (append keys unread-command-events)))
  (let ((map (make-sparse-keymap)) (objname (or (and (use-region-p) (buffer-substring-no-properties (point) (mark))) (ess-symbol-at-point))) ess--descr-o-a-p-commands) (if objname nil (error "No object at point ")) (define-key map (vector last-command-event) 'ess--describe-object-at-point) (let* ((inhibit-quit t) (buf (let* ((ev last-command-event) (command (lookup-key map ...)) out exit) (if (not (or nil command)) (message "%s is undefined" (key-description ...)) (if nil nil (setq out ...)) (while (and ... ...) (setq out ...) (sleep-for 0.01) (setq exit nil)) (if exit nil (setq unread-command-events ...)) out))) (keys (read-key-sequence-vector "")) (command (and keys (key-binding keys)))) (if (and (commandp command) (bufferp buf) (or (not (symbolp command)) (not (string-match "window" (symbol-name command))))) (progn (kill-buffer buf))) (setq unread-command-events (append keys unread-command-events))))
  (if (not ess-describe-object-at-point-commands) (message "Not implemented for dialect %s" ess-dialect) (ess-force-buffer-current) (let ((map (make-sparse-keymap)) (objname (or (and (use-region-p) (buffer-substring-no-properties (point) (mark))) (ess-symbol-at-point))) ess--descr-o-a-p-commands) (if objname nil (error "No object at point ")) (define-key map (vector last-command-event) 'ess--describe-object-at-point) (let* ((inhibit-quit t) (buf (let* ((ev last-command-event) (command ...) out exit) (if (not ...) (message "%s is undefined" ...) (if nil nil ...) (while ... ... ... ...) (if exit nil ...) out))) (keys (read-key-sequence-vector "")) (command (and keys (key-binding keys)))) (if (and (commandp command) (bufferp buf) (or (not (symbolp command)) (not (string-match "window" ...)))) (progn (kill-buffer buf))) (setq unread-command-events (append keys unread-command-events)))))
  ess-describe-object-at-point()

[vspinu]

Another example company-show-doc-buffer on an argument.

[vspinu]

Another error on C-c C-q and C-c C-e C-r when working with heavy loaded processes. These can can take a few seconds easily:

Timeout while interrupting process

[lionel-]

The idea is that all Emacs freezes should be considered bugs. So instead of setting a large timeout, two things should ideally happen:

1. Background command should be instantaneous and use a timeout of 2s.
2. Commands that are not instant should be implemented asynchronously and only lock up the inferior, not all of Emacs.

We currently have the infrastructure for (1) but not for (2). So I've been collecting the commands that should be implemented asynchronously with ess--foreground-command which uses ess-command with an infinite timeout for now. In the future, these commands can be refactored using a new asynchronous command (I think similar but different to ess-async-command because this one is queued, by comparison a foregound command is async but requires an available process which will become locked for further interaction until the async command has resolved - probably there will be a large overlap between these two kinds).

Because async commands will be callback-based, we can't use the ess-command API for this. That's why I think the latter is a more natural fit for the instantaneous background commands. My plan was to set a large timeout before release (like 30s as you proposed) but in the meantime the small timeout serves to map the usage of ess-command and identify the ones that should switch to the foreground API. Once we have the async API actually implemented, we'll be able to leave a small timeout for ess-command. So anything that is instant would be able to use the simpler non-callback API without any UI impact for the user, and anything else would use a callback API with UI impact (locking up the inferior or at least causing interactions to be queued).

[vspinu]

Ok, let's discuss further. But let's fix the default to inf for now. I am having serious issues. Can no longer start R processes with long startup times properly. They just freeze and ESS is not loaded properly. #1102 is almost surely related to this as well.

So I've been collecting the commands that should be implemented asynchronously with ess--foreground-command which uses ess-command with an infinite timeout for now.

I think doing the other way around is more natural: collect all time sensitive commands and set short timeout only for those, or do async. Leave all others to the backward compatible default. You never know who is using ess-command and how. Things might start breaking in third packages like org-mode and personal code of our users. Designers of the old code didn't envisage timeouts like these. Things can go wrongly in unexpected ways, particularly with chained commands.

Also designers of new code will have to consider timeouts, which complicates reasoning and implementation. I think we can do much better than timeouts. Async can also be used for time sensitive stuff.

Background command should be instantaneous and use a timeout of 2s.
2s is arbitrary, but ok. We can make it customizable and also different on remotes. But still, not a global default for all invocations of ess-command, only selected commands.

The idea is that all Emacs freezes should be considered bugs.

Yes and no. For most interactive commands I, as a user, expect them to take a bit (fetching stuff, display help, print etc). So it's ok to wait, and it is also ok to interrupt with C-g when output no longer needed or it's partial but enough. For instance C-c C-d C-e output can be very long, I would like to C-g and stop the printing (currently the printing continues to the R console, which is not ok, but well, you get the idea).

[lionel-]

Leave all others to the backward compatible default. You never know who is using ess-command and how. Things might start breaking in third packages like org-mode and personal code of our users. Designers of the old code didn't envisage timeouts like these. Things can go wrongly in unexpected ways, particularly with chained commands.

This is definitely what I was planning for this release. In the future we could switch ess-command to a small timeout or introduce new functions. This can be discussed at that time.

Yes and no. For most interactive commands I, as a user, expect them to take a bit (fetching stuff, display help, print etc). So it's ok to wait, and it is also ok to interrupt with C-g when output no longer needed or it's partial but enough. For instance C-c C-d C-e output can be very long, I would like to C-g and stop the printing (currently the printing continues to the R console, which is not ok, but well, you get the idea).

I guess it will be more productive to discuss this over an actual implementation of ess--foreground-command, so we can compare the two approaches with actual usage. So the ball is in my court for actually going through with this (but I plan to take a break from ESS after the release so that's long term).

In the short term here are our options:

1. Increase the timeout to a large value right away.
2. Switch the long commands to ess--foreground-command and only increase the timeout when we are done identifying these commands.

Both work for me. I think (2) would help me design the foreground command API when the time comes by making sure the approach works for all the collected use cases.

[vspinu]

This is definitely what I was planning for this release.

Got it. I really thought you insist on moving to 2s everywhere at once.

I think (2) would help me design the foreground command API when the time comes by making sure the approach works for all the collected use cases.

But this means breaking everyone else's ESS in the meanwhile :)

I guess it will be more productive to discuss this over an actual implementation of ess--foreground-command

Sure, but I am still a bit confused. Wouldn't it make sense to enhance the ess-command and keeping it as the backward compatible version of ess--foregrand-command but design a new "self-interrupting" ess-background-command with proper timeout implementation?

[lionel-]

But this means breaking everyone else's ESS in the meanwhile :)

Right it became apparent that longer timeouts were needed in several places as people updated their ESS and reported issues.

Wouldn't it make sense to enhance the ess-command and keeping it as the backward compatible version of ess--foregrand-command but design a new "self-interrupting" ess-background-command with proper timeout implementation?

If we keep ess-command as is with a big timeout, that means we'll encourage locking up the Emacs UI. I think it would be a good long term goal to encourage switching to an async API. I expect this will improve the user experience.

[vspinu]

If we keep ess-command as is with a big timeout, that means we'll encourage locking up the Emacs UI. I think it would be a good long term goal to encourage switching to an async API.

My uninformed estimate is that the large majority of user commands are expected (must?) be locking. I would say about 90/10% ratio. I also vaguely remember some other emacs IDEs to use large timeouts for sync commands by default. We can check, but I think this is largely the expected behavior on the developer side.

[vspinu]

For instance C-c C-d C-e output can be very long, I would like to C-g and stop the printing (currently the printing continues to the R console, which is not ok, but well, you get the idea).

I am very pleasantly surprised that this is no longer the case with your changes. So we no loner have output spilling to R console on C-g under any circumstance? That's pretty amazing!! How does it work in 2 words?

plan to take a break from ESS after the release so that's long term

Do you need us to catch up on your recent changes then? I am on a break myself, and it might take a while till I am fully back to full loop.

[lionel-]

Thanks! Summary of the ess-command mechanism:

• As before, output is accumulated in a buffer until a prompt. Any line that finishes with > is a prompt, like R> or browser>

• ess-command now generates a sentinel string for languages that support it (only R atm). If used, output is accumulated until the sentinel is detected. This makes it robust to output that looks like a prompt.

• On early exits of any kind on the Emacs side, an interrupt is sent to the process via ess-interrupt. The interrupt is blocking (we're waiting for the prompt/sentinel to show up) and has a timeout of 2 seconds. This is why we're no longer leaking output on interrupts.

• .ess.command() was introduced on the R side to deal with the sentinel, preserve .Last.value, manage active sinks so that output of background commands doesn't get sinked, and preserve browser sessions on interrupts.

  TODO: detect early exits on the R side and bubble those up as errors on the Emacs side. Should now be easy to implement. We probably want to track errors specially to propagate the error message. We could also propagate warnings and messages to the message buffer.

I suspect the sentinel approach will synergise well with the evaluation queue planned in #1017 and may allow us to simplify the treatement of async commands. With the sentinel we'll never pop the queue while an async command is running.

[lionel-]

Another important change is that we're now using the Rd AST to generate some aspects of the documentation (links) #1099. In the future it'd be nice to generate it solely from the AST.