|
90 | 90 |
|
91 | 91 | ;;;; Help
|
92 | 92 |
|
93 |
| -(def help:signal-content "TODO") |
94 |
| -(def help:environmental-config "TODO") |
| 93 | +(do |
| 94 | + (impl/defhelp help:profiling-options :profiling-options) |
| 95 | + (impl/defhelp help:pstats-content :pstats-content) |
| 96 | + (impl/defhelp help:psignal-content :psignal-content) |
| 97 | + (impl/defhelp help:environmental-config :environmental-config)) |
95 | 98 |
|
96 | 99 | ;;;; Level filtering
|
97 | 100 | ;; Terminology note: we distinguish between call/form and min levels to ensure
|
|
226 | 229 |
|
227 | 230 | ;;;; Low-level primitives
|
228 | 231 |
|
229 |
| -#?(:clj (defn- valid-opts! [caller x] (if (map? x) x (truss/ex-info! (str caller " opts must be a const (compile-time) map") (enc/typed-val x))))) |
230 |
| -#?(:clj (defn- valid-opt:dynamic! [caller x] (if (enc/const-form? x) x (truss/ex-info! (str caller " `:dynamic?` opt must be a const (compile-time) value") (enc/typed-val x))))) |
231 |
| - |
232 | 232 | (defn profiling? "Returns e/o #{nil :thread :dynamic}."
|
233 | 233 | [] (if impl/*pdata* :dynamic (when (impl/pdata-local-get) :thread)))
|
234 | 234 |
|
235 | 235 | (comment (enc/qb 1e6 (profiling?))) ; 43.91
|
236 | 236 |
|
237 |
| -(def ^:const ^:private default-nmax (long 8e5)) |
| 237 | +(def ^:const ^:no-doc default-nmax (long 8e5)) |
238 | 238 | (defn new-pdata
|
239 | 239 | "Low-level primitive for advanced users.
|
240 | 240 | Returns a new pdata object for use with `with-profiling` and/or `capture-time!`.
|
|
275 | 275 | macros.
|
276 | 276 |
|
277 | 277 | See `new-pdata` for more info on low-level primitives."
|
278 |
| - [pdata {:keys [dynamic?]} & body] |
279 |
| - (valid-opt:dynamic! 'tufte/with-profiling dynamic?) |
| 278 | + [pdata {:as opts, :keys [dynamic?]} & body] |
| 279 | + (impl/valid-opts! &form &env 'tufte/with-profiling opts body) |
280 | 280 | (if dynamic?
|
281 | 281 | `(binding [impl/*pdata* ~pdata] (do ~@body))
|
282 | 282 | `(binding [impl/*pdata* nil] ; Ensure no dynamic parent (=>nesting) steals local captures
|
|
286 | 286 | (finally (impl/pdata-local-pop)))))))
|
287 | 287 |
|
288 | 288 | #?(:clj
|
289 |
| - (defmacro ^:private profiled* |
| 289 | + (defmacro ^:no-doc profiled* |
290 | 290 | "Unconditionally returns [<body-result> <pstats>]."
|
291 | 291 | [caller dynamic? nmax run-form]
|
292 |
| - (valid-opt:dynamic! caller dynamic?) |
293 | 292 | (if dynamic?
|
294 | 293 | `(let [pd# (impl/new-pdata-dynamic (or ~nmax default-nmax))] (binding [impl/*pdata* pd#] [~run-form @pd#]))
|
295 | 294 | `(let [pd# (impl/new-pdata-local (or ~nmax default-nmax))]
|
|
344 | 343 |
|
345 | 344 | #?(:clj
|
346 | 345 | (defmacro p
|
347 |
| - "Profiling spy. |
348 |
| -
|
349 |
| - Use this to wrap forms that should be timed during profiling: |
350 |
| - - Always executes body and returns <body-result>. |
351 |
| - - When profiling is active (via `profiled` or `profile`), |
352 |
| - records body's execution time. |
353 |
| -
|
354 |
| - Options include: |
355 |
| - `:id` - Form id for this body in stats output (e.g. `::my-fn-call`) |
356 |
| - `:level` - e/o #{0 1 2 3 4 5} ; Default is `5`" |
357 |
| - |
358 |
| - {:arglists '([id & body] [opts & body])} |
| 346 | + "Profiling spy, wraps forms that should be timed during profiling." |
| 347 | + {:doc (impl/docstring :p) |
| 348 | + :arglists '([id & body] [{:keys [id level]} & body])} |
359 | 349 | [s1 & body]
|
360 |
| - (let [ns-str (str *ns*) |
361 |
| - opts (if (map? s1) s1 {:level 5 :id s1}) |
362 |
| - level (get opts :level) |
363 |
| - id-form (get opts :id) |
364 |
| - loc (or (get opts :loc) (dissoc (enc/get-source &form &env) :file))] |
365 |
| - |
366 |
| - ;; If *any* level is present, it must be a valid compile-time level |
| 350 | + (let [opts (if (map? s1) s1 {:id s1}) |
| 351 | + level-form (get opts :level 5) |
| 352 | + id-form (get opts :id) |
| 353 | + location |
| 354 | + (enc/assoc-some nil |
| 355 | + (or (get opts :loc) (dissoc (enc/get-source &form &env) :file)))] |
| 356 | + |
| 357 | + ;; If level is present, it must be a valid compile-time level |
367 | 358 | ;; since this macro doesn't offer runtime level checking
|
368 |
| - (when level (valid-call-level level)) |
| 359 | + (when level-form (sigs/valid-level level-form)) |
369 | 360 |
|
370 |
| - (when (nil? id-form) |
371 |
| - (truss/ex-info! "`tufte/p` requires an id." |
372 |
| - {:loc loc |
373 |
| - :opts opts |
374 |
| - :form (cons 'p (cons s1 body))})) |
| 361 | + (when (or (nil? id-form) (empty? body)) |
| 362 | + (truss/ex-info! |
| 363 | + (str "`tufte/p` form needs an id at " (impl/location-str location) ": " |
| 364 | + `(~'p s1 ~@body)))) |
375 | 365 |
|
376 |
| - (if (-elide? level ns-str) |
| 366 | + (if-let [elide? (when-let [sf impl/ct-call-filter] (not (sf (:ns location) (enc/const-form id-form) (enc/const-form level-form))))] |
377 | 367 | `(do ~@body)
|
| 368 | + ;; Note no `impl/*rt-call-filter*` check |
378 | 369 | `(if-let [pd# (or impl/*pdata* (impl/pdata-local-get))]
|
379 | 370 | (let [t0# (enc/now-nano*)
|
380 | 371 | result# (do ~@body)
|
381 | 372 | t1# (enc/now-nano*)]
|
382 | 373 | ;; Note that capture cost is excluded from p time
|
383 |
| - (pd# ~id-form (- t1# t0#) ~loc) |
| 374 | + (pd# ~id-form (- t1# t0#) ~location) |
384 | 375 | result#)
|
385 | 376 | (do ~@body))))))
|
386 | 377 |
|
|
398 | 389 |
|
399 | 390 | (comment (valid-compile-time-opts 'sym 'sym))
|
400 | 391 |
|
| 392 | +#?(:clj (defn- auto-> [form auto-form] (if (= form :auto) auto-form form))) |
401 | 393 | #?(:clj
|
402 | 394 | (defmacro profiled
|
403 |
| - "Always executes body, and always returns [<body-result> <?pstats>]. |
404 |
| -
|
405 |
| - When [ns level] unelided and [ns level `when`] unfiltered, executes body |
406 |
| - with profiling active. |
407 |
| -
|
408 |
| - Handy if you'd like to consume stats output directly. |
409 |
| - Otherwise see `profile`. |
410 |
| -
|
411 |
| - `pstats` objects are derefable and mergeable: |
412 |
| - - @pstats => {:clock {:keys [t0 t1 total]}, :stats {<id> {:keys [n sum ...]}}} |
413 |
| - - @(merge-pstats ps1 ps2) => {:clock {:keys [t0 t1 total]}, :stats {<id> {:keys [n sum ...]}}} |
414 |
| -
|
415 |
| - Full set of keys in above `:stats` maps: |
416 |
| - :n :min :max :mean :mad :sum :p25 :p50 :p75 :p90 :p95 :p99 :loc :last |
417 |
| -
|
418 |
| - All values are numerical (longs or doubles), except for `:loc` which |
419 |
| - is a map of `p` callsite location information, or set of such maps, e.g.: |
420 |
| - {:ns \"my-ns\", :file \"/tmp/my-ns.clj\", :line 122, :column 21} |
421 |
| -
|
422 |
| - Compile-time opts: |
423 |
| - `:dynamic?` - Use multi-threaded profiling? ; Default is `false` |
424 |
| - `:nmax` ----- ~Max captures per id before compaction ; Default is 8e5 |
425 |
| -
|
426 |
| - Runtime opts: |
427 |
| - `:level` ---- e/o #{0 1 2 3 4 5} ; Default is `5` |
428 |
| - `:when` ----- Optional arbitrary conditional form (e.g. boolean expr) |
429 |
| -
|
430 |
| - Laziness in body: |
431 |
| - Lazy seqs and other forms of laziness (e.g. delays) in body will only |
432 |
| - contribute to profiling results if/when EVALUATION ACTUALLY OCCURS. |
433 |
| - This is intentional and a useful property. Compare: |
434 |
| -
|
435 |
| - (profiled {} (delay (Thread/sleep 2000))) ; Doesn't count sleep |
436 |
| - (profiled {} @(delay (Thread/sleep 2000))) ; Does count sleep |
437 |
| -
|
438 |
| - Async code in body: |
439 |
| - Execution time of any code in body that runs asynchronously on a |
440 |
| - different thread will generally NOT be automatically captured by default. |
441 |
| -
|
442 |
| - `:dynamic?` can be used to support capture in cases where Clojure's |
443 |
| - binding conveyance applies (e.g. futures, agents, pmap). Just make sure |
444 |
| - that all work you want to capture has COMPLETED before the `profiled` |
445 |
| - form ends- for example, by blocking on pending futures. |
446 |
| -
|
447 |
| - In other advanced cases (notably core.async `go` blocks), please see |
448 |
| - `with-profiling` and `capture-time!`. |
449 |
| -
|
450 |
| - `core.async` warning: |
451 |
| - `core.async` code can be difficult to profile correctly without a deep |
452 |
| - understanding of precisely what it's doing under-the-covers. |
453 |
| -
|
454 |
| - Some general recommendations that can help keep things simple: |
455 |
| -
|
456 |
| - - Try minimize the amount of code + logic in `go` blocks. Use `go` |
457 |
| - blocks for un/parking to get the data you need, then pass the data |
458 |
| - to external fns. Profile these fns (or in these fns), not in your |
459 |
| - `go` blocks. |
460 |
| -
|
461 |
| - - In particular: you MUST NEVER have parking calls inside |
462 |
| - `(profiled {:dynamic? false} ...)`. |
463 |
| -
|
464 |
| - This can lead to concurrency exceptions. |
465 |
| -
|
466 |
| - If you must profile code within a go block, and you really want to |
467 |
| - include un/parking times, use `(profiled {:dynamic? true} ...)` |
468 |
| - instead." |
| 395 | + {:doc (impl/docstring :profiled) |
| 396 | + :arglists '([{:keys [id level sample when limit limit-by]} & body])} |
469 | 397 |
|
470 | 398 | [opts & body]
|
471 |
| - (let [ns-str (str *ns*)] |
472 |
| - |
473 |
| - (when-not (map? opts) |
474 |
| - (truss/ex-info! "`tufte/profiled` requires a compile-time map as first arg." |
475 |
| - {:ns-str ns-str :line (:line (meta &form)) |
476 |
| - :form (cons 'profiled (cons opts body))})) |
477 |
| - |
478 |
| - (let [level-form (get opts :level 5) |
479 |
| - dynamic? (get opts :dynamic? false) |
480 |
| - test-form (get opts :when true) |
481 |
| - nmax (get opts :nmax default-nmax) |
482 |
| - |
483 |
| - _ (valid-compile-time-opts dynamic? nmax) |
484 |
| - nmax (long nmax)] |
485 |
| - |
486 |
| - (when (integer? level-form) (valid-call-level level-form)) |
487 |
| - |
488 |
| - (if (-elide? level-form ns-str) |
489 |
| - `[(do ~@body)] |
490 |
| - (let [runtime-check |
491 |
| - (if (= test-form true) ; Common case |
492 |
| - `(may-profile? ~level-form ~ns-str) |
493 |
| - `(and (may-profile? ~level-form ~ns-str) ~test-form))] |
494 |
| - |
495 |
| - (if dynamic? |
496 |
| - `(if ~runtime-check |
497 |
| - (let [pd# (impl/new-pdata-dynamic ~nmax)] |
498 |
| - (binding [impl/*pdata* pd#] |
499 |
| - [(do ~@body) @pd#])) |
500 |
| - [(do ~@body)]) |
501 |
| - |
502 |
| - `(if ~runtime-check |
503 |
| - (let [pd# (impl/new-pdata-local ~nmax)] |
504 |
| - (binding [impl/*pdata* nil] ; Ensure no dynamic parent (=>nesting) steals local captures |
505 |
| - (try |
506 |
| - (impl/pdata-local-push pd#) |
507 |
| - [(do ~@body) @pd#] |
508 |
| - (finally (impl/pdata-local-pop))))) |
509 |
| - [(do ~@body)])))))))) |
| 399 | + (impl/valid-opts! &form &env 'tufte/profiled opts body) |
| 400 | + (let [opts (merge {:level 5} opts) |
| 401 | + ns-form* (get opts :ns :auto) |
| 402 | + ns-form (auto-> ns-form* (str *ns*)) |
| 403 | + |
| 404 | + {:keys [elide? allow?]} |
| 405 | + (sigs/filter-call |
| 406 | + {:cljs? (boolean (:ns &env)) |
| 407 | + :sf-arity 3 |
| 408 | + :ct-call-filter impl/ct-call-filter |
| 409 | + :*rt-call-filter* `impl/*rt-call-filter*} |
| 410 | + (assoc opts :ns ns-form)) |
| 411 | + |
| 412 | + {:keys [dynamic? nmax]} opts] |
| 413 | + |
| 414 | + (if elide? |
| 415 | + `[(do ~@body)] |
| 416 | + `((fn [] ; iffe-wrap |
| 417 | + (let [body-fn# (fn [] ~@body)] |
| 418 | + (enc/if-not ~allow? |
| 419 | + [(body-fn#)] |
| 420 | + (profiled* 'tufte/profiled ~dynamic? ~nmax (body-fn#)))))))))) |
510 | 421 |
|
511 | 422 | (comment
|
512 |
| - (enc/qb 1e6 ; [463.23 560.09] |
513 |
| - (profiled {}) |
514 |
| - (profiled {} 2 (p :p1))) |
| 423 | + (enc/qb 1e6 (profiled {:allow? false}) (profiled {})) ; [36.74 259.73] |
| 424 | + (macroexpand '(profiled {:allow? false})) |
515 | 425 |
|
516 |
| - (profiled {} (p :p1)) |
517 |
| - (profiled {} (p {:level 5 :id :p1})) |
| 426 | + (profiled {} (p :p1 nil)) |
| 427 | + (profiled {} (p {:level 5 :id :p1} nil)) |
518 | 428 | (profiled {} (p (let [x :foo/id] x) "body"))
|
519 | 429 | (profiled {:level 2 :when (chance 0.5)} (p :p1 "body"))
|
520 |
| - (profiled {} (p :foo (p :bar)))) |
| 430 | + (profiled {} (p :foo (p :bar nil)))) |
521 | 431 |
|
522 | 432 | #?(:clj
|
523 | 433 | (defmacro profile
|
524 |
| - "Always executes body, and always returns <body-result>. |
525 |
| -
|
526 |
| - When [ns level] unelided and [ns level `when`] unfiltered, executes body |
527 |
| - with profiling active and dispatches stats to any registered handlers |
528 |
| - (see `add-handler!`). |
529 |
| -
|
530 |
| - Handy if you'd like to consume/aggregate stats output later/elsewhere. |
531 |
| - Otherwise see `profiled`. |
532 |
| -
|
533 |
| - Compile-time opts: |
534 |
| - `:dynamic?` - Use multi-threaded profiling? ; Default is `false` |
535 |
| - `:nmax` ----- ~Max captures per id before compaction ; Default is 8e5 |
536 |
| -
|
537 |
| - Runtime opts: |
538 |
| - `:level` ---- e/o #{0 1 2 3 4 5} ; Default is `5` |
539 |
| - `:when` ----- Optional arbitrary conditional form (e.g. boolean expr) |
540 |
| - `:id` ------- Optional profiling id provided to handlers (e.g. `::my-stats-1`) |
541 |
| - `:data` ----- Optional arbitrary data provided to handlers |
542 |
| -
|
543 |
| - Laziness in body: |
544 |
| - Lazy seqs and other forms of laziness (e.g. delays) in body will only |
545 |
| - contribute to profiling results if/when EVALUATION ACTUALLY OCCURS. |
546 |
| - This is intentional and a useful property. Compare: |
547 |
| -
|
548 |
| - (profiled {} (delay (Thread/sleep 2000))) ; Doesn't count sleep |
549 |
| - (profiled {} @(delay (Thread/sleep 2000))) ; Does count sleep |
550 |
| -
|
551 |
| - Async code in body: |
552 |
| - Execution time of any code in body that runs asynchronously on a |
553 |
| - different thread will generally NOT be automatically captured by default. |
554 |
| -
|
555 |
| - `:dynamic?` can be used to support capture in cases where Clojure's |
556 |
| - binding conveyance applies (e.g. futures, agents, pmap). Just make sure |
557 |
| - that all work you want to capture has COMPLETED before the `profiled` |
558 |
| - form ends- for example, by blocking on pending futures. |
559 |
| -
|
560 |
| - In other advanced cases (notably core.async `go` blocks), please see |
561 |
| - `with-profiling` and `capture-time!`. |
562 |
| -
|
563 |
| - `core.async` warning: |
564 |
| - `core.async` code can be difficult to profile correctly without a deep |
565 |
| - understanding of precisely what it's doing under-the-covers. |
566 |
| -
|
567 |
| - Some general recommendations that can help keep things simple: |
568 |
| -
|
569 |
| - - Try minimize the amount of code + logic in `go` blocks. Use `go` |
570 |
| - blocks for un/parking to get the data you need, then pass the data |
571 |
| - to external fns. Profile these fns (or in these fns), not in your |
572 |
| - `go` blocks. |
573 |
| -
|
574 |
| - - In particular: you MUST NEVER have parking calls inside |
575 |
| - `(profiled {:dynamic? false} ...)`. |
576 |
| -
|
577 |
| - This can lead to concurrency exceptions. |
578 |
| -
|
579 |
| - If you must profile code within a go block, and you really want to |
580 |
| - include un/parking times, use `(profiled {:dynamic? true} ...)` |
581 |
| - instead." |
| 434 | + {:doc (impl/docstring :profile) |
| 435 | + :arglists '([{:keys [id level sample when limit limit-by]} & body])} |
582 | 436 |
|
583 | 437 | [opts & body]
|
584 |
| - (let [ns-str (str *ns*)] |
585 |
| - |
586 |
| - (when-not (map? opts) |
587 |
| - (truss/ex-info! "`tufte/profile` requires a compile-time map as first arg." |
588 |
| - {:ns-str ns-str :line (:line (meta &form)) |
589 |
| - :form (cons 'profile (cons opts body))})) |
590 |
| - |
591 |
| - (let [level-form (get opts :level 5) |
| 438 | + (impl/valid-opts! &form &env 'tufte/profile opts body) |
| 439 | + (let [opts (merge {:level 5} opts) |
| 440 | + ns-form* (get opts :ns :auto) |
| 441 | + ns-form (auto-> ns-form* (str *ns*)) |
| 442 | + |
| 443 | + {:keys [elide? allow?]} |
| 444 | + (sigs/filter-call |
| 445 | + {:cljs? (boolean (:ns &env)) |
| 446 | + :sf-arity 3 |
| 447 | + :ct-call-filter impl/ct-call-filter |
| 448 | + :*rt-call-filter* `impl/*rt-call-filter*} |
| 449 | + (assoc opts :ns ns-form)) |
| 450 | + |
| 451 | + {:keys [dynamic? nmax]} opts] |
| 452 | + |
| 453 | + (let [level-form (get opts :level) |
592 | 454 | id-form (get opts :id)
|
593 | 455 | data-form (get opts :data)]
|
594 | 456 |
|
595 |
| - (when (integer? level-form) (valid-call-level level-form)) |
596 |
| - |
597 | 457 | `(let [[result# pstats#] (profiled ~opts ~@body)]
|
598 |
| - (when pstats# |
| 458 | + (when pstats# |
599 | 459 | (impl/handle!
|
600 |
| - (HandlerVal. ~ns-str ~level-form ~id-form ~data-form |
| 460 | + (HandlerVal. ~ns-form ~level-form ~id-form ~data-form |
601 | 461 | pstats# (delay (format-pstats pstats#))
|
602 | 462 | ~*file* ~(:line (meta &form)))))
|
603 | 463 | result#)))))
|
|
0 commit comments