From 2dd31f4602d4c08cbe4426fa1d5268907f9bcdb4 Mon Sep 17 00:00:00 2001 From: Joe Groff Date: Wed, 9 Nov 2011 11:34:31 -0800 Subject: [PATCH] tools.profiler.sampling: preliminary docs --- .../profiler/sampling/sampling-docs.factor | 223 ++++++++++++++++++ basis/tools/profiler/sampling/sampling.factor | 21 +- 2 files changed, 235 insertions(+), 9 deletions(-) create mode 100644 basis/tools/profiler/sampling/sampling-docs.factor diff --git a/basis/tools/profiler/sampling/sampling-docs.factor b/basis/tools/profiler/sampling/sampling-docs.factor new file mode 100644 index 0000000000..5fa9cc3921 --- /dev/null +++ b/basis/tools/profiler/sampling/sampling-docs.factor @@ -0,0 +1,223 @@ +! (c)2010 Joe Groff bsd license +USING: arrays calendar help.markup help.syntax kernel math +quotations threads words ; +IN: tools.profiler.sampling + +{ cross-section flat top-down top-down-max-depth profile profile. } related-words +{ cross-section* flat* top-down* top-down-max-depth* most-recent-profile-data } related-words + +{ total-sample-count gc-sample-count jit-sample-count foreign-sample-count foreign-thread-sample-count sample-thread sample-callstack } related-words + +{ total-time gc-time foreign-time foreign-thread-time } related-words + +HELP: cross-section +{ $values + { "depth" integer } + { "tree" "a profile report" } +} +{ $description "Generates a cross-section profile at " { $snippet "depth" } " from the results of the most recent " { $link profile } ". Each sample's time will be charged to the function " { $snippet "depth" } " levels deep in the callstack, or to the deepest function in the callstack if the callstack at the time of the sample is fewer than " { $snippet "depth" } " levels deep. The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: cross-section* +{ $values + { "depth" integer } { "profile-data" "raw profile data" } + { "tree" "a profile report" } +} +{ $description "Generates a cross-section profile at " { $snippet "depth" } " from the profile results in " { $snippet "profile-data" } ". Each sample's time will be charged to the function " { $snippet "depth" } " levels deep in the callstack, or to the deepest function in the callstack if the callstack at the time of the sample is fewer than " { $snippet "depth" } " levels deep. The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: flat +{ $values + { "flat" "a profile report" } +} +{ $description "Generates a flat profile from the results of the most recent " { $link profile } ". Each sample's time will be charged to every function in the callstack at the time of the sample. The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: flat* +{ $values + { "profile-data" "raw profile data" } + { "flat" "a profile report" } +} +{ $description "Generates a flat profile from the profile results in " { $snippet "profile-data" } ". Each sample's time will be charged to every function in the callstack at the time of the sample. The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: foreign-sample-count +{ $values + { "sample" "a raw profile sample" } + { "count" integer } +} +{ $description "Returns the number of sample intervals spent in non-Factor code (such as the Factor VM, or FFI calls) during " { $snippet "sample" } "." } ; + +HELP: foreign-thread-sample-count +{ $values + { "sample" "a raw profile sample" } + { "count" integer } +} +{ $description "Returns the number of sample intervals spent executing non-Factor threads within the Factor process during " { $snippet "sample" } "." } ; + +HELP: foreign-thread-time +{ $values + { "n" duration } +} +{ $description "Returns the total time spent executing non-Factor threads within the Factor process during the last " { $link profile } "." } ; + +HELP: foreign-thread-time* +{ $values + { "profile-data" "raw profile data" } + { "n" duration } +} +{ $description "Returns the total time spent executing non-Factor threads within the Factor process from the given " { $snippet "profile-data" } "." } ; + +HELP: foreign-time +{ $values + { "n" duration } +} +{ $description "Returns the total time spent in non-Factor code (such as the Factor VM, or FFI calls) during the last " { $link profile } "." } ; + +HELP: foreign-time* +{ $values + { "profile-data" "raw profile data" } + { "n" duration } +} +{ $description "Returns the total time spent in non-Factor code (such as the Factor VM, or FFI calls) from the given " { $snippet "profile-data" } "." } ; + +HELP: gc-sample-count +{ $values + { "sample" "a raw profile sample" } + { "count" integer } +} +{ $description "Returns the number of sample intervals spent in the garbage collector during " { $snippet "sample" } "." } ; + +HELP: gc-time +{ $values + { "n" duration } +} +{ $description "Returns the total time spent in the garbage collector during the last " { $link profile } "." } ; + +HELP: gc-time* +{ $values + { "profile-data" "raw profile data" } + { "n" duration } +} +{ $description "Returns the total time spent in the garbage collector from the given " { $snippet "profile-data" } "." } ; + +HELP: jit-sample-count +{ $values + { "sample" "a raw profile sample" } + { "count" integer } +} +{ $description "Returns the number of sample intervals spent in the non-optimizing compiler during " { $snippet "sample" } "." } ; + +HELP: most-recent-profile-data +{ $values + { "profile-data" "raw profile data" } +} +{ $description "Returns the raw profile data from the most recent " { $link profile } ". This data can be saved and used with the " { $snippet "*" } " variants of reporting words, such as " { $link top-down* } " and " { $link flat* } ", independent of later executions of the profiler.." } ; + +HELP: profile +{ $values + { "quot" quotation } +} +{ $description "Executes " { $snippet "quot" } " with the sampling profiler enabled. The results of the profile can subsequently be reported with words such as " { $link top-down } " and " { $link flat } ", or the raw data can be saved and inspected with " { $link most-recent-profile-data } "." } ; + +HELP: profile-node +{ $class-description "Objects of this type are generated by profile reporting words such as " { $link top-down } ", " { $link top-down-max-depth } ", " { $link cross-section } ", and " { $link flat } "." } ; + +HELP: profile. +{ $values + { "tree" "a profile report" } +} +{ $description "Formats and prints a profile report generated by " { $link top-down } ", " { $link top-down-max-depth } ", " { $link cross-section } ", or " { $link flat } "." } ; + +HELP: sample-callstack +{ $values + { "sample" "a raw profile sample" } + { "array" array } +} +{ $description "Returns the callstack (the stack of functions currently executing) at the time of " { $snippet "sample" } "." } ; + +HELP: sample-thread +{ $values + { "sample" "a raw profile sample" } + { "thread" thread } +} +{ $description "Returns the currently-executing Factor thread at the time of " { $snippet "sample" } "." } ; + +HELP: samples-per-second +{ $var-description "This variable controls the rate at which the profiler takes samples during calls to " { $link profile } "." } ; + +HELP: samples>time +{ $values + { "samples" integer } + { "time" duration } +} +{ $description "Converts a sample interval count to a " { $link duration } " based on the value of " { $link samples-per-second } "." } ; + +HELP: top-down +{ $values + { "tree" "a profile report" } +} +{ $description "Generates a top-down tree profile from the results of the most recent " { $link profile } ". The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: top-down* +{ $values + { "profile-data" "raw profile data" } + { "tree" "a profile report" } +} +{ $description "Generates a top-down tree profile from the profile results in " { $snippet "profile-data" } ". The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: top-down-max-depth +{ $values + { "max-depth" integer } + { "tree" "a profile report" } +} +{ $description "Generates a top-down tree profile from the results of the most recent " { $link profile } ". Functions at a callstack depth greater than " { $snippet "max-depth" } " will be filtered out. The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: top-down-max-depth* +{ $values + { "max-depth" integer } { "profile-data" "raw profile data" } + { "tree" "a profile report" } +} +{ $description "Generates a top-down tree profile from the profile results in " { $snippet "profile-data" } ". Functions at a callstack depth greater than " { $snippet "max-depth" } " will be filtered out. The output " { $snippet "tree" } " can be printed with the " { $link profile. } " word." } ; + +HELP: total-sample-count +{ $values + { "sample" "a raw profile sample" } + { "count" integer } +} +{ $description "Returns the total number of sample intervals spent during " { $snippet "sample" } "." } ; + +HELP: total-time +{ $values + { "n" duration } +} +{ $description "Returns the total time spent during the most recent " { $link profile } "." } ; + +HELP: total-time* +{ $values + { "profile-data" "raw profile data" } + { "n" duration } +} +{ $description "Returns the total time spent from the given " { $snippet "profile-data" } "." } ; + +ARTICLE: "tools.profiler.sampling" "Sampling profiler" +"The " { $vocab-link "tools.profiler.sampling" } " vocabulary provides an interface to Factor's sampling profiler. It provides words for running the profiler:" +{ $subsections profile } +"General statistics can then be collected:" +{ $subsections total-time gc-time foreign-time foreign-thread-time } +"More detailed by-function profile reports can be generated:" +{ $subsections top-down top-down-max-depth cross-section flat } +"The report data can then be printed:" +{ $subsections profile. } +"Profile data can be saved for future reporting:" +{ $subsections most-recent-profile-data top-down* top-down-max-depth* cross-section* flat* } +"For example, the following will profile a call to the foo word, and generate and display a top-down tree profile from the results:" +{ $code """[ foo ] profile +top-down profile.""" } +; + +ABOUT: "tools.profiler.sampling" + +! Implementation + +! Inaccuracies +! epilogue bias +! sample count phase +! not compensated for sample collection time +! nearest-neighbor reporting diff --git a/basis/tools/profiler/sampling/sampling.factor b/basis/tools/profiler/sampling/sampling.factor index d4a1213dec..af1ddf378f 100644 --- a/basis/tools/profiler/sampling/sampling.factor +++ b/basis/tools/profiler/sampling/sampling.factor @@ -10,15 +10,17 @@ FROM: sequences => change-nth ; FROM: assocs => change-at ; IN: tools.profiler.sampling -SYMBOL: raw-profile-data SYMBOL: samples-per-second samples-per-second [ 1,000 ] initialize + : most-recent-profile-data ( -- profile-data ) raw-profile-data get-global [ "No profile data" throw ] unless* ; @@ -35,7 +37,7 @@ CONSTANT: ignore-words : foreign-thread-sample-count ( sample -- count ) 4 swap nth ; : sample-counts-slice ( sample -- counts ) 5 head-slice ; -: sample-thread ( sample -- alien ) 5 swap nth ; +: sample-thread ( sample -- thread ) 5 swap nth ; : sample-callstack ( sample -- array ) 6 swap nth ; : unclip-callstack ( sample -- sample' callstack-top ) clone 6 over [ unclip swap ] change-nth ; @@ -113,17 +115,17 @@ CONSTANT: zero-counts { 0 0 0 0 0 } : trim-root ( root -- root' ) dup redundant-root-node? [ children>> values first trim-root ] when ; -:: (top-down) ( profile-data max-depth depth -- tree ) +:: (top-down) ( max-depth profile-data depth -- tree ) profile-data collect-threads [ [ max-depth depth collect-tops ] trim-root ] assoc-map ; PRIVATE> -: top-down-max-depth* ( profile-data max-depth -- tree ) +: top-down-max-depth* ( max-depth profile-data -- tree ) 0 (top-down) ; : top-down-max-depth ( max-depth -- tree ) - most-recent-profile-data swap top-down-max-depth* ; + most-recent-profile-data top-down-max-depth* ; : top-down* ( profile-data -- tree ) most-positive-fixnum top-down-max-depth* ; @@ -157,7 +159,7 @@ PRIVATE> collect-threads [ [ collect-flat ] trim-flat ] assoc-map ; -: flat ( -- tree ) +: flat ( -- flat ) most-recent-profile-data flat* ; PRIVATE> -:: cross-section* ( depth profile-data -- flat ) +:: cross-section* ( depth profile-data -- tree ) profile-data collect-threads [ [ depth collect-cross-section ] ] assoc-map ; @@ -221,11 +223,12 @@ DEFER: (profile.) : (profile.) ( nodes depth -- ) [ by-total-time ] dip '[ _ (profile-node.) ] assoc-each ; -PRIVATE> - : profile-heading. ( -- ) "depth time ms GC % JIT % FFI % FT %" print ; ! NNNN XXXXXXX.X XXXX.X XXXX.X XXXX.X XXXX.X | | foo + +PRIVATE> + : profile. ( tree -- ) profile-heading. [ 0 (profile-node.) ] assoc-each ;