Profiling and determining the time taken by each subroutine

[csp]

Dear Experts,
I tried to write and add some microphysical subroutines in the SCAM model. But unfortunately, the SCAM had slowed down tremendously, thus I am trying to figure out which subroutine is taking the maximum time. In this regard I want to profile the code, is there any way we can do that in the CESM? Any comment would be very much appreciated, many thanks in advance.

 

[peverley]

Hello!

One way to do this is to use the shr_timer_mod.F90 module located here: $CAM/share/src/shr_timer_mod.F90.

You'll want to do something like this:

use shr_timer_mod, only: shr_timer_init, shr_timer_get, shr_timer_start, shr_timer_stop
use shr_log_mod, only: shr_log_setLogUnit
use cam_logfile, only: iulog

integer :: t0
call shr_timer_init()
call shr_log_setLogUnit(iulog)
call shr_timer_get(t0, "some string to identify your timer")
call shr_timer_start(t0)
<CODE OR CALL TO SUBROUTINE YOU ARE TRYING TO PROFILE>
call shr_timer_stop(t0)
call shr_timer_print(t0)

You can also use multiple timers and the shr_timer_printall() function.

Also, if you want to instead look at memory usage, you can use shr_mem_getusage() [from shr_mem_mod.F90 module in the same $CAM/share/src/ folder] before and after the code you're profiling and then print the results to the log.

Hope that helps.
Courtney

 

[csp]

Hi,
Many thanks, Courtney @peverley for your reply and help, in fact, I was waiting for any comment/help, for a long time. I have some follow-up questions:

1. There are 3 files of the name *shr_timer_mod.F90* at the following locations:

• ./cime/tools/mapping/gen_mapping_files/runoff_to_ocn/src/shr_timer_mod.F90
• ./cime/src/share/util/shr_timer_mod.F90
• ./components/clm/tools/mksurfdata_map/src/shr_timer_mod.F90

I guess, I need to do the modification at *./cime/src/share/util/shr_timer_mod.F90* ?

2. This file (attached herewith, changed the format from *.F90 to *.txt, otherwise difficult to upload it) already has multiple lines of code, should I add the lines that you suggested in that file?

3. Will this file be by default called, and executed, and give me a log file detailing the time spent for every subroutine or do I need to run this file separately?

4. Sorry for my 3rd question, I have been naive and new to the CESM; but how, where, and in which format I will obtain the logfile?

5. Suppose, if I need to check the time spent on all the subroutines for the files *nucleate_ice_cam.F90* and *zm_microphysics.F90*, then in the above code, I should use as:

call shr_timer_start(t0)
nucleate_ice_cam.F90
zm_microphysics.F90
call shr_timer_stop(t0)

I am again extremely sorry for my ignorance and I am very grateful for your consistent help, highly appreciate that.

 

[peverley]

Hi again,

Sorry for the confusion. Let me explain (hopefully) more clearly.

You shouldn't have to modify any code in shr_timer_mod.F90; instead, you'll be using those subroutines (adding them to the source code) to get a timer going.

STEP 1: You'll want to initialize the timer module somewhere early in the run process so you have access to a timer whenever you need it. A good place for this could be in cam_init in cam_comp.F90. You'll need to add the following lines (in bold) to cam_comp.F90 to do this:

use cam_abortutils, only: endrun
use shr_timer_mod, only: shr_timer_init
...
call shr_timer_init()
call init_pio_subsystem()

STEP 2: It looks like one thing you want to profile is in zm_microphysics.F90. If, for example, the subroutine that you want to profile is zm_mphy, you would find where that is called (in this case in zm_conv.F90) and make the following additions to the top of the module:

use cam_history, only: outfld
use shr_timer_mod, only: shr_timer_get, shr_timer_start, shr_timer_end, shr_timer_print
use shr_log_mod, only: shr_log_setLogUnit

And then to the cldprp subroutine from which zm_mphy is called:

logical done(pcols)
integer t0
integer shrlogunit
...
call shr_log_getLogUnit(shrlogunit)
call shr_log_setLogUnit(iulog)
call shr_timer_get(t0, "some unique string to identify your timer")
call shr_timer_start(t0)
call zm_mphy(...)
call shr_timer_stop(t0)
call shr_timer_print(t0)
call shr_log_setLogUnit(shrlogunit)

STEP 3: In your case directory, change the number of tasks to 1 and then do a clean rebuild. (Since you're running SCAM and that only has one task by default, you should be able to skip the first two lines below)

./xmlchange NTASKS=1
./case.setup --reset
./case.build --clean-all
./case.build
./case.submit

The results of your timer should be output in the run/atm.log.* file and you'll be able to identify the output with the string you specified in your call shr_timer_get() statement.

Hope that all helps! Let me know if anything is unclear or if you run into any trouble.
Courtney