Improve output format of Carpet timer trees

Create issue
Issue #1232 resolved
Erik Schnetter created an issue

Marek Blazewicz reports:

I was using the timer tree in Carpet. Because it was not too nicely outputted, and I had to format it manually each time, I've fixed it ;).

Keyword:

Comments (8)

  1. Erik Schnetter reporter
    • removed comment

    Marek says:

    First for "untimed", the precision was 1, always. I unified it with other lines.

    Secondly I've changed the width of the column float field (duration in s.) to the maximal printed length. These are # digits before decimal sep. (.) + 1 for dec. sep. + precision. The length of the field is computed once (log10(total time (which I assume is the largest number))) and passed to children via recurrence, to avoid unnecessary computations.

    For '%' of total time I've used constant equation: 3 (log(100) + 1) + 1 + precision.

    Thanks to these changes the time tree looks like tree ;)

  2. Frank Löffler
    • changed status to open
    • removed comment

    The patch no longer applies, and since the output format seems to have changed in the meantime, there is no quick way to see how to merge.

  3. Roland Haas

    Most of this code (sizing columns by precision) was implemented in , but not for the untimed part. Pull request
    https://bitbucket.org/eschnett/carpet/pull-requests/43/timers-respect-precision-setting-for

    implements it for the untimed part as well. A before / after example using this parfile:

    ActiveThorns = "
      CoordBase
      Carpet
      CarpetReduce
      SymBase
      Timers
    "
    
    Cactus::cctk_show_schedule = no
    Carpet::output_timer_tree_every = 1024
    
    Timers::output_precision = 5
    

    Before:

    ------------------------------------------------------------------------------------------------------------------
    Time          Time       Imblnc       Timer                                               gettimeof  getrusage    
    percent       secs       percent                                                               secs       secs    
    ------------------------------------------------------------------------------------------------------------------
    100.00000%  0.00226 0.00000%  Evolve                                               0.002257   0.002219  5.844e+06 
    53.30084%  0.00120 0.00000%  |_CallAnalysis                                       0.001203   0.001184  3.114e+06  
    27.78024%  0.00063 0.00000%  | |_CCTK_ANALYSIS                                    0.000627   0.000616   1.62e+06  
    22.46345%  0.00051 0.00000%  | | |_CallFunction                                   0.000507   0.000504  1.318e+06  
    4.38635%  0.00010 0.00000%  | | | |_thorns                                        9.9e-05    9.6e-05  2.604e+05   
      18.1%      0.0          | | | |_untimed
       5.3%      0.0          | | |_untimed
    1.01905%  0.00002 0.00000%  | |_CCTK_CHECKPOINT                                   2.3e-05    2.4e-05  6.385e+04   
    1.32920%  0.00003 0.00000%  | |_CCTK_POSTSTEP                                       3e-05      3e-05  7.353e+04   
    2.25964%  0.00005 0.00000%  | |_OutputGH                                          5.1e-05      5e-05  1.199e+05   
    1.15197%  0.00003 0.00000%  | | |_OutputGH                                        2.6e-05    2.5e-05  2.414e+04   
       1.1%      0.0          | | |_untimed
      20.9%      0.0          | |_untimed
    27.64732%  0.00062 0.00000%  |_CallEvol                                           0.000624   0.000616  1.616e+06  
    1.19628%  0.00003 0.00000%  | |_CCTK_EVOL                                         2.7e-05    2.5e-05  6.141e+04   
    12.45016%  0.00028 0.00000%  | |_CCTK_PRESTEP                                     0.000281   0.000276  7.335e+05  
    9.74745%  0.00022 0.00000%  | | |_CallFunction                                    0.00022   0.000216  5.675e+05   
    1.28489%  0.00003 0.00000%  | | | |_thorns                                        2.9e-05    2.6e-05  7.512e+04   
       8.5%      0.0          | | | |_untimed
       2.7%      0.0          | | |_untimed
    1.10767%  0.00003 0.00000%  | |_CycleTimeLevels                                   2.5e-05    2.5e-05  6.917e+04   
    1.32920%  0.00003 0.00000%  | |_Poison                                              3e-05      3e-05  7.887e+04   
      11.6%      0.0          | |_untimed
    4.38635%  0.00010 0.00000%  |_CallRegrid                                          9.9e-05    9.7e-05  2.591e+05   
    1.28489%  0.00003 0.00000%  | |_CCTK_PREREGRID                                    2.9e-05    2.8e-05  7.511e+04   
       1.9%      0.0          | |_untimed
      12.1%      0.0          | untimed
    ------------------------------------------------------------------------------------------------------------------
    ------------------------------------------------------------------------------------------------------------------
    Time          Time       Imblnc       Timer                                               gettimeof  getrusage    
    percent       secs       percent                                                               secs       secs    
    ------------------------------------------------------------------------------------------------------------------
    100.01987%  0.01007 0.00000%  meta mode                                             0.01007   0.006001   2.61e+07 
    40.23845%  0.00405 0.00000%  |_meta mode                                          0.004052   0.003985  1.051e+07  
    2.55340%  0.00026 0.00000%  | |_enter_global_mode                                0.000257   0.000255  6.809e+05   
    25.04719%  0.00252 0.00000%  | |_global mode                                      0.002521   0.002476  6.535e+06  
    1.11277%  0.00011 0.00000%  | | |_enter_level_mode                               0.000112   0.000112   2.47e+05   
    15.69796%  0.00158 0.00000%  | | |_level(0)                                        0.00158   0.001541  4.067e+06  
       7.3%      0.0          | | |_untimed
      11.8%      0.0          | |_untimed
      59.8%      0.0          | untimed
    ------------------------------------------------------------------------------------------------------------------
    

    After:

    --------------------------------------------------------------------------------------------------------------
    Time          Time       Imblnc       Timer                                               gettimeof  getrusage
    percent       secs       percent                                                               secs       secs
    --------------------------------------------------------------------------------------------------------------
     100.00000%      0.00233    0.00000%  Evolve                                                0.00233   0.001576
      49.91416%      0.00116    0.00000%  |_CallAnalysis                                       0.001163   0.000742
      27.25322%      0.00064    0.00000%  | |_CCTK_ANALYSIS                                    0.000635   0.000398
      21.75966%      0.00051    0.00000%  | | |_CallFunction                                   0.000507   0.000326
       4.29185%      0.00010    0.00000%  | | | |_thorns                                         0.0001    6.1e-05
      17.46781%      0.00041              | | | |_untimed
       5.49356%      0.00013              | | |_untimed
       1.20172%      0.00003    0.00000%  | |_CCTK_POSTSTEP                                     2.8e-05    1.6e-05
       1.28755%      0.00003    0.00000%  | |_OutputGH                                            3e-05      2e-05
      19.22747%      0.00045              | |_untimed
      29.57082%      0.00069    0.00000%  |_CallEvol                                           0.000689   0.000488
       1.07296%      0.00003    0.00000%  | |_CCTK_EVOL                                         2.5e-05    1.9e-05
      12.83262%      0.00030    0.00000%  | |_CCTK_PRESTEP                                     0.000299   0.000218
       9.82833%      0.00023    0.00000%  | | |_CallFunction                                   0.000229   0.000164
       1.45923%      0.00003    0.00000%  | | | |_thorns                                        3.4e-05    2.7e-05
       8.36910%      0.00020              | | | |_untimed
       3.00429%      0.00007              | | |_untimed
       1.11588%      0.00003    0.00000%  | |_CycleTimeLevels                                   2.6e-05    1.9e-05
       1.33047%      0.00003    0.00000%  | |_Poison                                            3.1e-05    2.3e-05
      13.21888%      0.00031              | |_untimed
       5.06438%      0.00012    0.00000%  |_CallRegrid                                         0.000118    8.9e-05
       1.41631%      0.00003    0.00000%  | |_CCTK_PREREGRID                                    3.3e-05    2.6e-05
       2.31760%      0.00005              | |_untimed
      13.34764%      0.00031              | untimed
    --------------------------------------------------------------------------------------------------------------
    --------------------------------------------------------------------------------------------------------------
    Time          Time       Imblnc       Timer                                               gettimeof  getrusage
    percent       secs       percent                                                               secs       secs
    --------------------------------------------------------------------------------------------------------------
     100.01924%      0.01040    0.00000%  meta mode                                              0.0104   0.009338
      40.35594%      0.00419    0.00000%  |_meta mode                                          0.004197   0.003148
       2.19336%      0.00023    0.00000%  | |_enter_global_mode                                0.000228   0.000163
      25.35835%      0.00264    0.00000%  | |_global mode                                      0.002636   0.002089
       1.06782%      0.00011    0.00000%  | | |_leave_level_mode                               0.000111    8.9e-05
      16.07504%      0.00167    0.00000%  | | |_level(0)                                       0.001671   0.001324
       7.24387%      0.00075              | | |_untimed
      11.95767%      0.00124              | |_untimed
      59.67292%      0.00620              | untimed
    --------------------------------------------------------------------------------------------------------------
    

    There remains some hard-coding, namely there is an assumption that the number of seconds will never require more than 6 digits (+ 1 char for the “dot” plus precision) for the integer part, ie fewer than 999999s or about 11.5days. If there is ever a cluster that allows for longer run times than that, then this may need to be adjusted.

    Please review.

  4. Log in to comment