(defpackage :slynk-profiler
(:use :cl)
(:import-from :slynk :defslyfun :from-string :to-string)
(:export #:toggle-timing
#:untime-spec
#:clear-timing-tree
#:untime-all
#:timed-spec-p
#:time-spec))
(in-package :slynk-profiler)
(defvar *timing-lock* (slynk-backend:make-lock :name "slynk-timings lock"))
(defvar *current-timing* nil)
(defvar *timed-spec-lists* (make-array 10
:fill-pointer 0
:adjustable t))
(defun started-timing ())
(defmethod timed-specs ()
(aref *timed-spec-lists* (1- (fill-pointer *timed-spec-lists*))))
(defmethod (setf timed-specs) (value)
(setf (aref *timed-spec-lists* (1- (fill-pointer *timed-spec-lists*))) value))
(defclass timing ()
((parent :reader parent-of :initform *current-timing* )
(origin :initarg :origin :reader origin-of
:initform (error "must provide an ORIGIN for this TIMING"))
(start :reader start-of :initform (get-internal-real-time))
(end :accessor end-of :initform nil)))
(defclass timed-spec ()
((spec :initarg :spec :accessor spec-of
:initform (error "must provide a spec"))
(stats :accessor stats-of)
(total :accessor total-of)
(subtimings :accessor subtimings-of)
(owntimings :accessor owntimings-of)))
(defun get-singleton-create (spec)
(let ((existing (find spec (timed-specs) :test #'equal :key #'spec-of)))
(if existing
(reinitialize-instance existing)
(let ((new (make-instance 'timed-spec :spec spec)))
(push new (timed-specs))
new))))
(defmethod shared-initialize :after ((ts timed-spec) slot-names &rest initargs)
(declare (ignore slot-names))
(setf (stats-of ts) (make-hash-table)
(total-of ts) 0
(subtimings-of ts) nil
(owntimings-of ts) nil)
(loop for otherts in (remove ts (timed-specs))
do (setf (gethash ts (stats-of otherts)) 0)
(setf (gethash otherts (stats-of ts)) 0)))
(defmethod initialize-instance :after ((tm timing) &rest initargs)
(declare (ignore initargs))
(push tm (owntimings-of (origin-of tm)))
(let ((parent (parent-of tm)))
(when parent
(push tm (subtimings-of (origin-of parent))))))
(defmethod (setf end-of) :after (value (tm timing))
(let* ((parent (parent-of tm))
(parent-origin (and parent (origin-of parent)))
(origin (origin-of tm))
(tm1 (pop (owntimings-of origin)))
(tm2 (and parent
(pop (subtimings-of parent-origin))))
(delta (- value (start-of tm))))
(assert (eq tm tm1) nil "Hmm something's gone wrong in the owns")
(assert (or (null tm2)
(eq tm tm2)) nil "Something's gone wrong in the subs")
(when (null (owntimings-of origin))
(incf (total-of origin) delta))
(when (and parent-origin
(null (subtimings-of parent-origin)))
(incf (gethash origin (stats-of parent-origin))
delta))))
(defmethod duration ((tm timing))
(/ (- (or (end-of tm)
(get-internal-real-time))
(start-of tm))
internal-time-units-per-second))
(defmethod print-object ((tm timing) stream)
(print-unreadable-object (tm stream :type t :identity t)
(format stream "~a: ~f~a"
(spec-of (origin-of tm))
(duration tm)
(if (not (end-of tm)) "(unfinished)" ""))))
(defmethod print-object ((e timed-spec) stream)
(print-unreadable-object (e stream :type t)
(format stream "~a ~fs" (spec-of e)
(/ (total-of e)
internal-time-units-per-second))))
(defslyfun time-spec (spec)
(when (timed-spec-p spec)
(warn "~a is apparently already timed! Untiming and retiming." spec)
(untime-spec spec))
(let ((timed-spec (get-singleton-create spec)))
(flet ((before-hook (args)
(declare (ignore args))
(setf *current-timing*
(make-instance 'timing :origin timed-spec)))
(after-hook (retlist)
(declare (ignore retlist))
(let* ((timing *current-timing*))
(when timing
(setf (end-of timing) (get-internal-real-time))
(setf *current-timing* (parent-of timing))))))
(slynk-backend:wrap spec 'timings
:before #'before-hook
:after #'after-hook)
(format nil "~a is now timed for timing dialog" spec))))
(defslyfun untime-spec (spec)
(slynk-backend:unwrap spec 'timings)
(let ((moribund (find spec (timed-specs) :test #'equal :key #'spec-of)))
(setf (timed-specs) (remove moribund (timed-specs)))
(loop for otherts in (timed-specs)
do (remhash moribund (stats-of otherts))))
(format nil "~a is now untimed for timing dialog" spec))
(defslyfun toggle-timing (spec)
(if (timed-spec-p spec)
(untime-spec spec)
(time-spec spec)))
(defslyfun timed-spec-p (spec)
(find spec (timed-specs) :test #'equal :key #'spec-of))
(defslyfun untime-all ()
(mapcar #'untime-spec (timed-specs)))
;;;; Reporting to emacs
;;;
(defun describe-timing-for-emacs (timed-spec)
(declare (ignore timed-spec))
`not-implemented)
(defslyfun report-latest-timings ()
(loop for spec in (timed-specs)
append (loop for partial being the hash-values of (stats-of spec)
for path being the hash-keys of (stats-of spec)
collect (list (slynk-api:slynk-pprint-to-line spec) partial
(slynk-api:slynk-pprint-to-line path)))))
(defun print-tree ()
(loop for ts in (timed-specs)
for total = (total-of ts)
do (format t "~%~a~%~%" ts)
(when (plusp total)
(loop for partial being the hash-values of (stats-of ts)
for path being the hash-keys of (stats-of ts)
when (plusp partial)
sum partial into total-partials
and
do (format t " ~8fs ~4f% ~a ~%"
(/ partial
internal-time-units-per-second)
(* 100 (/ partial
total))
(spec-of path))
finally
(format t " ~8fs ~4f% ~a ~%"
(/ (- total total-partials)
internal-time-units-per-second)
(* 100 (/ (- total total-partials)
total))
'other)))))
(defslyfun clear-timing-tree ()
(setq *current-timing* nil)
(loop for ts in (timed-specs)
do (reinitialize-instance ts)))
(provide :slynk/profiler)