Show timing for commands

racket/command-server.rkt

@@ -65,18 +65,18 @@
   (define response-channel (make-channel))
 
   (define (do-command/queue-response nonce sid sexp)
+    ;; Make "label" for logging. A thread name comes from its thunk ∴
+    ;; renaming the thunk lets us log the thread more informatively.
+    (define label (command-invocation-label nonce sid sexp))
     (define (thk)
       (channel-put
        response-channel
        (cons
         nonce
         (with-handlers ([exn:fail?  (λ (e) `(error ,(exn-message e)))]
                         [exn:break? (λ (e) `(break))])
-          `(ok ,(call-with-session-context sid command sexp))))))
-    ;; Make "label" for logging. A thread name comes from its thunk ∴
-    ;; renaming the thunk lets us log the thread more informatively.
-    (define label (command-invocation-label nonce sid sexp))
-    (log-racket-mode-info label)
+          (with-time/log label
+           `(ok ,(call-with-session-context sid command sexp)))))))
     (procedure-rename thk (string->symbol label)))
 
   (define (write-responses-forever)

racket/util.rkt

@@ -93,7 +93,7 @@
 (define (time-apply/log what proc args)
   (define-values (vs cpu real gc) (time-apply proc args))
   (define (fmt n) (~v #:align 'right #:min-width 4 n))
-  (log-racket-mode-debug "~a cpu | ~a real | ~a gc <= ~a"
+  (log-racket-mode-debug "~a cpu | ~a real | ~a gc :: ~a"
                          (fmt cpu) (fmt real) (fmt gc) what)
   (apply values vs))