tools.profiler.sampling: preliminary docs

db4
Joe Groff 2011-11-09 11:34:31 -08:00
parent 2e9552d98a
commit 2dd31f4602
2 changed files with 235 additions and 9 deletions

View File

@ -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

View File

@ -10,15 +10,17 @@ FROM: sequences => change-nth ;
FROM: assocs => change-at ; FROM: assocs => change-at ;
IN: tools.profiler.sampling IN: tools.profiler.sampling
SYMBOL: raw-profile-data
SYMBOL: samples-per-second SYMBOL: samples-per-second
samples-per-second [ 1,000 ] initialize samples-per-second [ 1,000 ] initialize
<PRIVATE
SYMBOL: raw-profile-data
CONSTANT: ignore-words CONSTANT: ignore-words
{ signal-handler leaf-signal-handler profiling minor-gc } { signal-handler leaf-signal-handler profiling minor-gc }
: ignore-word? ( word -- ? ) ignore-words member? ; inline : ignore-word? ( word -- ? ) ignore-words member? ; inline
PRIVATE>
: most-recent-profile-data ( -- profile-data ) : most-recent-profile-data ( -- profile-data )
raw-profile-data get-global [ "No profile data" throw ] unless* ; 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 ; : foreign-thread-sample-count ( sample -- count ) 4 swap nth ;
: sample-counts-slice ( sample -- counts ) 5 head-slice ; : 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 ; : sample-callstack ( sample -- array ) 6 swap nth ;
: unclip-callstack ( sample -- sample' callstack-top ) : unclip-callstack ( sample -- sample' callstack-top )
clone 6 over [ unclip swap ] change-nth ; clone 6 over [ unclip swap ] change-nth ;
@ -113,17 +115,17 @@ CONSTANT: zero-counts { 0 0 0 0 0 }
: trim-root ( root -- root' ) : trim-root ( root -- root' )
dup redundant-root-node? [ children>> values first trim-root ] when ; 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 profile-data collect-threads
[ [ max-depth depth collect-tops ] <profile-root-node> trim-root ] assoc-map ; [ [ max-depth depth collect-tops ] <profile-root-node> trim-root ] assoc-map ;
PRIVATE> PRIVATE>
: top-down-max-depth* ( profile-data max-depth -- tree ) : top-down-max-depth* ( max-depth profile-data -- tree )
0 (top-down) ; 0 (top-down) ;
: top-down-max-depth ( max-depth -- tree ) : 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 ) : top-down* ( profile-data -- tree )
most-positive-fixnum top-down-max-depth* ; most-positive-fixnum top-down-max-depth* ;
@ -157,7 +159,7 @@ PRIVATE>
collect-threads collect-threads
[ [ collect-flat ] <profile-root-node> trim-flat ] assoc-map ; [ [ collect-flat ] <profile-root-node> trim-flat ] assoc-map ;
: flat ( -- tree ) : flat ( -- flat )
most-recent-profile-data flat* ; most-recent-profile-data flat* ;
<PRIVATE <PRIVATE
@ -179,7 +181,7 @@ PRIVATE>
PRIVATE> PRIVATE>
:: cross-section* ( depth profile-data -- flat ) :: cross-section* ( depth profile-data -- tree )
profile-data collect-threads profile-data collect-threads
[ [ depth collect-cross-section ] <profile-root-node> ] assoc-map ; [ [ depth collect-cross-section ] <profile-root-node> ] assoc-map ;
@ -221,11 +223,12 @@ DEFER: (profile.)
: (profile.) ( nodes depth -- ) : (profile.) ( nodes depth -- )
[ by-total-time ] dip '[ _ (profile-node.) ] assoc-each ; [ by-total-time ] dip '[ _ (profile-node.) ] assoc-each ;
PRIVATE>
: profile-heading. ( -- ) : profile-heading. ( -- )
"depth time ms GC % JIT % FFI % FT %" print ; "depth time ms GC % JIT % FFI % FT %" print ;
! NNNN XXXXXXX.X XXXX.X XXXX.X XXXX.X XXXX.X | | foo ! NNNN XXXXXXX.X XXXX.X XXXX.X XXXX.X XXXX.X | | foo
PRIVATE>
: profile. ( tree -- ) : profile. ( tree -- )
profile-heading. profile-heading.
[ 0 (profile-node.) ] assoc-each ; [ 0 (profile-node.) ] assoc-each ;