Skip to content

reduce output to console for ADMB 13#312

Merged
Rick-Methot-NOAA merged 17 commits intomainfrom
console_cleanup
Sep 9, 2022
Merged

reduce output to console for ADMB 13#312
Rick-Methot-NOAA merged 17 commits intomainfrom
console_cleanup

Conversation

@k-doering-NOAA
Copy link
Copy Markdown
Contributor

@k-doering-NOAA k-doering-NOAA commented May 12, 2022

What issue(s) does this PR address? Describe and add issue numbers, if applicable.

Link issue(s) here:

#313 . The new ADMB console (#257) inspired me to make some changes to the SS3 console output

What tests have been done? Upload any model input files created for testing in a zip file, if possible.

Some of the changes have been tested locally by compiling and running a model

What tests/review still need to be done? Who can do it, and by when is it needed (ideally)?

When the last changes are made, the output should be looked at in github actions to make sure everything looks ok

Check which is true. This PR requires:

  • no further changes to r4ss
  • no further changes to the manual
  • no further changes to SSI (the SS3 GUI)
  • no further changes to the stock synthesis change log (new features, bug reports)

Describe any changes in r4ss/SS3 manual/SSI/change log that are needed (if not checked):

May need to check on r4ss and SSI

Additional information (optional):

@k-doering-NOAA
Copy link
Copy Markdown
Contributor Author

For reference, this is what the admb console output looks like for the simple admb model:

Starting optimization of 'simple' in phase 1 of 1 at Thu May 12 12:33:34 2022
phase= 1 | nvar=  2 | iter=  0 | nll=2.50e+01 | mag=3.61e+00 | par[  2]=b1
phase= 1 | nvar=  2 | iter=  7 | nll=3.45e+00 | mag=7.00e-05 | par[  2]=b1
Optimization completed after 0 s with final statistics:
 nll=3.451260 | mag=7.00140e-05 | par[  2]=b1

Checking for estimated parameters on bounds... none found!
Calculating Hessian: 1, 2 done! (0.019 s)
Inverting Hessian: 1, 2 done! (0 s)
Starting standard error calculations...  done! (0 s)

Finished running model 'simple' after 0.019 s.

This is what the SS3 console output looks like (including current changes made to this branch):

Begin reading the 4 required input files
Finished reading the 4 required input files

Begin setting up parameters
Finished setting up parameters
Begin evaluating biology calculations once
Finished evaluating biology calculations once


Begin estimating
Starting optimization of 'ss' in phase 1 of 5 at Thu May 12 12:30:50 2022
 did survey obj_fun  0 485.216 213.444
 did lencomp obj_fun   1613.44 408.812 0
 did agecomp obj_fun  2067.9 570.293 0
 did meanlength obj_fun  0 0 0
 initequ_catch -log(L)  0 0 0
 catch -log(L)  140920 0 0
 did recruitdev obj_fun -15.8356 31 0.72
 OK with obj_func 144812
phase= 1 | nvar=  3 | iter=  0 | nll=1.45e+05 | mag=1.98e+07 | par[  1]=SR_parm[1]
phase= 1 | nvar=  3 | iter= 20 | nll=9.09e+02 | mag=2.74e+02 | par[  1]=SR_parm[1]
phase= 1 | nvar=  3 | iter= 23 | nll=9.08e+02 | mag=8.54e+00 | par[  1]=SR_parm[1]
phase= 2 | nvar= 38 | iter=  0 | nll=9.08e+02 | mag=3.47e+02 | par[ 25]=recdev1[23]
phase= 2 | nvar= 38 | iter= 20 | nll=8.24e+02 | mag=5.65e+03 | par[  2]=SR_parm[1]
phase= 2 | nvar= 38 | iter= 40 | nll=7.99e+02 | mag=1.00e+03 | par[  2]=SR_parm[1]
phase= 2 | nvar= 38 | iter= 56 | nll=7.96e+02 | mag=1.29e+00 | par[ 18]=recdev1[16]
phase= 3 | nvar= 40 | iter=  0 | nll=7.96e+02 | mag=3.78e+00 | par[ 39]=selparm[4]
phase= 3 | nvar= 40 | iter= 20 | nll=7.96e+02 | mag=2.55e+01 | par[  2]=SR_parm[1]
phase= 3 | nvar= 40 | iter= 35 | nll=7.96e+02 | mag=9.24e-01 | par[  2]=SR_parm[1]
phase= 4 | nvar= 50 | iter=  0 | nll=7.96e+02 | mag=1.55e+01 | par[ 45]=selparm[11]
phase= 4 | nvar= 50 | iter= 20 | nll=7.95e+02 | mag=4.08e+02 | par[  6]=SR_parm[1]
phase= 4 | nvar= 50 | iter= 40 | nll=7.95e+02 | mag=6.13e+02 | par[  6]=SR_parm[1]
phase= 4 | nvar= 50 | iter= 60 | nll=7.95e+02 | mag=7.35e+00 | par[  6]=SR_parm[1]
phase= 4 | nvar= 50 | iter= 69 | nll=7.95e+02 | mag=3.70e-05 | par[ 45]=selparm[11]
phase= 5 | nvar= 60 | iter=  0 | nll=7.95e+02 | mag=3.70e-05 | par[ 55]=selparm[11]
Optimization completed after 31 s with final statistics:
 nll=794.959837 | mag=3.69930e-05 | par[ 55]=selparm[11]

Checking for estimated parameters on bounds... none found!
 writing big output now
Wrote bigoutput and bodywt for last_phase in REPORT_SECTION and before hessian, no benchmark or forecast
Calculating Hessian (60 variables): 20%, 40%, 60%, 80%, 100% done! (31 s)
Differentiating 8 derived quantities: do benchmark and forecast if requested in sdphase
1, 2, 3, 4, 5, 6, 7, 8 done! (2 m 11 s)
Inverting Hessian (60 variables): 20%, 40%, 60%, 80%, 100% done! (0.006 s)
Starting standard error calculations...  done! (0.42 s)

In final section
Finish time: Thu May 12 12:34:05 2022
Elapsed time: 0 hours, 3 minutes, 15 seconds.
 Iterations: 498 -log(L): 794.96
Final gradient: 3.6993e-05

 finished COVAR.SSO
 finished forecast
 finished StdDev quantities
 mceval counter: 0
 finished posteriors
 finished SS_summary.sso
 writing big output now
 finished report.sso
Creating bootstrap files: 1 files finished
 Write new starter file
 Write new forecast file
 Write new control file
dynamic Bzero in FINAL_SECTION:  finished
setup_benchmark:
SPR_profile:  finished
Global_MSY:  finished

!!  Run has completed  !!            See warning.sso for N warnings: 4

Finished running model 'ss' after 3 m 17 s.

This info is available with the default console for ADMB 13.
@iantaylor-NOAA
Copy link
Copy Markdown
Contributor

I just looked through all the changes. This all seems great to me. Moving more into echoinput.sso ensures that nothing is lost and the console output is easier to read with less info.
@k-doering-NOAA, it looks like the output in your example was run with rundetail = 0. Should we also consider a cleanup of output for rundetail = 1 or 2? Sorry if I'm failing to see edits to those outputs in the differences shown in github--I haven't downloaded the branch to try it out myself.

@k-doering-NOAA
Copy link
Copy Markdown
Contributor Author

I just looked through all the changes. This all seems great to me. Moving more into echoinput.sso ensures that nothing is lost and the console output is easier to read with less info. @k-doering-NOAA, it looks like the output in your example was run with rundetail = 0. Should we also consider a cleanup of output for rundetail = 1 or 2? Sorry if I'm failing to see edits to those outputs in the differences shown in github--I haven't downloaded the branch to try it out myself.

That was what I was thinking, too, more details in echoinput rather than the console.

And you are right about the run detail setting, thanks @iantaylor-NOAA! I'll try it with 1 and 2 as well. Any idea what most people would use as a default setting?

@iantaylor-NOAA
Copy link
Copy Markdown
Contributor

iantaylor-NOAA commented May 12, 2022

I really can't speak for what others use for rundetail setting in their starter file with SS3, but here's what I do:

  • 0 if I'm automating the running of lots of models and won't be looking at the console.
  • 1 is my default almost all the time
  • 2 if the model fails to run and I need to debug

However, with the revised ADMB output it's possible that I'll be inspired to use 0 more often.

@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

My logic similar to Ian's.
I'm sensing good energy on this topic and will let you run with it. What's in echoinput today is a hodgepodge of things I needed while developing. All those IF - write statements slow SS3 down to some degree.

Send more messages to echoinput than cout
@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

Johnoel got me set up with ADMB 13.0, so I can test now also. He is open to tweaks on the ADMB side if you see something in the console output that could be even better. make_ss_safe.bat has a few more explicit references now.

@k-doering-NOAA
Copy link
Copy Markdown
Contributor Author

Here is what option 0 output looks like now (using ADMB 13):

Reading the 4 required input files... done
Setting up parameters... done
Evaluating biology calculations once... done
Starting optimization of 'ss' in phase 1 of 5 at Tue May 24 09:27:24 2022
phase= 1 | nvar=  3 | iter=  0 | nll=1.45e+05 | mag=1.98e+07 | par[  1]=SR_parm[1]
phase= 1 | nvar=  3 | iter= 20 | nll=9.09e+02 | mag=2.74e+02 | par[  1]=SR_parm[1]
phase= 1 | nvar=  3 | iter= 23 | nll=9.08e+02 | mag=8.54e+00 | par[  1]=SR_parm[1]
phase= 2 | nvar= 38 | iter=  0 | nll=9.08e+02 | mag=3.47e+02 | par[ 25]=recdev1[23]
phase= 2 | nvar= 38 | iter= 20 | nll=8.24e+02 | mag=5.65e+03 | par[  2]=SR_parm[1]
phase= 2 | nvar= 38 | iter= 40 | nll=7.99e+02 | mag=1.00e+03 | par[  2]=SR_parm[1]
phase= 2 | nvar= 38 | iter= 56 | nll=7.96e+02 | mag=1.29e+00 | par[ 18]=recdev1[16]
phase= 3 | nvar= 40 | iter=  0 | nll=7.96e+02 | mag=3.78e+00 | par[ 39]=selparm[4]
phase= 3 | nvar= 40 | iter= 20 | nll=7.96e+02 | mag=2.55e+01 | par[  2]=SR_parm[1]
phase= 3 | nvar= 40 | iter= 35 | nll=7.96e+02 | mag=9.24e-01 | par[  2]=SR_parm[1]
phase= 4 | nvar= 50 | iter=  0 | nll=7.96e+02 | mag=1.55e+01 | par[ 45]=selparm[11]
phase= 4 | nvar= 50 | iter= 20 | nll=7.95e+02 | mag=4.08e+02 | par[  6]=SR_parm[1]
phase= 4 | nvar= 50 | iter= 40 | nll=7.95e+02 | mag=6.13e+02 | par[  6]=SR_parm[1]
phase= 4 | nvar= 50 | iter= 60 | nll=7.95e+02 | mag=7.35e+00 | par[  6]=SR_parm[1]
phase= 4 | nvar= 50 | iter= 69 | nll=7.95e+02 | mag=3.70e-05 | par[ 45]=selparm[11]
phase= 5 | nvar= 60 | iter=  0 | nll=7.95e+02 | mag=3.70e-05 | par[ 55]=selparm[11]
Optimization completed after 25 s with final statistics:
  nll=794.959837 | mag=3.69930e-05 | par[ 55]=selparm[11]

Wrote first version of output files (before hessian, benchmark, and forecast)
Calculating Hessian (60 variables): 20%, 40%, 60%, 80%, 100% done (24 s)
Differentiating 8 derived quantities: 1, 2, 3, 4, 5, 6, 7, 8 done (1 m 37 s)
Inverting Hessian (60 variables): 20%, 40%, 60%, 80%, 100% done (0.009 s)
Starting standard error calculations...  done (0.39 s)
Iterations: 498
Finished forecast
Writing wtatage.ss_new
mceval counter: 0
Finished posteriors
Finished final writing of report.sso
Begin writing *.ss_new output files... done
See warning.sso for N warnings: 4

Finished running model 'ss' after 2 m 29 s.

I'm fairly satisfied with how this looks, but please feel free to suggest changes, even if they are minor aesthetic ones!

Also one question about the Finished posteriors line, @Rick-Methot-NOAA ...should that be showing up for a MLE run?

@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

correct that significant output occurs in get_posteriors even in a MLE run. Thanks for checking.

@kellijohnson-NOAA
Copy link
Copy Markdown
Contributor

@Rick-Methot-NOAA I noticed that this pull request is still marked as a draft request. I wanted to make sure that it is still needed/wanted before I tried to fix the merge conflicts.

@k-doering-NOAA
Copy link
Copy Markdown
Contributor Author

@kellijohnson-NOAA Yes, we were just waiting until using admb 13 until merging in! So I think fixing merge conflicts would be helpful, but it could also be done later.

@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

I have changes in these files queued in the PR for D-M and Tweedie. Let me merge that one first. Great if both of you could take a look at it first. Ian reviewed it last week.

@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

in progress. @nschindler-noaa is resolving merge conflicts

@nschindler-noaa
Copy link
Copy Markdown
Contributor

All conflicts resolved. Just a matter of beginning/ending reading file comments and new message system (and new messages at end of run)).

@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

Excellent. Thanks Neal.

@nschindler-noaa nschindler-noaa marked this pull request as ready for review August 31, 2022 20:10
Comment thread SS_global.tpl Outdated
if (N_nudata > 0)
{
cout << "Creating bootstrap files: " << N_nudata << " files";
cout << "Begin writing *.ss_new output files... ";
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Space after files.

Comment thread SS_global.tpl Outdated

// SS_Label_Info_12.4.5 #Call fxn write_nucontrol() to produce control.ss_new
write_nucontrol();
cout << "done" << endl; // finish writing *.ss_new output files
Copy link
Copy Markdown
Contributor

@kellijohnson-NOAA kellijohnson-NOAA Sep 2, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suggest a more verbose statement such as

"Finished writing *.ss_new output files"

Comment thread SS_objfunc.tpl Outdated
}
if (do_once == 1)
cout << " did lencomp obj_fun " << length_like_tot << endl;
echoinput << "Finished lencomp obj_fun " << length_like_tot << endl;
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure that it matters but there are two spaces after "obj_fun".

Comment thread SS_param.tpl Outdated
ad_comm::adprogram_name = "ss";
echoinput << "now in PARAMETER_SECTION " << endl;
echoinput << "Begin setting up parameters" << endl;
cout << "Setting up parameters... ";
Copy link
Copy Markdown
Contributor

@kellijohnson-NOAA kellijohnson-NOAA Sep 2, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why are these statements on line 20 and 21 different? If you keep line 21 as is, I think there needs to be a space after "parameters" before the l-dots. APA style-guide says to treat the three dots as a word. This should be carried out throughout this pull request.

Comment thread SS_popdyn.tpl
Comment thread SS_popdyn.tpl
Comment thread SS_prelim.tpl Outdated
// SS_Label_Info_6.8.1 #Call fxn get_MGsetup() to copy MGparms to working array and applies time-varying factors
get_MGsetup(styr);
echoinput << " did MG setup" << endl;
echoinput << "Finished MG setup" << endl;
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Earlier you used "MGsetup" to better match the code base.

Comment thread SS_prelim.tpl
@nschindler-noaa
Copy link
Copy Markdown
Contributor

@Rick-Methot-NOAA , is it okay to merge even with more warnings?

@Rick-Methot-NOAA
Copy link
Copy Markdown
Collaborator

Can you find and send me the warnings file so we can review it before merging with the increased N warnings

Places spaces before/after and after ... to treat it as if
it is a word in its own right.
Nitpicky change to reduce spacing from 2 to 1 at
end of line for consistency.
Changes done to be more explicit.
Make the lines essentially match in what
is printed to the screen
versus what is saved in echoinput
MG setup is changed to MGsetup which matches
what the codebase is to help
users that are searching for parameter names.
@kellijohnson-NOAA
Copy link
Copy Markdown
Contributor

@Rick-Methot-NOAA I resolved all of the comments that I made with the last 7 commits. I think this is ready for your review because if my memory serves me correctly the first failing job will potentially change with the use of ADMB 13.0 and or the number of warnings expected needs to be changed.

@k-doering-NOAA
Copy link
Copy Markdown
Contributor Author

@kellijohnson-NOAA that is correct re the warnings job

@Rick-Methot-NOAA Rick-Methot-NOAA self-requested a review September 9, 2022 20:51
Copy link
Copy Markdown
Collaborator

@Rick-Methot-NOAA Rick-Methot-NOAA left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks Kathryn, Neal and Kelli. Looks great. Approving now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

change log use for issues that should appear in change log misc. output

Projects

Status: No status

5 participants