profile.scm 54 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468146914701471147214731474147514761477147814791480148114821483148414851486148714881489149014911492149314941495149614971498149915001501150215031504150515061507150815091510151115121513151415151516151715181519152015211522152315241525152615271528152915301531153215331534153515361537153815391540154115421543154415451546154715481549155015511552155315541555155615571558155915601561156215631564156515661567156815691570157115721573157415751576157715781579158015811582158315841585158615871588158915901591159215931594159515961597159815991600160116021603160416051606160716081609161016111612161316141615161616171618161916201621162216231624162516261627162816291630163116321633163416351636163716381639164016411642164316441645164616471648164916501651165216531654165516561657165816591660166116621663166416651666166716681669167016711672167316741675167616771678167916801681168216831684168516861687168816891690169116921693169416951696169716981699170017011702170317041705170617071708170917101711171217131714171517161717171817191720172117221723172417251726172717281729173017311732
  1. ; Copyright (c) 1993-2008 by Richard Kelsey and Jonathan Rees. See file COPYING.
  2. ;;;;;; Rudimentary Scheme48 profiler -*- Scheme -*-
  3. ;;; Taylor Campbell wrote parts of the original code; he has placed them in the public domain.
  4. ;; profiling information for each template
  5. (define-record-type profinfo :profinfo
  6. (really-make-profinfo template callers occurs hist memoryuse min-pc instrumented cycle)
  7. profinfo?
  8. (template profinfo-template) ; scheme code template
  9. (callers profinfo-callers profinfo-set-callers!) ; table of callerinfos
  10. (occurs profinfo-occurs profinfo-set-occurs!)
  11. (hist profinfo-hist profinfo-set-hist!)
  12. (tchild profinfo-tchild profinfo-set-tchild!)
  13. (toporder profinfo-toporder profinfo-set-toporder!)
  14. (dfn profinfo-dfn profinfo-set-dfn!) ; depth-first number
  15. (cycle profinfo-cycle profinfo-set-cycle!)
  16. (memoryuse profinfo-memoryuse profinfo-set-memoryuse!)
  17. (min-pc profinfo-min-pc profinfo-set-min-pc!)
  18. (instrumented profinfo-instrumented? profinfo-set-instrumented?!))
  19. (define (make-profinfo prof-data template)
  20. (let ((pi (really-make-profinfo template
  21. (make-table profinfo-id)
  22. 0 0 0 #f #f #f)))
  23. (table-set! (profile-data-templates prof-data) template pi)
  24. pi))
  25. ;; profiling data for template when being called by CALLER
  26. (define-record-type callerinfo :callerinfo
  27. (make-callerinfo caller calls)
  28. callerinfo?
  29. (caller callerinfo-caller) ; caller profinfo
  30. (calls callerinfo-calls callerinfo-set-calls!) ; number of calls
  31. (tself callerinfo-tself callerinfo-set-tself!) ; time spent in called self
  32. (tchild callerinfo-tchild callerinfo-set-tchild!)) ; time spent in children of called
  33. ;;; Miscellaneous global stuff
  34. (define-record-type profile-data :profile-data
  35. (really-make-profile-data)
  36. (interrupttime profile-data-interrupttime set-profile-data-interrupttime!)
  37. (measure-noninstr? profile-data-measure-noninstr? set-profile-data-measure-noninstr?!)
  38. (starttime profile-data-starttime set-profile-data-starttime!)
  39. (endtime profile-data-endtime set-profile-data-endtime!)
  40. (root profile-data-root set-profile-data-root!)
  41. (cycles profile-data-cycles set-profile-data-cycles!)
  42. (samples profile-data-samples set-profile-data-samples!)
  43. (templates profile-data-templates set-profile-data-templates!)
  44. (memoryuse profile-data-memoryuse set-profile-data-memoryuse!)
  45. (gcruns profile-data-gcruns set-profile-data-gcruns!))
  46. ;; hash function for callers table in profiling information
  47. (define (profinfo-id pi)
  48. ; (template-id (profinfo-template pi)))
  49. 0)
  50. (define (make-empty-profile-data)
  51. (let ((pd (really-make-profile-data)))
  52. (set-profile-data-interrupttime! pd (profiler-default-interrupt-time))
  53. (set-profile-data-measure-noninstr?! pd (profiler-measure-non-instrumented?))
  54. (set-profile-data-memoryuse! pd 0)
  55. (set-profile-data-cycles! pd '())
  56. pd))
  57. (define-record-type cycleinfo :cycleinfo
  58. (make-cycleinfo number members)
  59. cycleinfo?
  60. (number cycleinfo-number) ; consecutive numbering
  61. (members cycleinfo-members cycleinfo-set-members!) ; member profinfos
  62. (tchild cycleinfo-tchild cycleinfo-set-tchild!)
  63. )
  64. ;; represents a stack entry (while profiling)
  65. (define-record-type stackentry :stackentry
  66. (really-make-stackentry cont template calls firstseen seen)
  67. stackentry?
  68. (cont stackentry-cont stackentry-set-cont!) ; scheme continuation
  69. (template stackentry-template stackentry-set-template!) ; scheme code template
  70. (calls stackentry-reccalls stackentry-set-reccalls!) ; recursive calls
  71. (firstseen stackentry-firstseen stackentry-set-firstseen!) ; run-time first seen this entry
  72. (seen stackentry-seen stackentry-set-seen!)) ; seen this time? (boolean)
  73. (define (make-stackentry cont template)
  74. (really-make-stackentry cont template 0 (run-time) #f))
  75. ;;; Global profiling stuff (independent of prof-data)
  76. (define *interrupt-time* #f) ; (theoretical) ms between interrupts
  77. (define *measure-noninstr?* #f)
  78. (define *saved-interrupt-handler* #f) ; non-profiler interrupt handler
  79. (define *profiler-continuation* #f) ; profiler's top continuation
  80. (define *profiler-lock* (make-lock)) ; exclusive lock for interrupt handler
  81. (define *profiler-lastrun* #f) ; run-time of profiler runs
  82. (define *profiler-thisrun* #f)
  83. (define *start-gc-count* 0)
  84. (define *last-gc-count* 0)
  85. (define *cur-gc-count* 0)
  86. (define *last-avail-memory* 0)
  87. (define *cur-avail-memory* 0)
  88. (define interrupt/alarm (enum interrupt alarm))
  89. (define *active-profile-data* #f)
  90. (define *first-call?* #f)
  91. ;;; Sampling interrupt time (with setting)
  92. (define *profiler-default-interrupt-time* 50)
  93. (define (positive-integer? n)
  94. (and (integer? n)
  95. (exact? n)
  96. (positive? n)))
  97. (define (profiler-default-interrupt-time)
  98. *profiler-default-interrupt-time*)
  99. (define (set-profiler-default-interrupt-time! interrupt-time)
  100. (set! *profiler-default-interrupt-time* interrupt-time))
  101. (add-setting 'profiler-interrupt-time positive-integer?
  102. profiler-default-interrupt-time
  103. set-profiler-default-interrupt-time!
  104. "profiler sampling interrupt time in milliseconds")
  105. ;;; Measure-non-instrumented? flag
  106. (define *profiler-measure-non-instrumented?* #t)
  107. (define (profiler-measure-non-instrumented?)
  108. *profiler-measure-non-instrumented?*)
  109. (define (set-profiler-measure-non-instrumented?! do?)
  110. (set! *profiler-measure-non-instrumented?* do?))
  111. (add-setting 'profiler-measure-noninstr #t
  112. profiler-measure-non-instrumented?
  113. set-profiler-measure-non-instrumented?!
  114. "profiler will measure calls to non-instrumented code"
  115. "profiler will only measure calls to instrumented code")
  116. ;;; Miscellaneous global stuff
  117. (define (run-time)
  118. (primitives:time (enum time-option run-time) #f))
  119. ;; debug display
  120. (define (ddisplay x)
  121. ; (display x)
  122. #f)
  123. (define (get-profinfo prof-data stack-entry)
  124. (if stack-entry
  125. (get-profinfo-from-template prof-data (stackentry-template stack-entry))
  126. #f))
  127. (define (profiler-continuation? cont)
  128. (eq? cont *profiler-continuation*))
  129. (define (get-profinfo-from-template prof-data template)
  130. (or (table-ref (profile-data-templates prof-data) template)
  131. (make-profinfo prof-data template)))
  132. (define (get-profinfo prof-data stack-entry)
  133. (if stack-entry
  134. (get-profinfo-from-template prof-data (stackentry-template stack-entry))
  135. #f))
  136. (define (get-template-name-and-modules prof-data template)
  137. (if (eq? template (profile-data-root prof-data))
  138. (cons '<profiler> '())
  139. (let ((ddata (template-debug-data template)))
  140. (if (not (and (debug-data? ddata)
  141. (pair? (debug-data-names ddata))))
  142. (cons (string-append "anonymous"
  143. (if (debug-data? ddata)
  144. (number->string (debug-data-uid ddata))
  145. (if (number? ddata)
  146. (number->string ddata)
  147. "?")))
  148. '())
  149. (let loop ((names (debug-data-names ddata))
  150. (lst '()))
  151. (set! lst (cons (or (car names) "anonymous") lst))
  152. (if (pair? (cdr names))
  153. (loop (cdr names) lst)
  154. (reverse lst)))))))
  155. (define (same-name? a b)
  156. (string=? (if (symbol? a)
  157. (symbol->string a)
  158. a)
  159. (if (symbol? b)
  160. (symbol->string b)
  161. b)))
  162. (define (profile-data-find prof-data names)
  163. (let ((found-lst '()))
  164. (table-walk
  165. (lambda (template pi)
  166. (let loop ((names names)
  167. (tempnames (get-template-name-and-modules prof-data template)))
  168. (if (string? names)
  169. ;; only string given, search match in path
  170. (if (pair? tempnames)
  171. (if (same-name? names (car tempnames))
  172. (set! found-lst (cons pi found-lst))
  173. (loop names (cdr tempnames))))
  174. ;; list of strings given, requires full path matching
  175. (if (not (pair? names))
  176. (set! found-lst (cons pi found-lst))
  177. (if (and (pair? tempnames)
  178. (same-name? (car names) (car tempnames)))
  179. (loop (cdr names) (cdr tempnames)))))))
  180. (profile-data-templates prof-data))
  181. found-lst))
  182. (define (do-for-first-matching fun prof-data names)
  183. (let ((pis (profile-data-find prof-data names)))
  184. (if (pair? pis)
  185. (fun (car pis)))))
  186. ;;; MAIN
  187. (define (profile command . interrupt-time)
  188. (profile-and-display (if (eq? (car command) 'run)
  189. (eval `(LAMBDA () ,(cadr command))
  190. (environment-for-commands))
  191. (lambda () (execute-command command)))
  192. interrupt-time
  193. (current-output-port)))
  194. (define (profile-and-display thunk
  195. interrupt-time
  196. port)
  197. (let ((prof-data (make-empty-profile-data)))
  198. (call-with-values
  199. (lambda ()
  200. (if (null? interrupt-time)
  201. (profile-thunk prof-data thunk)
  202. (profile-thunk prof-data thunk (car interrupt-time))))
  203. (lambda results
  204. (profile-display prof-data port)
  205. (set-command-results! results)))))
  206. (define (profile-thunk prof-data thunk . opt-args)
  207. (if (not (eq? (profile-data-samples prof-data)
  208. (primitives:unspecific)))
  209. (error 'profile-thunk
  210. "a profile-data record can be used only once"))
  211. (set! *interrupt-time* #f)
  212. (set! *measure-noninstr?* (primitives:unspecific))
  213. ;; optional arguments: interrupt-time ...
  214. (case (length opt-args)
  215. ((1) ; interrupt time
  216. (let ((int-time (car opt-args)))
  217. (set! *interrupt-time* int-time)))
  218. ((2) ; interrupt time with non-instr?
  219. (let ((int-time (car opt-args))
  220. (non-instr? (cadr opt-args)))
  221. (set! *interrupt-time* int-time)
  222. (set! *measure-noninstr?* non-instr?)))
  223. )
  224. ;; profile-data interrupt time, if not set
  225. (if (not *interrupt-time*)
  226. (set! *interrupt-time* (profile-data-interrupttime prof-data)))
  227. ;; profile-data measure-noninstr?, if not set
  228. (if (eq? *measure-noninstr?* (primitives:unspecific))
  229. (set! *measure-noninstr?* (profile-data-measure-noninstr? prof-data)))
  230. (if *profiler-continuation*
  231. (error
  232. 'profile-thunk
  233. "profiler can not be running twice at the same time" thunk)
  234. (begin
  235. (set! *active-profile-data* prof-data)
  236. (set! *first-call?* #t)
  237. (set! *last-stack* #f)
  238. (set! *profiler-thisrun* #f)
  239. (set! *profiler-lastrun* #f)
  240. (set! *last-avail-memory* (available-memory))
  241. (set! *start-gc-count* (get-current-gc-count))
  242. (set! *last-gc-count* *start-gc-count*)
  243. (release-lock *profiler-lock*)
  244. ;; init profile-data
  245. (set-profile-data-templates! prof-data (make-table template-id))
  246. (set-profile-data-samples! prof-data 0)
  247. (set-profile-data-starttime! prof-data (run-time))
  248. (set-profile-data-interrupttime! prof-data *interrupt-time*)
  249. ;; this is more flexible than generating a own template
  250. (primitive-cwcc
  251. (lambda (cont)
  252. (set-profile-data-root! prof-data
  253. (continuation-template cont))))
  254. (call-with-values
  255. (lambda ()
  256. (dynamic-wind
  257. (lambda ()
  258. (install-profiler-interrupt-handler)
  259. (start-periodic-interrupts!))
  260. (lambda ()
  261. (primitive-cwcc
  262. (lambda (profiler-cont)
  263. (set! *profiler-continuation* profiler-cont)
  264. (thunk)))) ; run program!
  265. (lambda ()
  266. (set! *profiler-continuation* #f)
  267. (stop-periodic-interrupts!)
  268. (uninstall-profiler-interrupt-handler)
  269. (set-profile-data-endtime! prof-data (run-time))
  270. (set-profile-data-gcruns! prof-data (- (get-current-gc-count) *start-gc-count*))
  271. (post-process-stack! prof-data *last-stack*) ; process the last stack trace
  272. ;; do necessary calculations
  273. (remove-uncalled prof-data)
  274. (depth-numbering prof-data)
  275. (propagate-times prof-data)
  276. (toporder-numbering prof-data)
  277. (set! *active-profile-data* #f))))
  278. (lambda results
  279. (apply values results))))))
  280. ;;; INTERRUPT HANDLING
  281. (define (start-periodic-interrupts!)
  282. (schedule-interrupt *interrupt-time*))
  283. (define (stop-periodic-interrupts!)
  284. (schedule-interrupt 0))
  285. (define (install-profiler-interrupt-handler)
  286. (set! *saved-interrupt-handler* (get-interrupt-handler interrupt/alarm))
  287. (set-interrupt-handler! interrupt/alarm handle-profiler-interrupt))
  288. (define (uninstall-profiler-interrupt-handler)
  289. (let ((handler *saved-interrupt-handler*))
  290. (set! *saved-interrupt-handler* #f)
  291. (set-interrupt-handler! interrupt/alarm handler)))
  292. (define (handle-profiler-interrupt template enabled)
  293. ;; After Scheme48 1.0's architectural changes TEMPLATE argument has
  294. ;; always been just #f.
  295. ;; first thing is getting the continuation, in tail position to prevent
  296. ;; capturing profiler functions
  297. (primitive-cwcc
  298. (lambda (cont)
  299. (if (maybe-obtain-lock *profiler-lock*)
  300. (begin
  301. (*saved-interrupt-handler* template enabled) ; thread system, ...
  302. (if *profiler-continuation* (record-continuation! *active-profile-data* cont))
  303. (release-lock *profiler-lock*)
  304. ;; HACK: To override thread system interrupt scheduling, may cause
  305. ;; extreme performance loss on thread system?
  306. (start-periodic-interrupts!))))))
  307. ;;; DISPLAY DATA
  308. ;; display s right-aligned in field with width w
  309. (define (display-w s w port)
  310. (if (< (string-length s) w)
  311. (begin
  312. (display " " port)
  313. (display-w s (- w 1) port))
  314. (display s port)))
  315. ;; display number right-aligned in field with width w
  316. (define (display-w-nr n w port)
  317. (if n
  318. (display-w (number->string (round n)) w port)
  319. (display-w "?" w port)))
  320. ;; same as above, but do not display 0 values
  321. (define (display-w-nr-nz n w port)
  322. (if (= n 0)
  323. (display-w "" w port)
  324. (display-w-nr n w port)))
  325. (define (display-w-mem n w port)
  326. (if (> n 1000000000)
  327. (display-w (string-append (number->string (round (/ n 1000000))) "M") w port)
  328. (display-w (string-append (number->string (round (/ n 1000))) "k") w port)))
  329. (define (display-sep-nrs nr1 nr2 sep w port)
  330. (display-w
  331. (string-append (number->string nr1) sep (number->string nr2))
  332. w
  333. port))
  334. (define (display-sep-unequal-nrs nr1 nr2 sep w port)
  335. (display-w
  336. (if (= nr1 nr2)
  337. (number->string nr1)
  338. (string-append (number->string nr1) sep (number->string nr2)))
  339. w
  340. port))
  341. (define (display-sep-nz-nrs nr1 nr2 sep w port)
  342. (display-w
  343. (if (> nr2 0)
  344. (string-append (number->string nr1) sep (number->string nr2))
  345. (number->string nr1))
  346. w
  347. port))
  348. ;; Are there no functions for this!?
  349. (define (number-as-percent-string nr)
  350. (if nr
  351. (let* ((expanded (truncate (* 10000 nr)))
  352. (afterdot (round (inexact->exact (modulo expanded 100))))
  353. (full (round (inexact->exact (quotient (- expanded afterdot) 100)))))
  354. (string-append (number->string full)
  355. "."
  356. (number->string afterdot)
  357. "%"))
  358. "?"))
  359. (define (save/ a b)
  360. (if (= b 0)
  361. #f
  362. (/ a b)))
  363. (define (parse-port-arg opt-port)
  364. (if (null? opt-port)
  365. (current-output-port)
  366. (car opt-port)))
  367. (define (has-samples prof-data)
  368. (> (profile-data-samples prof-data) 0))
  369. (define (profile-display prof-data . opt-port)
  370. (let ((port (parse-port-arg opt-port)))
  371. (profile-display-overview prof-data port)
  372. (newline port)
  373. (profile-display-flat prof-data port)
  374. (newline port)
  375. (profile-display-tree prof-data port)))
  376. ;; general profiling data
  377. (define (profile-display-overview prof-data . opt-port)
  378. (let ((port (parse-port-arg opt-port))
  379. (run-time (profile-data-runtime prof-data))
  380. (samples (profile-data-samples prof-data)))
  381. (display "** Samples: " port)
  382. (display samples port)
  383. (if (has-samples prof-data)
  384. (begin
  385. (display " (approx. one per " port)
  386. (display (round (/ run-time samples)) port)
  387. (display "ms)")))
  388. (newline port)
  389. (display "** Interrupt time: " port)
  390. (display *interrupt-time* port)
  391. (display "ms" port)
  392. (newline port)
  393. (display "** Real run time: " port)
  394. (display run-time port)
  395. (display "ms" port)
  396. (newline port)
  397. (if (has-samples prof-data)
  398. (begin
  399. (display "** Total memory: " port)
  400. (display (round (/ (profile-data-memoryuse prof-data) 1000)) port)
  401. (display "k" port)
  402. (newline port)
  403. (display "** GC runs: " port)
  404. (display (profile-data-gcruns prof-data) port)
  405. (newline port)))))
  406. (define (profile-display-flat prof-data . opt-port)
  407. (let ((port (parse-port-arg opt-port)))
  408. (display "** Flat result (times in ms):" port)
  409. (newline port)
  410. (newline port)
  411. ;; gprof:
  412. ;; % cumulative self self total
  413. ;; time seconds seconds calls ms/call ms/call name
  414. (if (has-samples prof-data)
  415. (begin
  416. (display-w "time" 7 port)
  417. (display-w "cumu" 7 port)
  418. (display-w "self" 7 port)
  419. (display-w "mem" 10 port)))
  420. (display-w "calls" 14 port)
  421. (display-w "ms/call" 9 port)
  422. (display-w "name" 7 port)
  423. (newline port)
  424. ;; sort and print
  425. (let ((sorted-templates
  426. (get-sorted-templates prof-data (lambda (pi) (- (profinfo-hist pi))) #t)))
  427. (for-each (lambda (profinfo)
  428. (profile-display-profinfo-flat prof-data profinfo port))
  429. sorted-templates))))
  430. ;; display data "gprof call graph"-like
  431. (define (profile-display-tree prof-data . opt-port)
  432. (let ((port (parse-port-arg opt-port))
  433. (cycles (profile-data-cycles prof-data)))
  434. (display "** Tree result (times in ms):" port)
  435. (newline port)
  436. (newline port)
  437. (display-w "i" 3 port)
  438. (if (has-samples prof-data)
  439. (begin
  440. (display-w "time" 8 port)
  441. (display-w "self" 7 port)
  442. (display-w "child" 7 port)
  443. (display-w "mem" 10 port)))
  444. (display-w "calls" 14 port)
  445. (display-w "name" 7 port)
  446. (newline port)
  447. ;; sort and print
  448. (let ((sorted-templates
  449. (get-sorted-templates prof-data (lambda (pi) (- (profinfo-occurs pi))) #t)))
  450. (for-each (lambda (profinfo)
  451. (profile-display-profinfo-tree prof-data profinfo port))
  452. sorted-templates))
  453. (if cycles
  454. (for-each (lambda (cyc)
  455. (profile-display-cycle-tree prof-data cyc port))
  456. cycles))))
  457. (define (profile-function-calls prof-data names)
  458. (do-for-first-matching profinfo-total-calls prof-data names))
  459. (define (profile-function-reccalls prof-data names)
  460. (do-for-first-matching profinfo-total-reccalls prof-data names))
  461. (define (profile-function-nonreccalls prof-data names)
  462. (do-for-first-matching profinfo-total-nonreccalls prof-data names))
  463. (define (profile-function-occurs prof-data names)
  464. (do-for-first-matching profinfo-occurs prof-data names))
  465. (define (profile-function-hist prof-data names)
  466. (do-for-first-matching profinfo-hist prof-data names))
  467. (define (profile-function-memoryuse prof-data names)
  468. (do-for-first-matching profinfo-memoryuse prof-data names))
  469. (define (profile-function-timeshare prof-data names)
  470. (do-for-first-matching (lambda (pi) (profinfo-timeshare prof-data pi)) prof-data names))
  471. (define (profile-function-time-cumulative prof-data names)
  472. (do-for-first-matching (lambda (pi) (profinfo-total-ms prof-data pi)) prof-data names))
  473. (define (profile-function-time-self prof-data names)
  474. (do-for-first-matching (lambda (pi) (profinfo-self-ms prof-data pi)) prof-data names))
  475. (define (profile-display-function-flat prof-data names . opt-port)
  476. (let ((port (parse-port-arg opt-port))
  477. (pis (profile-data-find prof-data names)))
  478. (for-each (lambda (pi)
  479. (profile-display-profinfo-flat prof-data pi port))
  480. pis)))
  481. (define (profile-display-profinfo-flat prof-data profinfo port)
  482. (let* ((template (profinfo-template profinfo))
  483. (occurs (profinfo-occurs profinfo))
  484. (calls (profinfo-total-calls profinfo))
  485. (reccalls (profinfo-total-reccalls profinfo))
  486. (nonreccalls (profinfo-total-nonreccalls profinfo))
  487. (hist (profinfo-hist profinfo))
  488. (memuse (profinfo-memoryuse profinfo))
  489. (timeshare (profinfo-timeshare prof-data profinfo))
  490. (ttotal (profinfo-total-ms prof-data profinfo))
  491. (tself (profinfo-self-ms prof-data profinfo))
  492. (ms/call (save/ (occurs->ms prof-data occurs) calls)))
  493. (if (not (eq? template (profile-data-root prof-data)))
  494. (begin
  495. (if (has-samples prof-data)
  496. (begin
  497. (display-w (number-as-percent-string timeshare) 7 port)
  498. (display-w-nr ttotal 7 port)
  499. (display-w-nr tself 7 port)
  500. (display-w-mem memuse 10 port)))
  501. (display-sep-nz-nrs nonreccalls reccalls "+" 14 port)
  502. (display-w-nr ms/call 9 port)
  503. (display " " port)
  504. (display-location prof-data template port) ; name
  505. (newline port)
  506. ))))
  507. (define (profile-display-function-cycle prof-data names . opt-port)
  508. (let ((port (parse-port-arg opt-port))
  509. (pis (profile-data-find prof-data names)))
  510. (for-each (lambda (pi)
  511. (let ((ci (profinfo-cycle pi)))
  512. (if ci
  513. (profile-display-cycle-tree prof-data ci port))))
  514. pis)))
  515. (define (profile-display-cycle-tree prof-data cycleinfo port)
  516. (let* ((number (cycleinfo-number cycleinfo))
  517. (members (cycleinfo-members cycleinfo))
  518. (callers (cycleinfo-called-from cycleinfo))
  519. (intcalls (cycleinfo-internal-calls cycleinfo))
  520. (extcalls (cycleinfo-external-calls cycleinfo))
  521. (hist (cycleinfo-hist cycleinfo))
  522. (tchild (cycleinfo-tchild cycleinfo))
  523. (memuse (cycleinfo-memoryuse cycleinfo))
  524. (fromextcalls (sumup-calls-int/ext-cycle cycleinfo #f))
  525. (ttotal (+ hist tchild))
  526. (timeshare (save/ ttotal (profile-data-samples prof-data))))
  527. (display "=============================================" port)
  528. (display "=============================================" port)
  529. (newline port)
  530. ;; print cycle callers
  531. (for-each
  532. (lambda (caller-pi)
  533. (let* ((calls (cycleinfo-calls-from cycleinfo caller-pi))
  534. (share (/ calls fromextcalls))
  535. (tchild (* tchild share))
  536. (memuse (* memuse share)))
  537. (display-w "" 3 port)
  538. (if (has-samples prof-data)
  539. (begin
  540. (display-w "" 8 port)
  541. (display-w-nr (occurs->ms prof-data hist) 7 port)
  542. (display-w-nr (occurs->ms prof-data tchild) 7 port)
  543. (display-w-mem memuse 10 port)))
  544. (display-sep-nz-nrs calls fromextcalls "/" 14 port)
  545. (display " " port)
  546. (display-profinfo-name prof-data caller-pi port)
  547. (newline port)))
  548. callers)
  549. ;; print primary line
  550. (display-w-nr number 3 port)
  551. (if (has-samples prof-data)
  552. (begin
  553. (display-w (number-as-percent-string timeshare) 8 port)
  554. (display-w-nr (occurs->ms prof-data hist) 7 port)
  555. (display-w-nr (occurs->ms prof-data tchild) 7 port)
  556. (display-w-mem memuse 10 port)))
  557. (display-sep-nz-nrs extcalls intcalls "+" 14 port)
  558. (display " " port)
  559. (display "<cycle " port)
  560. (display number port)
  561. (display " as a whole>" port)
  562. (newline port)
  563. ;; print cycle members
  564. (for-each
  565. (lambda (member-pi)
  566. (let* ((intcalls (calls-int/ext-cycle cycleinfo member-pi #t))
  567. (nonreccalls (profinfo-total-nonreccalls member-pi))
  568. (totalmemuse (profinfo-memoryuse member-pi))
  569. (occurs (profinfo-occurs member-pi))
  570. (hist (profinfo-hist member-pi))
  571. (tchild (cycleinfo-tchild-member prof-data cycleinfo member-pi))
  572. (share (/ intcalls nonreccalls))
  573. (memuse (* totalmemuse share)))
  574. (display-w "" 3 port)
  575. (if (has-samples prof-data)
  576. (begin
  577. (display-w "" 8 port)
  578. (display-w-nr (occurs->ms prof-data hist) 7 port)
  579. (display-w-nr (occurs->ms prof-data tchild) 7 port)
  580. (display-w-mem memuse 10 port)))
  581. (display-w-nr intcalls 14 port)
  582. (display " " port)
  583. (display-profinfo-name prof-data member-pi port)
  584. (newline port)))
  585. members)
  586. ;; print functions called out of the cycle
  587. (for-each
  588. (lambda (called-pi)
  589. (let* ((nonreccalls (profinfo-total-nonreccalls called-pi))
  590. (totalmemuse (profinfo-memoryuse called-pi))
  591. (calls (cycleinfo-calls-to cycleinfo called-pi))
  592. (share (/ calls nonreccalls))
  593. (memuse (* totalmemuse share)))
  594. (display-w "" 3 port)
  595. (if (has-samples prof-data)
  596. (begin
  597. (display-w "" 8 port)
  598. (display-w-nr 0 7 port)
  599. (display-w-nr 0 7 port)
  600. (display-w-mem memuse 10 port)))
  601. (display-sep-nrs calls nonreccalls "/" 14 port)
  602. (display " " port)
  603. (display-profinfo-name prof-data called-pi port)
  604. (newline port)))
  605. (cycleinfo-called-externals prof-data cycleinfo))))
  606. (define (profile-display-function-tree prof-data names . opt-port)
  607. (let ((port (parse-port-arg opt-port))
  608. (pis (profile-data-find prof-data names)))
  609. (for-each (lambda (pi)
  610. (profile-display-profinfo-tree prof-data pi port))
  611. pis)))
  612. (define (profile-display-profinfo-tree prof-data primary-pi port)
  613. (let* ((template (profinfo-template primary-pi))
  614. (toporder (profinfo-toporder primary-pi))
  615. (dfn (profinfo-dfn primary-pi))
  616. (callers (profinfo-callers primary-pi))
  617. (occurs (profinfo-occurs primary-pi))
  618. (calls (profinfo-total-calls primary-pi))
  619. (reccalls (profinfo-total-reccalls primary-pi))
  620. (nonreccalls (profinfo-total-nonreccalls primary-pi))
  621. (memuse (profinfo-memoryuse primary-pi))
  622. (upcalls (profinfo-total-upcalls primary-pi))
  623. (hist (profinfo-hist primary-pi))
  624. (tchild (profinfo-tchild primary-pi))
  625. (primary-cyc (profinfo-cycle primary-pi))
  626. (timeshare (save/ occurs (profile-data-samples prof-data)))
  627. (ms/call (save/ (occurs->ms prof-data occurs) calls)))
  628. (display "=============================================" port)
  629. (display "=============================================" port)
  630. (newline port)
  631. ;; print parents
  632. (if (= (table-size callers) 0)
  633. (if (not (eq? template (profile-data-root prof-data)))
  634. (begin (display-w " " 49 port) (display " <spontaneous>" port) (newline)))
  635. (table-walk
  636. (lambda (caller-pi cinfo)
  637. (if (not (eq? caller-pi primary-pi))
  638. (let* ((template (profinfo-template caller-pi))
  639. (dfn (profinfo-dfn caller-pi))
  640. (occurs (profinfo-occurs caller-pi))
  641. (caller-cyc (profinfo-cycle caller-pi))
  642. (calls (callerinfo-calls cinfo))
  643. (share (/ calls upcalls))
  644. (tself-share (* hist share)) ; TODO: correct when recursive function?
  645. (tchild-share (* tchild share))
  646. (memuse-share (* memuse share)))
  647. (display-w "" 3 port)
  648. (if (has-samples prof-data)
  649. (begin
  650. (display-w "" 8 port)
  651. (if (or (not primary-cyc)
  652. (not (eq? caller-cyc primary-cyc)))
  653. (begin
  654. (display-w-nr (occurs->ms prof-data tself-share) 7 port)
  655. (display-w-nr (occurs->ms prof-data tchild-share) 7 port)
  656. (display-w-mem memuse-share 10 port))
  657. (begin
  658. (display-w "" 7 port)
  659. (display-w "" 7 port)
  660. (display-w "" 10 port)))))
  661. (display-sep-nrs calls nonreccalls "/" 14 port)
  662. (display " " port)
  663. (display-profinfo-name prof-data caller-pi port)
  664. (newline port))))
  665. callers))
  666. ;; print primary line
  667. (display-w-nr toporder 3 port)
  668. (if (has-samples prof-data)
  669. (begin
  670. (display-w (number-as-percent-string timeshare) 8 port)
  671. (display-w-nr (occurs->ms prof-data hist) 7 port)
  672. (display-w-nr (occurs->ms prof-data tchild) 7 port)
  673. (display-w-mem memuse 10 port)))
  674. (display-sep-nz-nrs nonreccalls reccalls "+" 14 port)
  675. (display " " port)
  676. (display-profinfo-name prof-data primary-pi port)
  677. (newline port)
  678. ;; print children
  679. (for-each
  680. (lambda (called-pi)
  681. (if (not (eq? called-pi primary-pi))
  682. (let* ((template (profinfo-template called-pi))
  683. (dfn (profinfo-dfn called-pi))
  684. (occurs (profinfo-occurs called-pi))
  685. (calls (number-of-calls primary-pi called-pi))
  686. (nonreccalls (profinfo-total-nonreccalls called-pi))
  687. (upcalls (profinfo-upcalls primary-pi called-pi))
  688. (hist (profinfo-hist called-pi))
  689. (tchild (profinfo-tchild called-pi))
  690. (called-cyc (profinfo-cycle called-pi))
  691. (memuse (profinfo-memoryuse called-pi))
  692. (share (/ calls upcalls))
  693. (tself-share (* hist share)) ; TODO: correct when recursive function?
  694. (tchild-share (* tchild share))
  695. (memuse-share (* memuse share)))
  696. (display-w "" 3 port)
  697. (if (has-samples prof-data)
  698. (begin
  699. (display-w "" 8 port)
  700. (if (or (not called-cyc)
  701. (not (eq? called-cyc primary-cyc)))
  702. (begin
  703. (display-w-nr (occurs->ms prof-data tself-share) 7 port)
  704. (display-w-nr (occurs->ms prof-data tchild-share) 7 port)
  705. (display-w-mem memuse-share 10 port))
  706. (begin
  707. (display-w "" 7 port)
  708. (display-w "" 7 port)
  709. (display-w "" 10 port)))))
  710. (display-sep-nrs calls nonreccalls "/" 14 port)
  711. (display " " port)
  712. (display-profinfo-name prof-data called-pi port)
  713. (newline port))))
  714. (profinfo-calls prof-data primary-pi))))
  715. ;; displays functionname and file of a code template
  716. (define (display-location prof-data template port)
  717. (let loop ((names (get-template-name-and-modules prof-data template)))
  718. (if (string? (car names)) (display "\"" port))
  719. (display (car names) port)
  720. (if (string? (car names)) (display "\"" port))
  721. (if (pair? (cdr names))
  722. (begin (display " in " port)
  723. (loop (cdr names))))))
  724. (define (display-profinfo-name prof-data pi port)
  725. (let* ((template (profinfo-template pi))
  726. (ton (profinfo-toporder pi))
  727. (cyc (profinfo-cycle pi)))
  728. (display-location prof-data template port)
  729. (if cyc
  730. (begin
  731. (display " <cycle " port)
  732. (display (cycleinfo-number cyc))
  733. (display ">" port)))
  734. (display " [" port)
  735. (display ton port)
  736. (display "]" port)))
  737. ;;; useful stuff
  738. (define (memq? x l)
  739. (let loop ((l l))
  740. (cond ((null? l) #f)
  741. ((eq? x (car l)) #t)
  742. (else (loop (cdr l))))))
  743. (define (remove-duplicates list)
  744. (do ((list list (cdr list))
  745. (res '() (if (memq? (car list) res)
  746. res
  747. (cons (car list) res))))
  748. ((null? list)
  749. res)))
  750. ;;; DATA CALCULATION
  751. (define (occurs->ms prof-data occs)
  752. (if (has-samples prof-data)
  753. (round (/ (* occs (profile-data-runtime prof-data))
  754. (profile-data-samples prof-data)))
  755. 0))
  756. (define (profile-data-runtime prof-data)
  757. (let ((st (profile-data-starttime prof-data))
  758. (et (profile-data-endtime prof-data)))
  759. (if (or (eq? st (primitives:unspecific))
  760. (eq? et (primitives:unspecific)))
  761. (primitives:unspecific)
  762. (- et st))))
  763. ;;; cycle stuff
  764. (define (make-new-cycleinfo prof-data)
  765. (let ((new (make-cycleinfo (length (profile-data-cycles prof-data)) '())))
  766. new))
  767. (define (cycleinfo-add prof-data ci)
  768. (if (not (memq? ci (profile-data-cycles prof-data)))
  769. (set-profile-data-cycles! prof-data (cons ci (profile-data-cycles prof-data)))))
  770. (define (cycleinfo-add-member ci member)
  771. (let ((members (cycleinfo-members ci)))
  772. (if (not (memq? member members))
  773. (cycleinfo-set-members! ci (cons member members)))))
  774. ;; is profinfo a member of cycle ci?
  775. (define (cycleinfo-member? ci profinfo)
  776. (memq? profinfo
  777. (cycleinfo-members ci)))
  778. (define (cycleinfo-foreach-member ci f)
  779. (for-each f (cycleinfo-members ci)))
  780. ;; number of calls to function called-pi from cycle or from outside of cycle
  781. (define (calls-int/ext-cycle ci called-pi internal)
  782. (let ((cnt-calls 0)
  783. (caller-list (profinfo-callers called-pi)))
  784. (table-walk (lambda (caller-pi cinfo)
  785. (if (and (eq? (cycleinfo-member? ci caller-pi)
  786. internal)
  787. (not (eq? caller-pi called-pi)))
  788. (set! cnt-calls (+ cnt-calls (callerinfo-calls cinfo)))))
  789. caller-list)
  790. cnt-calls))
  791. ;; sum up internal calls of the cycle or calls from outside into the cycle
  792. (define (sumup-calls-int/ext-cycle ci internal)
  793. (let ((cnt-calls 0))
  794. (cycleinfo-foreach-member
  795. ci
  796. (lambda (member-pi)
  797. (set! cnt-calls (+ cnt-calls (calls-int/ext-cycle ci member-pi internal)))))
  798. cnt-calls))
  799. ;; calls done in the cycle internally
  800. (define (cycleinfo-internal-calls ci)
  801. (sumup-calls-int/ext-cycle ci #t))
  802. ;; calls done from outside into the cycle
  803. (define (cycleinfo-external-calls ci)
  804. (sumup-calls-int/ext-cycle ci #f))
  805. ;; time spent in the functions of the cycle itself
  806. (define (cycleinfo-hist ci)
  807. (let ((tt 0))
  808. (cycleinfo-foreach-member
  809. ci
  810. (lambda (pi)
  811. (set! tt (+ tt (profinfo-hist pi)))))
  812. tt))
  813. (define (cycleinfo-memoryuse ci)
  814. (let ((tt 0))
  815. (cycleinfo-foreach-member
  816. ci
  817. (lambda (pi)
  818. (set! tt (+ tt (profinfo-memoryuse pi)))))
  819. tt))
  820. ;; list of function profinfos the called cycle ci
  821. (define (cycleinfo-called-from ci)
  822. (let ((lst '()))
  823. (cycleinfo-foreach-member
  824. ci
  825. (lambda (member-pi)
  826. (let ((caller-list (profinfo-callers member-pi)))
  827. ;; add share of every function called from this cycle-function to total
  828. (table-walk (lambda (caller-pi cinfo)
  829. (if (and (not (cycleinfo-member? ci caller-pi))
  830. (not (memq? caller-pi lst)))
  831. (set! lst (cons caller-pi lst))))
  832. caller-list))))
  833. lst))
  834. ;; list of function profinfos called from cycle ci
  835. (define (cycleinfo-called-externals prof-data ci)
  836. (let ((lst '()))
  837. (cycleinfo-foreach-member
  838. ci
  839. (lambda (member-pi)
  840. (let ((called-list (profinfo-calls prof-data member-pi)))
  841. ;; add share of every function called from this cycle-function to total
  842. (for-each (lambda (called-pi)
  843. (if (and (not (cycleinfo-member? ci called-pi))
  844. (not (memq? called-pi lst)))
  845. (set! lst (cons called-pi lst))))
  846. called-list))))
  847. lst))
  848. ;; calls from cycle ci to some other function
  849. (define (cycleinfo-calls-to ci called-pi)
  850. (let ((cnt-calls 0))
  851. (cycleinfo-foreach-member
  852. ci
  853. (lambda (member-pi)
  854. (set! cnt-calls (+ cnt-calls
  855. (number-of-calls member-pi called-pi)))))
  856. cnt-calls))
  857. ;; calls to cycle ci from some other function
  858. (define (cycleinfo-calls-from ci caller-pi)
  859. (let ((cnt-calls 0))
  860. (cycleinfo-foreach-member
  861. ci
  862. (lambda (member-pi)
  863. (set! cnt-calls (+ cnt-calls
  864. (number-of-calls caller-pi member-pi)))))
  865. cnt-calls))
  866. ;; time spent in functions outside the cycle called from member-pi
  867. (define (cycleinfo-tchild-member prof-data ci member-pi)
  868. (let ((tt 0)
  869. (called-list (profinfo-calls prof-data member-pi)))
  870. ;; add share of every function called from this cycle-function to total
  871. (for-each (lambda (called-pi)
  872. (if (and (not (eq? called-pi
  873. member-pi))
  874. (not (cycleinfo-member? ci called-pi)))
  875. (let* ((thiscalls (number-of-calls member-pi called-pi))
  876. (totalcalls (profinfo-total-nonreccalls called-pi))
  877. (occs (profinfo-occurs called-pi))
  878. (share (/ (* occs thiscalls)
  879. totalcalls)))
  880. (set! tt (+ tt share)))))
  881. called-list)
  882. tt))
  883. (define (get-callerinfo caller called)
  884. (let* ((caller-list (profinfo-callers called))
  885. (cinfo (table-ref caller-list caller)))
  886. cinfo))
  887. (define (number-of-calls caller called)
  888. (let ((cinfo (get-callerinfo caller called)))
  889. (if cinfo
  890. (callerinfo-calls cinfo)
  891. 0)))
  892. ;; total number of calls from caller to the member or its whole cycle
  893. ;; (without recursive and cyclic)
  894. (define (profinfo-upcalls caller-pi called-pi)
  895. (let* ((cyc-called (profinfo-cycle called-pi))
  896. (nonrec-calls (profinfo-total-nonreccalls called-pi)))
  897. (if cyc-called
  898. (cycleinfo-calls-from cyc-called caller-pi)
  899. nonrec-calls)))
  900. ;; total number of calls from caller to the member or its whole cycle
  901. ;; (without recursive and cyclic)
  902. (define (profinfo-total-upcalls called-pi)
  903. (let* ((cyc-called (profinfo-cycle called-pi))
  904. (nonrec-calls (profinfo-total-nonreccalls called-pi)))
  905. (if cyc-called
  906. (sumup-calls-int/ext-cycle cyc-called #f)
  907. nonrec-calls)))
  908. ;; number of calls from inside of it's own cycle
  909. (define (profinfo-total-cycliccalls pi)
  910. (let ((cyc (profinfo-cycle pi)))
  911. (if cyc
  912. (calls-int/ext-cycle cyc pi #t)
  913. 0)))
  914. (define (profinfo-timeshare prof-data profinfo)
  915. (let ((hist (profinfo-hist profinfo)))
  916. (save/ hist (profile-data-samples prof-data))))
  917. (define (profinfo-total-ms prof-data profinfo)
  918. (let ((occurs (profinfo-occurs profinfo)))
  919. (occurs->ms prof-data occurs)))
  920. (define (profinfo-self-ms prof-data profinfo)
  921. (let ((hist (profinfo-hist profinfo)))
  922. (occurs->ms prof-data hist)))
  923. ;; returns a list of all profinfos the function calls
  924. (define (profinfo-calls prof-data caller-pi)
  925. (let ((lst '()))
  926. (table-walk (lambda (template called-pi)
  927. (if (> (number-of-calls caller-pi called-pi) 0)
  928. (set! lst (cons called-pi lst))))
  929. (profile-data-templates prof-data))
  930. (remove-duplicates lst)))
  931. ;; total non-recursive calls of this function
  932. (define (profinfo-total-nonreccalls pi)
  933. (- (profinfo-total-calls pi)
  934. (profinfo-total-reccalls pi)))
  935. ;; total recursive calls of this function
  936. (define (profinfo-total-reccalls pi)
  937. (let* ((cs (profinfo-callers pi))
  938. (info (table-ref cs pi)))
  939. (if info
  940. (callerinfo-calls info)
  941. 0)))
  942. ;; total number of calls (with recursive)
  943. (define (profinfo-total-calls pi)
  944. (let ((cs (profinfo-callers pi))
  945. (total 0))
  946. (table-walk (lambda (key cinfo)
  947. (set! total (+ total (callerinfo-calls cinfo))))
  948. cs)
  949. total))
  950. (define (get-sorted-templates prof-data property filter-noncalled?)
  951. (let ((lst '()))
  952. (table-walk (lambda (template profinfo)
  953. (if (or (not filter-noncalled?)
  954. (> (profinfo-total-calls profinfo) 0))
  955. (set! lst (cons profinfo lst))))
  956. (profile-data-templates prof-data))
  957. (set! lst (sort-list lst
  958. (lambda (a b)
  959. (< (property a)
  960. (property b)))))
  961. lst))
  962. (define (propagate-time-from-children prof-data caller-pi)
  963. (ddisplay "progating time for ")
  964. (ddisplay (profinfo-template caller-pi))
  965. (ddisplay " from children...\n")
  966. (let ((called-list (profinfo-calls prof-data caller-pi)))
  967. (for-each
  968. (lambda (called-pi)
  969. (let* ((cinfo (get-callerinfo caller-pi called-pi))
  970. (called-cyc (profinfo-cycle called-pi))
  971. (caller-cyc (profinfo-cycle caller-pi))
  972. (calls (callerinfo-calls cinfo))
  973. (share 0)
  974. (childshare 0))
  975. (ddisplay (profinfo-template caller-pi))
  976. (ddisplay " --> ")
  977. (ddisplay (profinfo-template called-pi))
  978. (if (and (not (eq? caller-pi called-pi))
  979. (or (not called-cyc) (not (eq? called-cyc caller-cyc))))
  980. (begin
  981. (let ((ctself
  982. (if called-cyc
  983. (cycleinfo-hist called-cyc)
  984. (profinfo-hist called-pi)))
  985. (ctchild
  986. (if called-cyc
  987. (cycleinfo-tchild called-cyc)
  988. (profinfo-tchild called-pi)))
  989. (nonreccalls
  990. (if called-cyc
  991. (cycleinfo-external-calls called-cyc)
  992. (profinfo-total-nonreccalls called-pi))))
  993. (ddisplay " ctself: ")
  994. (ddisplay ctself)
  995. (ddisplay ", ctchild: ")
  996. (ddisplay ctchild)
  997. (ddisplay ", nrc: ")
  998. (ddisplay nonreccalls)
  999. (set! share (/ (* ctself calls) nonreccalls))
  1000. (set! childshare (/ (* ctchild calls) nonreccalls))
  1001. )))
  1002. (ddisplay ", calls ")
  1003. (ddisplay (round calls))
  1004. (ddisplay ", share ")
  1005. (ddisplay (round share))
  1006. (ddisplay ", childshare ")
  1007. (ddisplay (round childshare))
  1008. (ddisplay "\n")
  1009. ;; add shares to arc information
  1010. (callerinfo-set-tself! cinfo share)
  1011. (callerinfo-set-tchild! cinfo childshare)
  1012. ;; add everything to child share for parent
  1013. (profinfo-set-tchild! caller-pi
  1014. (+ (profinfo-tchild caller-pi)
  1015. (+ share childshare)))
  1016. (if caller-cyc
  1017. (cycleinfo-set-tchild! caller-cyc
  1018. (+ (cycleinfo-tchild caller-cyc)
  1019. (+ share childshare))))
  1020. ))
  1021. called-list)))
  1022. (define (propagate-times prof-data)
  1023. ;; zero out
  1024. (table-walk (lambda (template profinfo)
  1025. (profinfo-set-tchild! profinfo 0))
  1026. (profile-data-templates prof-data))
  1027. (for-each (lambda (cyc)
  1028. (cycleinfo-set-tchild! cyc 0))
  1029. (profile-data-cycles prof-data))
  1030. (for-each (lambda (template)
  1031. (propagate-time-from-children prof-data template))
  1032. (get-sorted-templates prof-data (lambda (pi) (- (profinfo-dfn pi))) #f)))
  1033. ;;; number function by their depth in the call stack
  1034. (define (profinfo-dfn-set? pi)
  1035. (number? (profinfo-dfn pi)))
  1036. (define (profinfo-dfn-busy? pi)
  1037. (eq? (profinfo-dfn pi) 'busy))
  1038. (define (build-cycle prof-data dfn-stack top-pi)
  1039. ;; is it just a recursive call?
  1040. (if (not (eq? (car dfn-stack) top-pi))
  1041. (begin
  1042. ;; move down the stack till we find ourselves again, adding
  1043. ;; every function to our cycle
  1044. (let ((cyc (make-new-cycleinfo prof-data)))
  1045. (let loop ((stack dfn-stack))
  1046. (let* ((pi (car stack))
  1047. (pi-cyc (profinfo-cycle pi)))
  1048. (cycleinfo-add-member cyc pi)
  1049. ;; if this function is in a cycle already, we all belong to this cycle too
  1050. (if pi-cyc
  1051. (begin
  1052. ;; copy members to this cycle
  1053. (for-each (lambda (memb)
  1054. (cycleinfo-add-member pi-cyc memb))
  1055. (cycleinfo-members cyc))
  1056. (set! cyc pi-cyc)))
  1057. (if (and (not (null? (cdr stack)))
  1058. (not (eq? pi top-pi)))
  1059. (loop (cdr stack)))))
  1060. ;; add cycle globally
  1061. (cycleinfo-add prof-data cyc)
  1062. ;; update cycle information in profinfos
  1063. (for-each (lambda (memb)
  1064. (profinfo-set-cycle! memb cyc))
  1065. (cycleinfo-members cyc))
  1066. ))))
  1067. (define (toporder-numbering prof-data)
  1068. (let ((sorted-templates
  1069. (get-sorted-templates prof-data (lambda (pi) (- (profinfo-occurs pi))) #f))
  1070. (toporder 0))
  1071. (for-each (lambda (profinfo)
  1072. (profinfo-set-toporder! profinfo toporder)
  1073. (set! toporder (+ toporder 1)))
  1074. sorted-templates)))
  1075. (define (remove-uncalled prof-data)
  1076. (let ((tab (profile-data-templates prof-data)))
  1077. (table-walk (lambda (template profinfo)
  1078. (if (and (= (profinfo-total-calls profinfo) 0)
  1079. (not (eq? template (profile-data-root prof-data))))
  1080. (table-set! tab template #f)))
  1081. tab)))
  1082. ;;; numbers all functions by their depth in the call stack
  1083. (define (depth-numbering prof-data)
  1084. (let ((dfn-counter (table-size (profile-data-templates prof-data))))
  1085. (letrec ((depth-number-function
  1086. (lambda (dfn-stack cur-pi)
  1087. ;; already set?
  1088. (if (not (profinfo-dfn-set? cur-pi))
  1089. (begin
  1090. ;; is it busy? must be a cycle
  1091. (if (profinfo-dfn-busy? cur-pi)
  1092. (build-cycle prof-data dfn-stack cur-pi)
  1093. ;; no cycle
  1094. (begin
  1095. ;; pre-visit
  1096. (profinfo-set-dfn! cur-pi 'busy)
  1097. ;; process children
  1098. (for-each (lambda (called-pi)
  1099. (depth-number-function (cons cur-pi dfn-stack)
  1100. called-pi))
  1101. (profinfo-calls prof-data cur-pi))
  1102. (set! dfn-counter (- dfn-counter 1))
  1103. ;; post-visit
  1104. (profinfo-set-dfn! cur-pi dfn-counter)
  1105. )))))))
  1106. ;; zero out
  1107. (table-walk (lambda (template profinfo)
  1108. (profinfo-set-dfn! profinfo 'notset)
  1109. (profinfo-set-cycle! profinfo #f))
  1110. (profile-data-templates prof-data))
  1111. (table-walk (lambda (template profinfo)
  1112. (depth-number-function '() profinfo))
  1113. (profile-data-templates prof-data)))))
  1114. ;; find root and number from there
  1115. ; (if (profile-data-root prof-data)
  1116. ; (let ((root-pi (get-profinfo-from-template prof-data (profile-data-root prof-data))))
  1117. ; (if root-pi
  1118. ; (depth-number-function '() root-pi)))))))
  1119. ;;; RECORDING DATA (while target is running)
  1120. (define *last-stack* #f) ; stack at last interrupt
  1121. (define *cur-stack* #f) ; stack at this interrupt (to be built)
  1122. (define (last-stackentry)
  1123. (if (null? *cur-stack*)
  1124. #f
  1125. (car *cur-stack*)))
  1126. ;; adds one call to the profinfo of CALLED
  1127. (define (profinfo-count-call called caller)
  1128. (if (and called caller)
  1129. (let ((cs (profinfo-callers called)))
  1130. (cond ((table-ref cs caller)
  1131. => (lambda (ci)
  1132. (callerinfo-set-calls! ci (+ 1 (callerinfo-calls ci)))))
  1133. (else
  1134. (table-set! cs caller (make-callerinfo caller 1)))))))
  1135. ;; duplicate from sort/vector-util
  1136. (define (has-element list index)
  1137. (cond
  1138. ((zero? index)
  1139. (if (pair? list)
  1140. (values #t (car list))
  1141. (values #f #f)))
  1142. ((null? list)
  1143. (values #f #f))
  1144. (else
  1145. (has-element (cdr list) (- index 1)))))
  1146. (define (list-ref-or-default list index default)
  1147. (if list
  1148. (call-with-values
  1149. (lambda () (has-element list index))
  1150. (lambda (has? maybe)
  1151. (if has?
  1152. maybe
  1153. default)))
  1154. default))
  1155. (define (set-unseen-all!)
  1156. (and *last-stack*
  1157. (for-each (lambda (se)
  1158. (stackentry-set-seen! se #f))
  1159. *last-stack*)))
  1160. (define (seen? stackentry)
  1161. (and stackentry
  1162. (stackentry-seen stackentry)))
  1163. (define (seen! old-se se)
  1164. (if old-se
  1165. (begin
  1166. (stackentry-set-firstseen! se (stackentry-firstseen old-se))
  1167. (stackentry-set-seen! old-se #t))))
  1168. (define (time-passed se)
  1169. (let* ((firstseen (stackentry-firstseen se))
  1170. (mid (if *profiler-lastrun*
  1171. (- *profiler-thisrun*
  1172. *profiler-lastrun*)
  1173. 0))
  1174. (passed (- *profiler-thisrun*
  1175. firstseen)))
  1176. (- passed (/ mid 2))))
  1177. ;; process the stack entries that have the seen "bit" not set.
  1178. (define (post-process-stack! prof-data call-stack)
  1179. (let ((gone-stackentries '()))
  1180. (if call-stack
  1181. (let loop ((stack call-stack)
  1182. (caller-se #f)
  1183. (seen-templates '()))
  1184. (if (not (null? stack))
  1185. (let* ((called-se (car stack))
  1186. (called-pi (get-profinfo prof-data called-se))
  1187. (template (stackentry-template called-se))
  1188. (reccalls (stackentry-reccalls called-se)))
  1189. (if (and (= reccalls 0)
  1190. (not (memq? template seen-templates)))
  1191. (begin
  1192. ;; record occurrence
  1193. (profinfo-set-occurs! called-pi
  1194. (+ (profinfo-occurs called-pi) 1))))
  1195. ;; if top element, count as running
  1196. (if (null? (cdr stack))
  1197. (profinfo-set-hist! called-pi
  1198. (+ (profinfo-hist called-pi) 1)))
  1199. ;; if gone, record it
  1200. (if (not (stackentry-seen called-se))
  1201. (set! gone-stackentries
  1202. (cons called-se gone-stackentries)))
  1203. (loop (cdr stack)
  1204. called-se
  1205. (cons template seen-templates))))))
  1206. gone-stackentries))
  1207. (define (compare-continuation-args c1 c2)
  1208. (let ((ac (continuation-arg-count c1))
  1209. (ac2 (continuation-arg-count c2)))
  1210. (if (= ac ac2)
  1211. (let loop ((i 1))
  1212. (if (< i ac)
  1213. (if (eq? (continuation-arg c1 i)
  1214. (continuation-arg c2 i))
  1215. (loop (+ i 1))
  1216. #f)
  1217. #t))
  1218. #f)))
  1219. (define (process-stack-traces! prof-data)
  1220. (let ((stat-new-funcs '())
  1221. (stat-gone-funcs '())
  1222. (stat-new-caller #f)
  1223. (stat-top #f))
  1224. ;; go from bottom to top and count calls
  1225. (let loop ((pos 0)
  1226. (stack *cur-stack*)
  1227. (caller-se #f)
  1228. (diff-found #f))
  1229. (if (not (null? stack))
  1230. (let ((new-se (car stack)))
  1231. ;; compare with last stack
  1232. (let ((old-se (list-ref-or-default *last-stack* pos #f))
  1233. (rcdcall #f)
  1234. (old-diff-found diff-found))
  1235. (if (or (not old-se) ; not on old stack
  1236. diff-found)
  1237. (begin
  1238. (set! rcdcall #t)
  1239. (set! diff-found #t))
  1240. (if (not (eq? (stackentry-template old-se) ; other template => other func
  1241. (stackentry-template new-se)))
  1242. (begin
  1243. (set! rcdcall #t)
  1244. (set! diff-found #t))
  1245. ;; same template...
  1246. (let ((old-cont (stackentry-cont old-se))
  1247. (new-cont (stackentry-cont new-se)))
  1248. (if (not (eq? old-cont new-cont)) ; other continuation, something changed
  1249. (begin
  1250. (set! diff-found #t) ; remember change upwards...
  1251. (if (and (eq? (continuation-pc old-cont) ; same pc and arg-count, else
  1252. (continuation-pc new-cont)) ; may be just other place in func
  1253. (eq? (continuation-code old-cont)
  1254. (continuation-code new-cont))
  1255. (compare-continuation-args old-cont new-cont)) ; detects most tailcalls
  1256. (set! rcdcall #t)))))))
  1257. (if (and caller-se
  1258. (not (eq? diff-found
  1259. old-diff-found)))
  1260. (set! stat-new-caller caller-se))
  1261. (if rcdcall
  1262. (begin ; new call to fun
  1263. (set! stat-new-funcs (cons new-se stat-new-funcs))
  1264. (if (and caller-se
  1265. *measure-noninstr?*)
  1266. (record-call! prof-data
  1267. (stackentry-template caller-se) 0
  1268. (stackentry-template new-se) 0
  1269. #f))
  1270. )
  1271. (seen! old-se new-se))
  1272. (loop (+ pos 1)
  1273. (cdr stack)
  1274. new-se
  1275. diff-found)))
  1276. (set! stat-top caller-se)))
  1277. (set! stat-gone-funcs
  1278. (post-process-stack! prof-data *last-stack*))
  1279. (analyze-memory-usage prof-data stat-top stat-new-funcs stat-new-caller stat-gone-funcs)
  1280. ))
  1281. (define (record-template! cont template)
  1282. (if template
  1283. (if (eq? (closure-template profile-count)
  1284. template)
  1285. (begin
  1286. ; (display "hitting profile-count, throwing stack away\n")
  1287. (set! *cur-stack* '()))
  1288. (begin
  1289. (let ((lse (last-stackentry))
  1290. (nse (make-stackentry cont template)))
  1291. (if (and lse
  1292. (eq? (stackentry-template lse)
  1293. template))
  1294. (stackentry-set-reccalls! lse
  1295. (+ 1 (stackentry-reccalls lse))))
  1296. ;; consider recursion (disabled)
  1297. (set! *cur-stack*
  1298. (cons nse *cur-stack*)))))))
  1299. ;; main record function (called from interrupt handler)
  1300. (define (record-continuation! prof-data cont)
  1301. ;; init
  1302. (set! *cur-stack* '())
  1303. (set! *profiler-lastrun* *profiler-thisrun*)
  1304. (set! *profiler-thisrun* (run-time)) ; we cap this here, profiler could run some time
  1305. (set! *cur-avail-memory* (available-memory))
  1306. (set! *cur-gc-count* (get-current-gc-count))
  1307. (set-profile-data-samples! prof-data
  1308. (+ 1 (profile-data-samples prof-data)))
  1309. ;; record the current template
  1310. (record-template! cont (find-template cont))
  1311. ;; decent until we reach our own continuation
  1312. (let loop ((cont (continuation-cont cont)))
  1313. (if (and cont
  1314. (not (profiler-continuation? cont)))
  1315. (let ((parent (continuation-cont cont)))
  1316. (record-template! cont (continuation-template cont))
  1317. (loop parent))))
  1318. ;; record our root template
  1319. (record-template! #f (profile-data-root prof-data))
  1320. ;; process the stack built above
  1321. (if (not (null? *cur-stack*))
  1322. (begin
  1323. (process-stack-traces! prof-data)
  1324. ;; save old stack
  1325. (set! *last-stack* *cur-stack*)
  1326. (set-unseen-all!)))
  1327. ;; save memory status
  1328. (set! *last-avail-memory* (available-memory))
  1329. (set! *last-gc-count* (get-current-gc-count)))
  1330. ;; searchs the (moving?) template in the continuation
  1331. (define (find-template cont)
  1332. (let ((len (primitives:continuation-length cont)))
  1333. (let loop ((i 0))
  1334. (and (< i len)
  1335. (let ((elt (primitives:continuation-ref cont i)))
  1336. (if (template? elt)
  1337. elt
  1338. (loop (+ i 1))))))))
  1339. ;;;;;; HEAP PROFILER
  1340. ;; see commit messages and documentation
  1341. (define (available-memory)
  1342. (primitives:memory-status (enum memory-status-option available) #f))
  1343. (define (get-current-gc-count)
  1344. (primitives:memory-status (enum memory-status-option gc-count) #f))
  1345. (define (gc-running-meanwhile?)
  1346. (> *cur-gc-count* *last-gc-count*))
  1347. (define (analyze-memory-usage prof-data top new caller gone)
  1348. (if (gc-running-meanwhile?)
  1349. (begin
  1350. ;; we need to know the free memory after GC to fix this
  1351. #f)
  1352. (begin
  1353. (let* ((usage (- *last-avail-memory*
  1354. *cur-avail-memory*))
  1355. (cntnew (length new))
  1356. (cntgone (length gone))
  1357. (dotop (and top
  1358. (= cntnew 0)
  1359. (= cntgone 0)))
  1360. (totcnt (+ (if caller 1 0)
  1361. cntnew
  1362. cntgone))
  1363. (avgusage (if (= totcnt 0) 0 (/ usage totcnt)))
  1364. (addmem (lambda (se amount)
  1365. (let ((pi (get-profinfo prof-data se)))
  1366. (profinfo-set-memoryuse!
  1367. pi
  1368. (+ (profinfo-memoryuse pi)
  1369. amount))))))
  1370. (if (> usage 0)
  1371. (begin
  1372. (set-profile-data-memoryuse!
  1373. prof-data
  1374. (+ (profile-data-memoryuse prof-data) usage))
  1375. ;; if the template at the top still the same, add all memory to it
  1376. (if dotop
  1377. (addmem top usage)
  1378. ;; else distribute memory usage to all relevant templates
  1379. (begin
  1380. (if caller (addmem caller avgusage))
  1381. (for-each (lambda (se) (addmem se avgusage)) new)
  1382. (for-each (lambda (se) (addmem se avgusage)) gone)))))))))
  1383. ; (warning
  1384. ; 'profile-analyse-memory-usage
  1385. ; (string-append "usage < 0, somehow memory got free with no GC run: "
  1386. ; (number->string *last-avail-memory*)
  1387. ; " -> "
  1388. ; (number->string *cur-avail-memory*)))
  1389. (define (record-call! prof-data caller-template caller-pc called-template called-pc instrumented?)
  1390. (let* ((caller-profinfo (get-profinfo-from-template
  1391. prof-data
  1392. (if *first-call?*
  1393. (begin
  1394. (set! *first-call?* #f)
  1395. (profile-data-root prof-data))
  1396. caller-template)))
  1397. (called-profinfo (get-profinfo-from-template prof-data called-template))
  1398. (min-pc (profinfo-min-pc called-profinfo))
  1399. (only-instrumented? (profinfo-instrumented? called-profinfo)))
  1400. ;; only count this call, if counted by profile-count or
  1401. ;; by the sampling interrupt if it was not counted by profile-count yet
  1402. (if (or instrumented?
  1403. (not only-instrumented?))
  1404. (begin
  1405. ;; store the program counter of the first call to the function
  1406. (if (not min-pc)
  1407. (begin
  1408. (set! min-pc called-pc)
  1409. (profinfo-set-min-pc! called-profinfo min-pc)
  1410. (if instrumented?
  1411. (profinfo-set-instrumented?! called-profinfo #t))))
  1412. ;; we need to check the program counter, otherwise let-s would be counted
  1413. ;; as a call
  1414. (if (<= called-pc min-pc)
  1415. (profinfo-count-call called-profinfo caller-profinfo))))))
  1416. ;;; called from every profiled function (mcount in gprof),
  1417. ;;; if profiler-instrumentation optimizer enabled for this package
  1418. (define (profile-count)
  1419. (if *active-profile-data*
  1420. (let ((x (primitive-cwcc profile-count-cont)))
  1421. x)))
  1422. (define (profile-count-cont cont)
  1423. (let* ((cont-called (continuation-cont cont))
  1424. (cont-caller (continuation-cont cont-called))
  1425. (template-called (continuation-template cont-called))
  1426. (template-caller (continuation-template cont-caller))
  1427. (pc-called (continuation-pc cont-called))
  1428. (pc-caller (continuation-pc cont-caller)))
  1429. ; (display template-caller)
  1430. ; (display " (")
  1431. ; (display pc-caller)
  1432. ; (display ") calls ")
  1433. ; (display template-called)
  1434. ; (display " (")
  1435. ; (display pc-called)
  1436. ; (display ")\n")
  1437. (record-call! *active-profile-data* template-caller pc-caller template-called pc-called #t)))
  1438. (define (get-profinfo-from-template prof-data template)
  1439. (or (table-ref (profile-data-templates prof-data) template)
  1440. (make-profinfo prof-data template)))
  1441. ;; adds one call to the profinfo of CALLED
  1442. (define (profinfo-count-call called caller)
  1443. (if (and called caller)
  1444. (let ((cs (profinfo-callers called)))
  1445. (cond ((table-ref cs caller)
  1446. => (lambda (ci)
  1447. (callerinfo-set-calls! ci (+ 1 (callerinfo-calls ci)))))
  1448. (else
  1449. (table-set! cs caller (make-callerinfo caller 1)))))))