330 likes | 481 Views
Dynamic Execution Tracing of Physical Simulations. Jonathan Cohen. The Motivation. Typical bugs in physical simulation are hard to find ! Complex code path & data flow gdb/printf ill-suited to the task – where's the breakpoint go? Insert complex debugging routines into the code?
E N D
Dynamic Execution Tracing of Physical Simulations Jonathan Cohen
The Motivation Typical bugs in physical simulation are hard to find! Complex code path & data flow gdb/printf ill-suited to the task – where's the breakpoint go? Insert complex debugging routines into the code? Need: trace aggregate data flow, gather statistics, look for anomalies, profiling, etc. Want: programmable, no recompiling, minimal impact
Anatomy of an sstrace Script A script is made of probes – like breakpoint, triggered by name MODULE:FUNCTION:EVENT or MODULE:CLASS@METHOD:EVENT
Examples of probe names sim:IncompressibleSolver@Advance:enter sim:IncompressibleSolver@*:enter sim:*:enter sim:PoissonSolver@Solve:iterations sys:main:enter
Anatomy of an sstrace Script Following each probe is a block of code that is executed when probe is hit MODULE:FUNCTION:EVENT { command -option arg -option arg command -option arg -option arg }
Some Commands print – display text to a log file timer – start, stop, pause a stopwatch histogram – add sample points, display indent – set indentation level of print out counters – basic math
Anatomy of an sstrace Script Command arguments can reference variables MODULE:FUNCTION:EVENT { print $TOTAL_COST counter -name TOTAL_COST -add $ARG0 }
Special Variables Any timer can be read as variable ($total_time) Arguments passed from code ($ARG0, $ARG1, etc.) Other special variables ($TIME, $PROBE, $PROCESSMEM, etc.)
Example: Execution Stack Tracing sim:SphereSim@step sim:SphereWorldBase@AddParticleSim sim:SphereWorldBase@AddParticleSim sim:ContSphereSolverGuendelman@Advance sim:ContSphereSolverGuendelman@TakeStep sim:ContSphereSolverGuendelman@DoCollisionImpulses sim:ContSphereMultiCollision@Insert sim:ContSphereUniformGridCollision@Insert sim:ContSphereUniformGridCollision@Insert sim:ContSphereUniformGridCollision@GetCollisions sim:ContSphereUniformGridCollision@GetCollisions sim:ContSphereSolverGuendelman@DoCollisionImpulses sim:ContSphereUniformGridCollision@GetCollisions sim:ContSphereUniformGridCollision@GetCollisions <snip> *:*:enter { print -var $PROBEBASE indent -add 2 } *:*:exit { indent -add -2 }
Example: Analyze FluidSim Timing sim:FluidSim@step:enter { timer -reset mytimer timer -start mytimer } sim:FluidSim@step:exit { histogram -name myhist -add $mytimer } sys:main:exit { histogram -print myhist }
Example: Sphere-Sphere collision Complex collision data structure: KD-Tree Leaf nodes are either flat lists or uniform grids Heuristic recursively decides whether to make leaf (which type?) or keep splitting How does the heuristic work in practice?
Trace Output FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 9,14,15 efficiency 46.8783 Type:ContSphereUniformGridCollision (X,Y,Z) = 8,13,13 efficiency 60.5769 Acceleration data structure memory usage: 122812 Total memory usage: 3.03354e+08
Per-Frame Callback FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 9,14,15 efficiency 46.8783 Type:ContSphereUniformGridCollision (X,Y,Z) = 8,13,13 efficiency 60.5769 Acceleration data structure memory usage: 122812 Total memory usage: 3.03354e+08 dem:*SphereSim@step:enter { print -msg "\nFRAME " -var $ARG0 print -msg "--------------------------\n" }
Memory Statistics FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 9,14,15 efficiency 46.8783 Type:ContSphereUniformGridCollision (X,Y,Z) = 8,13,13 efficiency 60.5769 Acceleration data structure memory usage: 122812 Total memory usage: 3.03354e+08 dem:*SphereWorld@MakeAccelValid:memusage { print -msg "Acceleration data structure memory usage: " -var $ARG0 print -msg "Total memory usage: " -var $PROCESSMEM }
Tree Structure dem:*SphereMultiCollision@Insert:child?type { print -msg "Type:" -var $ARG0 } dem:*SphereMultiCollision@Insert:enter { indent -add 2 } dem:*SphereMultiCollision@Insert:exit { indent -add -2 } FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 9,14,15 efficiency 46.8783 Type:ContSphereUniformGridCollision (X,Y,Z) = 8,13,13 efficiency 60.5769 Acceleration data structure memory usage: 122812 Total memory usage: 3.03354e+08
Uniform Grid Statistics FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 9,14,15 efficiency 46.8783 Type:ContSphereUniformGridCollision (X,Y,Z) = 8,13,13 efficiency 60.5769 Acceleration data structure memory usage: 122812 Total memory usage: 3.03354e+08 dem:*SphereUniformGridCollision@Insert:dimension { print -msg " (X,Y,Z) = " -var $ARG0, $ARGV1, $ARGV2 } dem:*SphereUniformGridCollision@Insert:efficiency { print -msg " efficiency " -var $ARG0 }
Trace Output – Second try FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 23, 38, 87 efficiency 3.92304 Type:ContSphereUniformGridCollision (X,Y,Z) = 41, 440, 62 efficiency 0.164151 Acceleration data structure memory usage: 2.86844e+07 Total memory usage: 3.25038e+08
Trace Output – Second try FRAME 240 -------------------------- Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 23, 38, 87 efficiency 3.92304 Type:ContSphereUniformGridCollision (X,Y,Z) = 41, 440, 62 efficiency 0.164151 Acceleration data structure memory usage:2.86844e+07 Total memory usage: 3.25038e+08
Found a bug in the Heuristic! Splitting threshold was set so that it could never succeed Code was never splitting Validate (with another sstrace script): cumulative time: 107.553 sec (old)
Found a bug in the Heuristic! • Splitting threshold was set so that it could never succeed • Code was never splitting • Validate (with another sstrace script): • cumulative time: 107.553 sec (old) • cumulative time: 82.6091 sec (new)
Trace Output – Third try Type: <top level> Type:ContSphereUniformGridCollision (X,Y,Z) = 23, 38, 87 efficiency 3.96249 Type:ContSphereMultiCollision Type:ContSphereUniformGridCollision (X,Y,Z) = 32, 18, 24 efficiency 8.99161 Type:ContSphereMultiCollision Type:ContSphereUniformGridCollision (X,Y,Z) = 26, 150, 20 efficiency 0.387179 Type:ContSphereMultiCollision Type:ContSphereMultiCollision Type:ContSphereBruteForceCollision Type:ContSphereBruteForceCollision Type:ContSphereMultiCollision Type:ContSphereBruteForceCollision Type:ContSphereBruteForceCollision Acceleration data structure memory usage:5.63038e+06 Total memory usage: 3.10231e+08
sstrace Run-Time In static constructor, loads sstrace script based on environment variable Parse each probe, build master list of active probes and stores pre-parsed commands Each probe associated with command list Commands triggered at run-time
Implementation Triggers are C++ macros, may be disabled with compile-time option Total overhead for probes ~5% Probe binding during static constructor Pro: minimize overhead when probes disabled Con: Can't change trace script after program launch
Implementation #define T_PROBE_FUNCTION1(BASENAME, ARG0) \ static THookToProbe *__hook = TInitializeProbe(BASENAME); \ TProbeFunctionRef __probe_function; \ if (__hook) __probe_function = \ new TProbeFunction(__hook, TDataList(ARG0)) FluidSim::Step(float dt) { T_PROBE_FUNCTION1(“sim:FluidSim@Step”, dt); ... }
Implementation #define T_PROBE_FUNCTION1(BASENAME, ARG0) \ static THookToProbe *__hook = TInitializeProbe(BASENAME); \ TProbeFunctionRef __probe_function; \ if (__hook) __probe_function = \ new TProbeFunction(__hook, TDataList(ARG0)) • __hook is bound statically • If BASENAME is never referenced in the script, TInitializeProbe returns NULL
Implementation #define T_PROBE_FUNCTION1(BASENAME, ARG0) \ static THookToProbe *__hook = TInitializeProbe(BASENAME); \ TProbeFunctionRef __probe_function; \ if (__hook) __probe_function = \ new TProbeFunction(__hook, TDataList(ARG0)) • TProbeFunctionRef is a smart pointer • Basically like std::auto_ptr
Implementation #define T_PROBE_FUNCTION1(BASENAME, ARG0) \ static THookToProbe *__hook = TInitializeProbe(BASENAME); \ TProbeFunctionRef __probe_function; \ if (__hook) __probe_function = \ new TProbeFunction(__hook, TDataList(ARG0)) • Since __hook is bound statically, one test per function call • TProbeFunction triggers “enter” and “exit” probes in its constructor and destructor • Passes ARG0 down to the sstrace run-time as $ARG0
Related Work Solaris DTRACE Same concept, but probes operate at kernel level (e.g. break on file IO, thread start, timers, etc.) DTRACE does everything sstrace can do & more Aspect Oriented Programming (AOP) “aspects” not “objects” - dynamic emergent entities “code weaver” interleaves aspects with rest of code
Future Get a real interpreter Hook up 2D/3D visualization tools Allow control to pass to user (like gdb breakpoint) for interactive queries
An idea... What if this were a standard library? All 3rd party applications could use the same trace language Maybe Sun DTRACE team will do this? User-level DTRACE for compatibility with non-Solaris/BSD applications
Thanks Entire Sandstorm development team Spider-Man 3 sand team DTRACE team for the idea