add logging to mred's event callback mechanism to record

how long event processing takes

original commit: 7e8ac872fec52fecf84e4ec6d62989e2b9304605

collects/mred/private/wx/common/queue.rkt

@@ -438,12 +438,23 @@
 
 (define event-dispatch-handler (make-parameter really-dispatch-event))
 
+(define event-logger (make-logger 'gui-event (current-logger)))
+;; start? : boolean -- indicates if this is a start of an event being handled or not
+;; msec : start time if start? is #t, delta from start to end if start? is #f
+;; name : (or/c #f symbol?)
+(struct gui-event (start? msec name) #:prefab)
+
 (define (handle-event thunk e)
   (call-with-continuation-prompt ; to delimit continuations
    (lambda ()
      (call-with-continuation-prompt ; to delimit search for dispatch-event-key
       (lambda ()
         ;; communicate the thunk to `really-dispatch-event':
+        (define before (current-inexact-milliseconds))
+        (when (log-level? event-logger 'debug)
+          (log-message event-logger 'debug 
+                       "starting to handle an event"
+                       (gui-event #t before (object-name thunk))))
         (let ([b (box thunk)])
           ;; use the event-dispatch handler:
           (with-continuation-mark dispatch-event-key b
@@ -452,7 +463,13 @@
           ;; to the original one, then do so now:
           (when (unbox b)
             (set-box! b #f)
-            (thunk))))
+            (thunk)))
+        (define after (current-inexact-milliseconds))
+        (when (log-level? event-logger 'debug)
+          (log-message event-logger 'debug 
+                       (format "handled an event: ~a msec"  
+                               (- after before))
+                       (gui-event #f (- after before) (object-name thunk)))))
       dispatch-event-prompt))))
 
 (define yield

collects/scribblings/gui/win-overview.scrbl

@@ -951,6 +951,25 @@ Along similar lines, if a button callback captures a continuation
  captured during a button callback is therefore potentially useful
  outside of the same callback.
 
+@subsection{Logging}
+
+The GUI system logs the timing of when events are handled and how
+long they take to be handled. Each event that involves a callback
+into Racket code has two events logged, both of which use
+the @racket[gui-event] struct:
+@racketblock[(struct gui-event (start? msec name) #:prefab)]
+The @racket[start?] field is a boolean indicating if this
+event is logging the time when an event is starting to be handled,
+or when it finishes. In the case that @racket[start?] is @racket[#t],
+the @racket[msec] field is the result of
+@racket[current-inexact-milliseconds]; when @racket[start?] is @racket[#f],
+then the @racket[msec] field is the number of milliseconds that the
+event handling took (the difference between @racket[current-inexact-milliseconds]'s
+results before and after the handling). The @racket[name] field is
+the name of the function that handled the event; in the case of a
+@racket[queue-callback]-based event, it is the name of the thunk passed to
+@racket[queue-callback].
+
 @section[#:tag "animation"]{Animation in Canvases}
 
 The content of a canvas is buffered, so if a canvas must be redrawn,