diff --git a/collects/mred/private/wx/common/queue.rkt b/collects/mred/private/wx/common/queue.rkt index fab54e0f..546efb2c 100644 --- a/collects/mred/private/wx/common/queue.rkt +++ b/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 diff --git a/collects/scribblings/gui/win-overview.scrbl b/collects/scribblings/gui/win-overview.scrbl index a3585dd3..1ce753c0 100644 --- a/collects/scribblings/gui/win-overview.scrbl +++ b/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,