Skip to content

Introduce --stats #3839

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Apr 25, 2025
Merged

Introduce --stats #3839

merged 3 commits into from
Apr 25, 2025

Conversation

mtzguido
Copy link
Member

This adds a --stats option to print out the time spent in several places of the compiler (we should add more). It displays the number of calls to a given "key", the total time taken by the calls, the time taken by the calls ignoring subcalls, and the time spent before raising an exception.
Example for the report in #3800:

$ ./bin/fstar.exe Bug3800.fst --stats --admit_smt_queries true
Verified module: Bug3800
All verification conditions discharged successfully
Stats:
                   key     calls      tree     point       exn
             norm_term   1471862  28148 ms  28148 ms      0 ms
           tc_one_file         8  40820 ms   8011 ms      0 ms
             norm_comp         4   4658 ms   4658 ms      0 ms
    Parser.Dep.collect         1      4 ms      3 ms      0 ms
                 parse         2      0 ms      0 ms      0 ms
           simplify_vc      1290  21075 ms      0 ms      0 ms
         desugar_decls         1      0 ms      0 ms      0 ms
      hash_dependences         7      0 ms      0 ms      0 ms
      deep_compress_se        15      0 ms      0 ms      0 ms

So out of 40 seconds it takes to check the file, 28 are spent in normalizing terms. 21s are spent under simplify_vc, but they are completely accounted by measured subcalls (in this case normalization).

There is support for profiling already. I wrote this since I wanted an easy way to see where time is being spent without having to look up the profiling tags. Also, --profile requires a module name, which is not really useful. We could coallesce profiling into these new stats?

Also, uncommenting this line

let profile  (f: unit -> 'a) (module_name:option string) (cid:string) : 'a =
  //Stats.record cid fun () ->

will cause all profiling events to be recorded as stats. And that makes the example above look something like:

Stats:
                                                          key     calls      tree     point       exn
  FStarC.TypeChecker.Normalize.normalize_with_primitive_steps   1471862  29453 ms  29453 ms      0 ms
                  FStarC.TypeChecker.Normalize.normalize_comp         4   4663 ms   4663 ms      0 ms
                             FStarC.TypeChecker.Tc.encode_sig        15  10016 ms   4149 ms      0 ms
                        FStarC.Universal.tc_source_file.check         1  44139 ms   4092 ms      0 ms
           FStarC.SMTEncoding.EncodeTerm.normalize_refinement   1441772   6146 ms    601 ms      0 ms
                                                    norm_term   1471862  30037 ms    583 ms      0 ms
                       FStarC.TypeChecker.Normalize.normalize   1471862  30603 ms    566 ms      0 ms
                                FStarC.Universal.extend_tcenv         7     19 ms     19 ms      0 ms
                                          FStarC.CheckedFiles         8     18 ms     18 ms      0 ms
                                  FStarC.TypeChecker.Rel.whnf     24326     48 ms      9 ms      0 ms
        FStarC.TypeChecker.Rel.try_solve_deferred_constraints       320     40 ms      5 ms      0 ms
                   FStarC.TypeChecker.Tc.tc_sig_let-tc-phase1         1  17751 ms      4 ms      0 ms
                       FStarC.TypeChecker.Rel.check_subtyping      1096     23 ms      4 ms      0 ms
                                           Parser.Dep.collect         1      3 ms      2 ms      0 ms
                   FStarC.TypeChecker.Tc.tc_sig_let-tc-phase2         1   8520 ms      1 ms      0 ms
                                   FStarC.Parser.Dep.discover         1      1 ms      0 ms      0 ms
                                                        parse         2      0 ms      0 ms      0 ms
                  FStarC.TypeChecker.Rel.normalize_refinement       186      0 ms      0 ms      0 ms
                           FStarC.TypeChecker.Util.generalize         2      0 ms      0 ms      0 ms
                       FStarC.TypeChecker.Tc.process_one_decl        15  36291 ms      0 ms      0 ms
                           FStarC.TypeChecker.Rel.simplify_vc      1290  21534 ms      0 ms      0 ms
                                                desugar_decls         1      0 ms      0 ms      0 ms
                                                  simplify_vc      1290  21534 ms      0 ms      0 ms
        FStarC.TypeChecker.Rel.solve_deferred_to_tactic_goals       318      0 ms      0 ms      0 ms
                               FStarC.TypeChecker.Rel.try_teq        32      0 ms      0 ms      0 ms
                                             hash_dependences         7      0 ms      0 ms      0 ms
                                             deep_compress_se        15      0 ms      0 ms      0 ms
                                                  tc_one_file         8  44178 ms      0 ms      0 ms
                              FStarC.TypeChecker.Rel.sub_comp         2  21530 ms      0 ms      0 ms
                FStarC.SMTEncoding.EncodeTerm.norm_with_steps        76      0 ms      0 ms      0 ms
                                    FStarC.TypeChecker.Rel.sn        66      0 ms      0 ms      0 ms
                        FStarC.Universal.tc_source_file.parse         1      0 ms      0 ms      0 ms
                     FStarC.TypeChecker.Rel.norm_with_steps.8        66      0 ms      0 ms      0 ms
               FStarC.SMTEncoding.Encode.norm_before_encoding        32   3475 ms      0 ms      0 ms
                 FStarC.Parser.Dep.topological_dependences_of         1      0 ms      0 ms      0 ms
                             FStarC.TypeChecker.Tc.tc_sig_let         1  26271 ms      0 ms      0 ms
                                                    norm_comp         4   4663 ms      0 ms      0 ms

(see also the 10s in encode_sig!)

@mtzguido
Copy link
Member Author

Updated to take a boolean (--stats true/--stats false) so it can be enabled and disabled, and even pushed/popped within a file. Stats are only counted while the option is enabled, and reported before exit if they were ever enabled.

@mtzguido mtzguido enabled auto-merge April 25, 2025 20:38
@mtzguido mtzguido merged commit 12742b4 into FStarLang:master Apr 25, 2025
10 checks passed
@mtzguido mtzguido deleted the stats branch April 25, 2025 21:10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant