search

GEOS-ESM / MAPL

MAPL is a foundation layer of the GEOS architecture, whose original purpose is to supplement the Earth System Modeling Framework (ESMF)
https://geos-esm.github.io/MAPL/
Apache License 2.0
25 stars 18 forks source link

Enable rerouting profile information to a log file through pFlogger #1419

Open tclune opened 2 years ago

tclune commented 2 years ago

Currently ProfileReporter returns an string array. MAPL_Generic.F90 then writes the elements of this array to OUTPUT_UNIT. Instead, this should be a call to the logging layer. Something like:

lgr => logging%get_logger('MAPL.profiler')
do i = 1, size(report)
    call lgr%info('%a ', report(i)
end do

For the component timers this should be fine. For the global timers, some work is needed as we don't want profiler itself to have a dependency on pFlogger. So we would instead move the writing back to ApplicationSupport.

@lizziel

tclune commented 2 years ago

I've decided that some aspects of the requested changes for profiler can go in on the development branch after all. In particular, the use of pFlogger for routing the output and the uptick in the number of digits used.

tclune commented 2 years ago

@lizziel For the global timers, I have introduced a new logger called 'MAPL.PROF', but for the per-gridcomp timers we have a choice. I can have them go through the same 'MAPL.PROF', or we can have a logger off the gridcomp: '.PROF'.

It really depends on whether you think you'll want to send them all to the same place or not. If we need both approaches, we can later add a switch to toggle.

tclune commented 2 years ago

OK - rerouting through pflogger was quite easy. I'm now working on the CSV aspect in the same branch. Here is an example output from my first attempt:

Times for component <GCM>
                                                                 Min                            Mean                           Max                     PE         # cycles
                                                     ============================   ============================   ============================   =============   ========
Full Name                                              %    inclusive  exclusive      %    inclusive  exclusive      %    inclusive  exclusive     max    min
,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,, , ------ ---------- ---------- , ------ ---------- ---------- , ------ ---------- ---------- , ------ ------ ,
GCM                                                ,   0.00     225.11       0.00 ,   0.00     225.14       0.00 ,   0.00     225.18       0.00 ,  00004  00001 ,       27
GCM.SetService                                     ,   0.66       2.22       1.46 ,   0.66       2.23       1.48 ,   0.67       2.28       1.53 ,  00000  00002 ,        1
GCM.SetService.generic                             ,   0.34       0.75       0.75 ,   0.33       0.75       0.75 ,   0.33       0.75       0.75 ,  00001  00003 ,        1
GCM.SetService.generic.Initialize                  ,   0.00      22.45       0.00 ,   0.00      22.48       0.00 ,   0.00      22.52       0.00 ,  00004  00003 ,        1
GCM.SetService.generic.Initialize.INITIALIZE       ,   1.15      22.45       2.57 ,   1.16      22.48       2.61 ,   1.16      22.52       2.64 ,  00004  00000 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM  ,   8.76      19.52      19.52 ,   8.67      19.52      19.52 ,   8.59      19.52      19.52 ,  00000  00005 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.01       0.03       0.03 ,   0.01       0.03       0.03 ,   0.01       0.03       0.03 ,  00003  00000 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.01       0.01       0.01 ,   0.01       0.01       0.01 ,   0.01       0.02       0.02 ,  00000  00001 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.06       0.14       0.14 ,   0.06       0.14       0.14 ,   0.06       0.14       0.14 ,  00005  00000 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.07       0.17       0.17 ,   0.07       0.17       0.17 ,   0.08       0.17       0.17 ,  00004  00000 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.04       0.00 ,   0.00       0.04       0.00 ,   0.00       0.04       0.00 ,  00004  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.01       0.03       0.03 ,   0.01       0.03       0.03 ,   0.02       0.03       0.03 ,  00004  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,  00004  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,  00004  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,   0.00       0.01       0.01 ,  00000  00001 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,  00000  00003 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00     186.97       0.00 ,   0.00     186.97       0.00 ,   0.00     186.97       0.00 ,  00004  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00     186.97       0.00 ,   0.00     186.97       0.00 ,   0.00     186.97       0.00 ,  00003  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.01     186.97       0.02 ,   0.01     186.97       0.03 ,   0.02     186.97       0.03 ,  00002  00003 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00     186.11       0.00 ,   0.00     186.11       0.00 ,   0.00     186.12       0.00 ,  00002  00000 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,  83.47     186.11     186.11 ,  82.66     186.11     186.11 ,  81.86     186.12     186.12 ,  00003  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.10       0.23       0.23 ,   0.10       0.23       0.23 ,   0.10       0.23       0.23 ,  00002  00001 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.33       0.00 ,   0.00       0.41       0.00 ,   0.00       0.48       0.00 ,  00003  00002 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.15       0.33       0.33 ,   0.18       0.41       0.41 ,   0.21       0.48       0.48 ,  00001  00000 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.05       0.12       0.12 ,   0.08       0.19       0.19 ,   0.12       0.26       0.26 ,  00000  00001 ,       12
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00      13.40       0.00 ,   0.00      13.42       0.00 ,   0.00      13.44       0.00 ,  00000  00004 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   5.12      11.41      11.41 ,   5.45      12.27      12.27 ,   5.88      13.36      13.36 ,  00000  00005 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.02       0.04       0.04 ,   0.50       1.13       1.13 ,   0.87       1.98       1.98 ,  00005  00000 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,   0.00       0.00       0.00 ,  00000  00005 ,        1
GCM.SetService.generic.Initialize.INITIALIZE.AGCM. ,   0.00       0.00       0.00 ,   0.01       0.02       0.02 ,   0.02       0.04       0.04 ,  00002  00004 ,        1

Two observations:

  1. It may be tricky in GEOS to allow enough space for the "full name" of a component to be written out. The current approach assumes a table and can't be elastic per row, so needs more thought. For now I'm bumping the width of the 1st column up to 150 from 50 to see if that is enough.
  2. Commas for the header info are more problematic, but maybe not a serious issue? I should be able to do better.

Together these suggest that maybe CSV is not just a minor formatting tweak, but requires a different approach for conversion.

tclune commented 2 years ago

OK - realized the mistake I was making in creating the long timer names. And a couple of other things, so CSV is close now:

Times for component <MOIST>
                                                                   Min                                Mean                               Max                        PE          # cycles
                                                     ================================   ================================   ================================   ===============   ========
Full Name                                              %      inclusive    exclusive      %      inclusive    exclusive      %      inclusive    exclusive     max      min
                                                   , ------ , ---------- , ---------- , ------ , ---------- , ---------- , ------ , ---------- , ---------- , ------ , ------ ,
MOIST                                              ,   0.00 ,       3.63 ,       0.00 ,   0.00 ,       3.77 ,       0.00 ,   0.00 ,       4.40 ,       0.00 ,  00005 ,  00001 ,        5
MOIST.SetService                                   ,   1.54 ,       0.05 ,       0.05 ,   1.50 ,       0.06 ,       0.06 ,   1.38 ,       0.06 ,       0.06 ,  00000 ,  00004 ,        1
MOIST.SetService.generic                           ,   0.00 ,       0.00 ,       0.00 ,   0.00 ,       0.00 ,       0.00 ,   0.00 ,       0.00 ,       0.00 ,  00005 ,  00002 ,        1
MOIST.Initialize                                   ,   0.10 ,       2.41 ,       0.00 ,   0.16 ,       2.43 ,       0.01 ,   0.21 ,       2.46 ,       0.01 ,  00000 ,  00001 ,        1
MOIST.Initialize.generic                           ,  67.09 ,       2.40 ,       2.40 ,  64.17 ,       2.42 ,       2.42 ,  54.87 ,       2.45 ,       2.45 ,  00001 ,  00000 ,        1
MOIST.Record                                       ,   0.00 ,       0.00 ,       0.00 ,   0.00 ,       0.00 ,       0.00 ,   0.00 ,       0.00 ,       0.00 ,  00003 ,  00005 ,        1
MOIST.Record.generic                               ,   0.00 ,       0.00 ,       0.00 ,   0.00 ,       0.00 ,       0.00 ,   0.00 ,       0.00 ,       0.00 ,  00003 ,  00002 ,        1
MOIST.Run                                          ,   0.00 ,       0.70 ,       0.00 ,   0.00 ,       0.85 ,       0.00 ,   0.00 ,       1.50 ,       0.00 ,  00000 ,  00004 ,        1
MOIST.Run.GenRunMine                               ,   0.00 ,       0.70 ,       0.00 ,   0.00 ,       0.85 ,       0.00 ,   0.00 ,       1.50 ,       0.00 ,  00000 ,  00003 ,        1
MOIST.Run.GenRunMine.DRIVER                        ,   0.18 ,       0.70 ,       0.01 ,   0.22 ,       0.85 ,       0.01 ,   0.33 ,       1.50 ,       0.01 ,  00000 ,  00002 ,        1
MOIST.Run.GenRunMine.DRIVER.MISC1                  ,   1.44 ,       0.17 ,       0.05 ,   1.45 ,       0.17 ,       0.05 ,   1.35 ,       0.18 ,       0.06 ,  00000 ,  00004 ,        1
MOIST.Run.GenRunMine.DRIVER.MISC1.USE_AEROSOL_NN1  ,   3.20 ,       0.11 ,       0.11 ,   3.10 ,       0.12 ,       0.12 ,   2.69 ,       0.12 ,       0.12 ,  00001 ,  00003 ,        1
MOIST.Run.GenRunMine.DRIVER.PRE_RAS                ,   0.46 ,       0.02 ,       0.02 ,   0.44 ,       0.02 ,       0.02 ,   0.37 ,       0.02 ,       0.02 ,  00000 ,  00004 ,        1
MOIST.Run.GenRunMine.DRIVER.GF                     ,   6.27 ,       0.22 ,       0.22 ,   9.66 ,       0.36 ,       0.36 ,  21.68 ,       0.97 ,       0.97 ,  00000 ,  00005 ,        1
MOIST.Run.GenRunMine.DRIVER.POST_RAS               ,   0.43 ,       0.02 ,       0.02 ,   0.42 ,       0.02 ,       0.02 ,   0.38 ,       0.02 ,       0.02 ,  00000 ,  00002 ,        2
MOIST.Run.GenRunMine.DRIVER.UWSHCU                 ,   1.89 ,       0.07 ,       0.07 ,   1.87 ,       0.07 ,       0.07 ,   1.72 ,       0.08 ,       0.08 ,  00000 ,  00004 ,        1
MOIST.Run.GenRunMine.DRIVER.MISC2                  ,   0.10 ,       0.00 ,       0.00 ,   0.13 ,       0.01 ,       0.01 ,   0.22 ,       0.01 ,       0.01 ,  00000 ,  00001 ,        1
MOIST.Run.GenRunMine.DRIVER.CLOUD                  ,   0.24 ,       0.18 ,       0.01 ,   0.25 ,       0.19 ,       0.01 ,   0.30 ,       0.20 ,       0.01 ,  00000 ,  00001 ,        1
MOIST.Run.GenRunMine.DRIVER.CLOUD.USE_AEROSOL_NN3  ,   0.28 ,       0.01 ,       0.01 ,   0.31 ,       0.01 ,       0.01 ,   0.28 ,       0.01 ,       0.01 ,  00004 ,  00002 ,        1
MOIST.Run.GenRunMine.DRIVER.CLOUD.CLOUD_RUN        ,   4.49 ,       0.16 ,       0.16 ,   4.38 ,       0.17 ,       0.17 ,   3.98 ,       0.18 ,       0.18 ,  00000 ,  00003 ,        1
MOIST.Run.GenRunMine.DRIVER.MISC3                  ,   0.27 ,       0.01 ,       0.01 ,   0.29 ,       0.01 ,       0.01 ,   0.35 ,       0.02 ,       0.02 ,  00000 ,  00005 ,        1
MOIST.Finalize                                     ,   0.00 ,       0.43 ,       0.00 ,   0.00 ,       0.44 ,       0.00 ,   0.00 ,       0.44 ,       0.00 ,  00005 ,  00001 ,        1

Still need to find a simple way to eliminate the vertical separations === and ---. Also need to get some commas into the headers. And finally, for the multi-column headers, I need to find a way to introduce additional commas. Probably have to put this aside again for a few days, but will at least push my branch feature/tclune/#1419-profiling-with-pflogger

mathomp4 commented 2 years ago

@tclune I suppose if the separator can be defined at runtime, you could use commas, or pipes or even spaces (as CSV has been sort of overloaded in practice to be "any-character" separated values").

tclune commented 2 years ago

Yeah the actual character to use is less crucial. The hardish part is dealing with the multicolumn headers.