Phoenix time reporting mechanisms

Phoenix time reporting mechanisms

  • Comments 5

Hey everyone, this is Renin John, an SDET from the Phoenix compiler backend team. If you are wondering what Phoenix is, take a look at: http://connect.microsoft.com/phoenix and/or http://channel9.msdn.com/Showpost.aspx?postid=396461.

 

During the compiler development process, several changes (features, fixes, …) are constantly made to the compiler. One of the roles in my position is to analyze the underlying cause for any unexpected throughput (time taken to compile/build) degradation that might arise as a result of any of those changes. I am going to show you how I use the Phoenix time reporting mechanisms to perform this analysis. This technique will help you gain a detailed understanding of all the stages of compilation that your code is going through, where the compiler is spending its maximum time, etc.

 

-d2timereport: This is to enable timereporting and display timing information. None of the other time reporting switches work without specifying this.

Please note that as of now, all the switches mentioned in this blog don’t play well with multithreading. Hence you must add -d2threads=0 to the command line, failing which the output would be non-deterministic or it could also throw an error.

Syntax: cl -d2timereport -d2threads=0 <source file>

 

The output would look like this (-timereport filters out anything that is less than 1% of overall time):

----------------------------------------:-----------------------------------------------------------------------

Overall Time Report                     :   Inclusive     (%)   Exclusive    (%)         Max        Mean  Count

----------------------------------------:-----------------------------------------------------------------------

 Total                                  :     0.00580 100.000     0.00261  45.118     0.00580     0.00580      1

  Driver::CompileModule                 :     0.00318  54.882     0.00029   4.969     0.00318     0.00318      1

 

LIR Phases                      :     0.00161  27.864     0.00007   1.272     0.00095     0.00081      2

  Alias analysis                :     0.00014   2.445     0.00013   2.304     0.00007     0.00007      2

 

 

“Inclusive” means time spent in this event and any sub-events.

“Exclusive” is time spent in this event that was not spent in a sub-event.

“Count” is a cheap way to find out how many functions were compiled, or inlined, etc.

“Max” vs “Mean” can give you an idea whether compilation time was dominated by one function, …

 

-d2timepercent=<n> where “n” indicates the threshold level for displaying timing stats. When n=0, it displays a complete report with all the phases and does not filter out any information.

Syntax: cl -d2timereport -d2timepercent=0 -d2threads=0 <source file>

Compare the sample output above and below (when n=0). Now, the different phases under Alias Analysis get reported as well.

----------------------------------------:-----------------------------------------------------------------------

Overall Time Report                     :   Inclusive     (%)   Exclusive    (%)         Max        Mean  Count

----------------------------------------:-----------------------------------------------------------------------

 Total                                  :     0.00580 100.000     0.00261  45.093     0.00580     0.00580      1

  Driver::CompileModule                 :     0.00318  54.907     0.00029   4.966     0.00318     0.00318      1

...

LIR Phases                      :     0.00161  27.806     0.00007   1.268     0.00094     0.00081      2

  Alias analysis                :     0.00014   2.446     0.00013   2.306     0.00007     0.00007      2

    PrePhase                    :     0.00000   0.005     0.00000   0.005     0.00000     0.00000      2

    PartialFlowGraph::Build     :     0.00000   0.049     0.00000   0.049     0.00000     0.00000      4

    FlowGraph::Build            :     0.00000   0.077     0.00000   0.077     0.00000     0.00000      2

    PostPhase                   :     0.00000   0.009     0.00000   0.009     0.00000     0.00000      2

 

-d2timefunc=<x> where “x” indicates the specific functions to be timed. “x” could be a function number, a range of function numbers (say 2-7) or a function name, starting with # (eg. #foo).

Syntax: cl -d2timereport -d2timefunc=#<function name> -d2threads=0 <source file>

The list of function names and numbers can be seen by passing in the “-d2dumpfuncname -d2threads=0” switches (works only with the SDK c2).

 

Take a look at the following sample output generated from using -d2timefunc=1. It says that the main function took 16.526% of total compile time, out of which 6.329% of the time was spent on Alias analysis.

Function Times: Interval-Phase Summary Report

Interval: main 0.0010629s [16.526% of total]

   0.0000637s ( 5.997%) CxxIL Reader

   0.0000673s ( 6.329%) Alias analysis

   0.0000281s ( 2.647%) Flow Optimization

 

-d2timereportmachinereadable: This produces a tab-separated timing report.

Syntax: cl -d2timereport -d2timereportmachinereadable -d2threads=0 <source file> > <.tsv results file>

This is helpful in situations where you need to perform further analysis/calculations with the results and for automation.

 

If you are not already aware, -d2xx is used to pass xx to the backend (c2.dll). You could also use these switches at link time in the form -d2:-xx.

The exhaustive list of all our tool controls are discoverable using “-d2dumpctrls” or “-d2?” (works only with the SDK c2).

 

 

I hope you enjoyed this post, and look forward to hearing back from you.

 

Thanks!

  • Phoenix is so awesome. I can't wait to actually use it for something!

  • Is Phoenix going to be the compiler shipped with Visual Studio Rosario or only on the Rosario+1 version?

  • Super.  Can we get this integrated into the GUI somehow?  So we can debug compile time as a regular engineering task.

    I've asked for this every time I've met the VC++ team I think...  :^)

    Thanks!

  • Actually, to add to my comment...  it's really only useful to engineers if you can link this back to source code artifacts in some way.  Otherwise I don't know what code is causing the compiler to grab the CPU for 10 seconds per file.  :^/

  • Dear Mr. Renin John,

    That was an excellent briefing. Hope you come out with more such explanations. Best of luck.

    Dr. CMT. Ph.D

Page 1 of 1 (5 items)