Skip to content
This repository has been archived by the owner on Apr 6, 2023. It is now read-only.

Timeout errors for Examples/Advanced/CustomProperties/Hydrocarbon_Processing_example.ipynb #81

Closed
lbianchi-lbl opened this issue Dec 20, 2021 · 25 comments
Assignees
Labels
Priority:Normal Normal Priority Issue or PR

Comments

@lbianchi-lbl
Copy link
Contributor

The maximum runtime allowed for a single notebook is limited to the value of the timeout parameter in build.yml, which is currently set to 600 s for our CI builds. If a notebook takes longer than that to run, it results in an error.

 2021-12-20 05:55:53,309 ERROR - [Worker 0] Failed to convert /home/runner/work/examples-pse/examples-pse/src/Examples/Advanced/CustomProperties/Hydrocarbon_Processing_example.ipynb: timeout for '/tmp/tmpcmwownao/Hydrocarbon_Processing_example.ipynb': 644.0461659431458s > 600s

Lately, this seems to be happening often for the Examples/Advanced/CustomProperties/Hydrocarbon_Processing_example.ipynb notebook, resulting in failing CI runs in both our nightly builds and unrelated PRs such as #80.

We should look into why the notebook is taking longer than it used to (since, until lately, the runtime was below the 600 s timeout), and, more in general, see if there could be ways to modify the notebook so that it runs as quickly as possible.

@adowling2
Copy link
Contributor

@lbianchi-lbl Is there any easy way to look at the notebook output (from CI) once it finished running? Did it finish in 644.05 seconds, or is that when CI decided to kill it?

@agarciadiego is this your notebook?

@lbianchi-lbl
Copy link
Contributor Author

@adowling2 These are both excellent questions. I can create a PR on this repo disabling the timeout (i.e. setting it to a very high value) and configuring the CI workflow so that the HTML docs are saved after the build (which is something we wanted to have anyways).

I'm currently testing the examples on our build system for the release and I'm also running into the same issue with a timeout, even when set to 1200 s. This does not prove that the notebook would continue to run indefinitely, but seems to at least indicate that it's not a matter of a slight variation in the runtime around the timeout threshold.

@adowling2
Copy link
Contributor

@agarciadiego @bpaul4 @lbianchi-lbl I am curious about looking at the solver output captured in the notebooks and comparing that to when run locally. This would let us look at the number of Ipopt iterations across platforms.

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 20, 2021

After some testing, I found that running the standard examples tests (python build.py -t after building the index) does not throw an error with the most recent commit, and running the line from the GitHub Actions check pytest --verbose -m 'not unit' tests/ results in a similar timeout error (various times around 650 seconds). When running locally, the notebook solved in 75 iterations initially and then optimized in 14 iterations.

Before adding scaling, the build.py test would fail with a timeout of ~1350 seconds > 1200 seconds, which would seem to indicate that a different test is being run.

@adowling2
Copy link
Contributor

adowling2 commented Dec 20, 2021

This is wild speculation, but could pytest --verbose -m 'not unit' tests/ be accessing the vanilla (pip installed) version of Ipopt, whereas the other approach using the version of Ipopt from idaes extensions? Edit: This would require the testing harness to have 2 versions of Ipopt, which we probably did not do...

@lbianchi-lbl
Copy link
Contributor Author

lbianchi-lbl commented Dec 20, 2021

I'm running the notebook manually on our build system and, after at least 20 minutes, it's still at the "3.3 Run Simulation" (cell 10). This is the (partial) output until now(EDIT This is the complete output; it finally converged after almost half an hour):

Ipopt 3.13.2: 

******************************************************************************
This program contains Ipopt, a library for large-scale nonlinear optimization.
 Ipopt is released as open source code under the Eclipse Public License (EPL).
         For more information visit http://projects.coin-or.org/Ipopt

This version of Ipopt was compiled from source code available at
    https://github.com/IDAES/Ipopt as part of the Institute for the Design of
    Advanced Energy Systems Process Systems Engineering Framework (IDAES PSE
    Framework) Copyright (c) 2018-2019. See https://github.com/IDAES/idaes-pse.

This version of Ipopt was compiled using HSL, a collection of Fortran codes
    for large-scale scientific computation.  All technical papers, sales and
    publicity material resulting from use of the HSL codes within IPOPT must
    contain the following acknowledgement:
        HSL, a collection of Fortran codes for large-scale scientific
        computation. See http://www.hsl.rl.ac.uk.
******************************************************************************

This is Ipopt version 3.13.2, running with linear solver ma27.

Number of nonzeros in equality constraint Jacobian...:     4334
Number of nonzeros in inequality constraint Jacobian.:        0
Number of nonzeros in Lagrangian Hessian.............:     2692

Total number of variables............................:      551
                     variables with only lower bounds:      303
                variables with lower and upper bounds:      194
                     variables with only upper bounds:       44
Total number of equality constraints.................:      551
Total number of inequality constraints...............:        0
        inequality constraints with only lower bounds:        0
   inequality constraints with lower and upper bounds:        0
        inequality constraints with only upper bounds:        0

iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
   0  0.0000000e+00 5.88e+05 1.00e+00  -1.0 0.00e+00    -  0.00e+00 0.00e+00   0
   1  0.0000000e+00 5.88e+05 7.10e+01  -1.0 1.94e+07    -  1.11e-03 1.53e-05h  1
   2r 0.0000000e+00 5.88e+05 9.99e+02   2.7 0.00e+00    -  0.00e+00 7.66e-08R  2
   3r 0.0000000e+00 5.90e+05 9.96e+02   2.7 5.85e+05    -  1.23e-02 9.78e-04f  1
   4r 0.0000000e+00 5.65e+05 9.86e+02   2.7 3.14e+04    -  5.20e-03 1.00e-02f  1
   5r 0.0000000e+00 5.62e+05 9.87e+02   2.7 2.28e+05    -  5.03e-04 1.34e-03f  1
   6r 0.0000000e+00 5.47e+05 9.77e+02   2.7 1.25e+04    -  1.02e-02 6.32e-03f  1
   7r 0.0000000e+00 1.75e+06 9.50e+02   2.7 7.14e+03    -  2.81e-02 1.76e-02f  1
   8r 0.0000000e+00 4.94e+05 2.60e+03   2.7 1.18e+03    -  1.44e-01 5.07e-02f  1
   9r 0.0000000e+00 2.36e+06 3.39e+03   2.7 8.51e+02    -  2.78e-01 1.83e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  10r 0.0000000e+00 5.17e+06 4.82e+03   2.7 8.16e+02    -  2.71e-01 5.12e-01f  1
  11r 0.0000000e+00 6.19e+06 3.71e+03   2.7 1.20e+02   0.0 2.73e-01 1.72e-01f  1
  12r 0.0000000e+00 1.69e+06 2.77e+03   2.7 7.67e+00   1.3 7.28e-01 1.00e+00f  1
  13r 0.0000000e+00 2.37e+06 2.36e+03   2.7 2.36e+01   0.9 1.43e-01 1.40e-01f  1
  14r 0.0000000e+00 8.41e+05 1.30e+03   2.7 2.54e+01   1.3 1.22e-01 6.63e-01f  1
  15r 0.0000000e+00 3.58e+06 1.56e+03   2.7 5.23e+03    -  4.56e-02 2.29e-02f  1
  16r 0.0000000e+00 5.89e+05 6.95e+02   2.7 4.11e+02    -  8.31e-01 1.00e+00f  1
  17r 0.0000000e+00 4.79e+04 1.32e+03   2.7 1.29e+01   1.7 3.23e-01 1.00e+00h  1
  18r 0.0000000e+00 5.02e+04 1.32e+02   2.7 6.93e+02    -  9.98e-01 1.00e+00f  1
  19r 0.0000000e+00 4.69e+04 6.37e+03   0.6 7.24e+01   1.2 4.48e-01 3.02e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  20r 0.0000000e+00 1.58e+06 1.73e+03   0.6 3.64e+03    -  2.57e-01 4.74e-01f  1
  21r 0.0000000e+00 6.61e+05 8.78e+02   0.6 1.01e+01   0.7 1.01e-01 3.23e-01f  1
  22r 0.0000000e+00 1.17e+06 1.16e+03   0.6 1.31e+01   0.3 3.37e-01 4.92e-01f  1
  23r 0.0000000e+00 1.12e+06 1.02e+03   0.6 3.33e+00   3.4 1.65e-01 3.82e-02f  1
  24r 0.0000000e+00 4.30e+05 2.42e+03   0.6 3.42e+00   2.9 1.70e-02 3.66e-01f  1
  25r 0.0000000e+00 4.11e+05 2.32e+03   0.6 6.41e+00   2.5 8.43e-02 4.35e-02f  1
  26r 0.0000000e+00 3.95e+05 2.18e+03   0.6 3.85e+00   2.0 3.33e-01 3.66e-02f  1
  27r 0.0000000e+00 1.12e+05 1.84e+03   0.6 2.40e+00   2.4 1.08e-01 2.72e-01f  1
  28r 0.0000000e+00 1.04e+05 1.65e+03   0.6 3.71e+00   1.9 3.86e-01 7.37e-02f  1
  29r 0.0000000e+00 5.63e+04 8.97e+02   0.6 2.42e+00   2.4 3.24e-01 4.49e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  30r 0.0000000e+00 4.01e+04 7.10e+03   0.6 1.88e+00   2.8 3.59e-01 2.85e-01f  1
  31r 0.0000000e+00 2.45e+04 3.46e+03   0.6 3.44e+00   2.3 4.81e-01 3.81e-01f  1
  32r 0.0000000e+00 1.93e+04 2.68e+03   0.6 4.14e+00   1.8 3.71e-01 2.04e-01f  1
  33r 0.0000000e+00 7.62e+03 4.84e+02   0.6 1.05e+00   2.2 1.00e+00 5.88e-01f  1
  34r 0.0000000e+00 7.41e+03 3.28e+03   0.6 1.85e+01   1.8 6.29e-02 2.78e-02f  1
  35r 0.0000000e+00 6.45e+03 1.13e+03   0.6 8.36e-01   3.1 8.36e-01 1.28e-01f  1
  36r 0.0000000e+00 4.64e+03 1.23e+03   0.6 9.80e-01   2.6 8.81e-01 2.71e-01f  1
  37r 0.0000000e+00 3.07e+03 6.81e+02   0.6 1.20e+00   3.0 3.03e-01 3.45e-01f  1
  38r 0.0000000e+00 2.26e+03 5.07e+02   0.6 8.39e-01   2.6 6.92e-01 2.93e-01f  1
  39r 0.0000000e+00 2.70e+03 1.62e+02   0.6 6.18e-01   2.1 5.12e-01 7.60e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  40r 0.0000000e+00 5.47e+03 8.46e+01  -0.1 1.28e+00   1.6 4.48e-01 5.00e-01f  1
  41r 0.0000000e+00 3.59e+03 1.03e+02  -0.1 5.02e-01   2.0 4.85e-01 4.38e-01f  1
  42r 0.0000000e+00 3.65e+03 2.21e+02  -0.1 1.30e+00   1.6 6.62e-01 3.52e-01f  1
  43r 0.0000000e+00 4.78e+03 6.63e+02  -0.1 6.45e-01   2.0 1.00e+00 9.30e-01f  1
  44r 0.0000000e+00 4.76e+03 6.61e+02  -0.1 2.80e+02   1.5 8.08e-03 4.44e-03h  1
  45r 0.0000000e+00 7.93e+05 2.61e+03  -0.1 3.54e+00   1.0 3.69e-01 4.17e-01f  1
  46r 0.0000000e+00 7.86e+05 2.67e+03  -0.1 1.59e+01   1.5 1.41e-01 8.16e-03f  1
  47r 0.0000000e+00 7.31e+05 1.73e+03  -0.1 4.83e+00   1.9 5.56e-03 6.93e-02f  1
  48r 0.0000000e+00 7.01e+05 1.66e+03  -0.1 5.12e+00   1.4 7.95e-02 4.15e-02f  1
  49r 0.0000000e+00 6.53e+05 1.55e+03  -0.1 5.68e+00   0.9 6.90e-03 6.66e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  50r 0.0000000e+00 4.96e+05 1.24e+03  -0.1 1.10e+01   0.5 2.83e-02 2.00e-01f  1
  51r 0.0000000e+00 5.14e+05 1.16e+03  -0.1 2.24e+01  -0.0 9.85e-02 6.62e-02f  1
  52r 0.0000000e+00 5.09e+05 1.16e+03  -0.1 3.45e+00   3.1 4.60e-02 1.02e-02h  1
  53r 0.0000000e+00 4.99e+05 1.13e+03  -0.1 2.50e+00   3.5 1.64e-03 1.96e-02h  1
  54r 0.0000000e+00 4.34e+05 9.17e+03  -0.1 1.94e+00   4.0 5.82e-03 3.22e-02h  1
  55r 0.0000000e+00 4.21e+05 8.91e+03  -0.1 1.38e+00   3.5 5.37e-02 2.92e-02h  1
  56r 0.0000000e+00 3.68e+05 7.80e+03  -0.1 1.35e+00   3.0 6.33e-02 1.26e-01h  1
  57r 0.0000000e+00 3.43e+05 7.27e+03  -0.1 1.15e+00   2.5 5.28e-02 6.75e-02h  1
  58r 0.0000000e+00 3.11e+05 6.58e+03  -0.1 1.07e+00   3.0 1.63e-01 9.42e-02h  1
  59r 0.0000000e+00 2.61e+05 5.53e+03  -0.1 9.61e-01   2.5 2.74e-01 1.59e-01h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  60r 0.0000000e+00 2.28e+05 4.83e+03  -0.1 8.15e-01   2.9 4.23e-01 1.28e-01h  1
  61r 0.0000000e+00 2.12e+05 4.50e+03  -0.1 8.59e-01   2.4 8.76e-01 6.74e-02h  1
  62r 0.0000000e+00 9.90e+04 2.12e+03  -0.1 6.50e-01   2.9 3.67e-01 5.31e-01h  1
  63r 0.0000000e+00 6.57e+04 1.41e+03  -0.1 3.95e-01   2.4 7.08e-01 3.36e-01f  2
  64r 0.0000000e+00 4.98e+05 5.33e+02  -0.1 5.01e-01   1.9 8.79e-01 3.07e-01f  1
  65r 0.0000000e+00 4.96e+05 1.29e+03  -0.1 2.74e+00   3.2 3.24e-02 3.39e-03h  2
  66r 0.0000000e+00 4.34e+04 5.73e+03  -0.1 2.20e+00   3.7 6.98e-04 4.13e-02h  1
  67r 0.0000000e+00 3.88e+04 5.12e+03  -0.1 1.38e-01   3.2 1.00e+00 1.07e-01f  1
  68r 0.0000000e+00 3.82e+04 5.05e+03  -0.1 1.57e-01   2.7 8.45e-01 1.54e-02f  5
  69r 0.0000000e+00 4.89e+05 2.77e+03  -0.1 2.78e-01   2.2 1.00e+00 2.35e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  70r 0.0000000e+00 4.79e+05 9.65e+02  -0.1 7.11e+01   1.8 1.09e-03 6.25e-03f  1
  71r 0.0000000e+00 4.72e+05 9.33e+02  -0.1 1.80e+01   1.3 4.16e-02 1.48e-02h  2
  72r 0.0000000e+00 4.46e+05 6.98e+02  -0.1 2.16e+01   0.8 3.80e-03 4.15e-02f  1
  73r 0.0000000e+00 4.35e+05 6.80e+02  -0.1 5.96e+00   1.2 1.73e-02 2.22e-02h  1
  74r 0.0000000e+00 4.15e+05 6.40e+02  -0.1 1.12e+01   0.7 5.60e-02 3.84e-02f  1
  75r 0.0000000e+00 3.97e+05 6.10e+02  -0.1 4.50e+00   1.2 1.46e-01 4.03e-02h  1
  76r 0.0000000e+00 3.76e+05 5.78e+02  -0.1 1.20e+01   0.7 9.65e-02 4.65e-02F  1
  77r 0.0000000e+00 2.99e+05 4.71e+02  -0.1 5.37e+00   1.1 2.45e-01 1.95e-01H  1
  78r 0.0000000e+00 2.65e+05 3.11e+03  -0.1 9.77e+00   0.6 5.30e-01 1.05e-01F  1
  79r 0.0000000e+00 2.61e+05 3.93e+03  -0.1 1.99e+00   3.8 3.32e-02 1.49e-02h  2
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  80r 0.0000000e+00 2.60e+05 4.08e+03  -0.1 2.02e+00   3.3 2.51e-02 2.42e-03h  7
  81r 0.0000000e+00 2.60e+05 4.09e+03  -0.1 1.25e+00   3.7 4.91e-03 1.24e-03h  7
  82r 0.0000000e+00 2.60e+05 4.12e+03  -0.1 1.35e+00   3.3 2.88e-02 7.37e-04h  8
  83r 0.0000000e+00 2.59e+05 4.14e+03  -0.1 1.27e+00   3.7 6.30e-03 9.86e-04h  8
  84r 0.0000000e+00 2.21e+05 5.96e+02  -0.1 1.48e+00   3.2 2.33e-02 1.47e-01H  1
  85r 0.0000000e+00 2.17e+05 6.00e+02  -0.1 1.59e+00   2.7 1.88e-01 1.66e-02h  5
  86r 0.0000000e+00 2.17e+05 6.00e+02  -0.1 2.38e+00   2.2 0.00e+00 3.03e-07R 20
  87r 0.0000000e+00 2.10e+05 4.57e+03  -0.1 5.10e+00   1.8 1.28e-01 3.90e-02f  1
  88r 0.0000000e+00 1.96e+05 4.23e+03  -0.1 5.92e+00   1.3 2.62e-01 7.11e-02f  1
  89r 0.0000000e+00 1.86e+05 4.01e+03  -0.1 7.16e+00   0.8 2.74e-01 5.17e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  90r 0.0000000e+00 1.91e+05 3.87e+03  -0.1 3.63e+01   0.3 2.65e-02 3.48e-02f  1
  91r 0.0000000e+00 1.80e+05 3.64e+03  -0.1 8.53e+00   0.8 9.87e-03 5.93e-02F  1
  92r 0.0000000e+00 1.40e+05 2.79e+03  -0.1 2.95e+00   1.2 5.81e-01 2.17e-01f  2
  93r 0.0000000e+00 1.39e+05 2.77e+03  -0.1 8.86e+00   0.7 5.67e-01 7.20e-03f  6

  94r 0.0000000e+00 1.38e+05 2.76e+03  -0.1 3.22e+00   1.1 1.00e+00 4.98e-03f  8
  95r 0.0000000e+00 1.38e+05 2.75e+03  -0.1 9.96e+00   0.7 4.94e-01 1.52e-03f  9
  96r 0.0000000e+00 7.97e+03 8.77e+03  -0.1 3.59e+00   1.1 1.00e+00 9.70e-01f  1
  97r 0.0000000e+00 7.74e+03 8.51e+03  -0.1 2.46e+00   2.4 1.12e-01 2.99e-02f  1
  98r 0.0000000e+00 7.28e+03 7.81e+03  -0.1 1.77e+00   2.8 2.87e-03 6.36e-02h  1
  99r 0.0000000e+00 8.38e+03 9.36e+03  -0.1 1.24e+00   2.4 5.36e-02 5.92e-02h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 100r 0.0000000e+00 6.04e+03 1.65e+03  -0.1 8.83e-01   2.8 1.44e-01 1.19e-01h  1
 101r 0.0000000e+00 2.47e+04 1.09e+04  -0.1 5.60e-01   2.3 8.71e-02 6.21e-02f  1
 102r 0.0000000e+00 1.52e+05 2.07e+04  -0.1 1.15e+00   2.7 8.74e-03 1.61e-01h  1
 103r 0.0000000e+00 4.65e+03 2.30e+03  -0.1 8.96e+00   2.3 3.40e-02 2.57e-02f  1
 104r 0.0000000e+00 2.13e+04 3.69e+04  -0.1 4.84e-01   2.7 5.08e-02 5.54e-02f  1
 105r 0.0000000e+00 1.76e+05 7.71e+03  -0.1 6.29e+00   3.1 9.67e-04 7.59e-03h  1
 106r 0.0000000e+00 3.15e+03 2.34e+03  -0.1 5.66e-01   2.6 2.57e-01 2.79e-01h  1
 107r 0.0000000e+00 1.94e+05 3.65e+03  -0.1 7.50e-01   2.2 1.32e-02 1.30e-01f  1
 108r 0.0000000e+00 2.27e+03 2.22e+03  -0.1 7.47e-01   2.6 7.63e-02 1.72e-01h  1
 109r 0.0000000e+00 1.95e+05 2.38e+03  -0.1 6.67e-01   2.1 7.19e-02 9.20e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 110r 0.0000000e+00 1.76e+03 2.40e+03  -0.1 9.14e-01   2.5 6.37e-02 1.51e-01h  1
 111r 0.0000000e+00 1.98e+05 1.02e+03  -0.1 7.67e-01   2.1 3.17e-02 7.91e-02f  1
 112r 0.0000000e+00 1.61e+03 2.57e+03  -0.1 2.67e+00   1.6 4.55e-02 2.33e-01f  1
 113r 0.0000000e+00 1.58e+03 2.53e+03  -0.1 7.23e-01   2.9 1.32e-01 1.93e-02f  1
 114r 0.0000000e+00 1.54e+03 2.48e+03  -0.1 7.06e-01   2.4 2.70e-01 2.20e-02f  1
 115r 0.0000000e+00 1.33e+03 2.14e+03  -0.1 6.95e-01   2.9 2.84e-01 1.39e-01f  1
 116r 0.0000000e+00 7.85e+02 1.21e+03  -0.1 8.60e-01   2.4 9.26e-01 4.36e-01f  1
 117r 0.0000000e+00 2.85e+02 3.99e+02  -0.1 3.60e-01   2.8 8.20e-01 6.74e-01f  1
 118r 0.0000000e+00 2.25e+02 2.69e+02  -0.1 3.40e-01   2.3 7.43e-01 3.27e-01f  1
 119r 0.0000000e+00 9.21e+01 6.46e+01  -0.1 1.01e-01   2.8 1.00e+00 1.00e+00f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 120r 0.0000000e+00 3.06e+02 1.18e+02  -0.1 6.15e-01   2.3 1.00e+00 1.00e+00f  1
 121r 0.0000000e+00 2.36e+03 5.78e+01  -0.1 6.42e-01   1.8 9.57e-01 1.00e+00f  1
 122r 0.0000000e+00 1.69e+05 4.99e+03  -0.1 1.96e+00   1.3 1.00e+00 5.53e-01f  1
 123r 0.0000000e+00 5.93e+03 2.29e+02  -0.1 4.07e+00   0.9 1.14e-01 1.70e-01f  1
 124r 0.0000000e+00 1.79e+05 1.54e+03  -0.1 1.31e+00   1.3 3.99e-01 4.88e-01f  1
 125r 0.0000000e+00 1.70e+05 1.44e+03  -0.1 8.73e+00   0.8 1.45e-01 4.93e-02f  1
 126r 0.0000000e+00 8.85e+03 1.04e+03  -0.1 2.59e+00   1.2 2.25e-01 7.18e-01f  1
 127r 0.0000000e+00 3.96e+03 4.80e+02  -0.1 8.32e-01   1.7 1.00e+00 5.40e-01f  1
 128r 0.0000000e+00 2.22e+03 5.01e+02  -0.1 1.45e+00   1.2 8.41e-01 6.70e-01f  1
 129r 0.0000000e+00 1.51e+02 7.26e+02  -0.1 5.98e-01   2.5 6.07e-01 1.00e+00f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 130r 0.0000000e+00 1.33e+02 7.46e+02  -0.1 1.10e+00   2.0 5.84e-01 1.00e+00f  1
 131r 0.0000000e+00 1.37e+02 5.97e+02  -0.1 1.06e+00   2.5 1.55e-01 5.13e-01f  1
 132r 0.0000000e+00 1.43e+05 6.02e+03  -0.1 7.60e-01   2.0 1.00e+00 6.62e-01f  1
 133r 0.0000000e+00 1.27e+03 1.86e+03  -0.1 7.13e-01   3.3 9.54e-02 1.92e-01h  1
 134r 0.0000000e+00 1.11e+03 3.95e+03  -0.1 9.86e-01   2.8 1.00e+00 1.13e-01f  1
 135r 0.0000000e+00 1.39e+05 9.94e+02  -0.1 1.02e+00   2.3 4.23e-01 6.32e-01f  1
 136r 0.0000000e+00 1.78e+03 1.30e+03  -0.1 7.49e-01   2.8 6.30e-02 7.91e-02h  3
 137r 0.0000000e+00 4.64e+02 8.67e+02  -0.1 5.52e-01   3.2 1.00e+00 6.67e-01f  1
 138r 0.0000000e+00 2.55e+02 8.09e+02  -0.1 1.10e+00   2.7 1.00e+00 3.45e-01h  1
 139r 0.0000000e+00 1.49e+05 4.30e+03  -0.1 6.04e-01   2.2 1.00e+00 1.00e+00f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 140r 0.0000000e+00 2.49e+02 1.44e+03  -0.1 7.24e-01   3.6 6.07e-02 7.36e-02h  1
 141r 0.0000000e+00 2.37e+02 1.27e+03  -0.1 5.92e-02   3.1 1.00e+00 1.18e-01f  1
 142r 0.0000000e+00 1.51e+05 4.11e+03  -0.1 4.66e-02   3.5 1.00e+00 1.00e+00f  1
 143r 0.0000000e+00 2.88e+02 1.50e+03  -0.1 7.83e-01   3.0 7.63e-02 1.02e-01h  1
 144r 0.0000000e+00 2.73e+02 1.34e+03  -0.1 1.09e-01   2.6 1.00e+00 1.08e-01f  1
 145r 0.0000000e+00 1.39e+05 7.18e+03  -0.1 3.16e-01   2.1 1.00e+00 4.96e-01f  1
 146r 0.0000000e+00 4.46e+02 1.06e+03  -0.1 8.06e-01   1.6 7.67e-02 2.48e-01h  1
 147r 0.0000000e+00 1.40e+05 2.60e+04  -0.1 2.77e-01   2.0 1.00e+00 5.30e-01f  1
 148r 0.0000000e+00 7.83e+02 5.15e+02  -0.1 8.33e+00   1.6 4.16e-02 5.42e-02f  1
 149r 0.0000000e+00 1.52e+05 3.68e+03  -0.1 2.10e-01   2.0 1.00e+00 9.31e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 150r 0.0000000e+00 1.09e+02 4.22e+02  -0.1 1.06e+00   1.5 2.58e-01 2.04e-01f  1
 151r 0.0000000e+00 8.85e+01 5.40e+02  -0.1 2.94e-01   1.9 1.00e+00 3.06e-01f  1
 152r 0.0000000e+00 1.40e+05 6.11e+03  -0.1 1.69e+00   1.5 1.00e+00 9.23e-01f  1
 153r 0.0000000e+00 8.49e+02 1.17e+03  -0.1 7.40e-01   2.8 9.96e-02 2.15e-01h  1
 154r 0.0000000e+00 3.27e+02 4.78e+02  -0.1 7.62e-01   2.3 1.00e+00 5.95e-01f  1
 155r 0.0000000e+00 1.52e+02 1.93e+02  -0.1 3.30e-01   2.7 1.00e+00 1.00e+00f  1
 156r 0.0000000e+00 1.52e+02 2.52e+02  -0.1 1.45e+01   2.3 6.99e-02 1.96e-02f  1
 157r 0.0000000e+00 1.40e+05 7.36e+03  -0.1 7.70e-01   2.7 1.00e+00 9.81e-01f  1
 158r 0.0000000e+00 1.39e+05 7.36e+03  -0.1 1.48e+00   2.2 8.54e-02 5.66e-03f  1
 159r 0.0000000e+00 1.03e+03 4.00e+02  -0.1 5.18e+00   1.7 1.86e-02 4.61e-02h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 160r 0.0000000e+00 1.49e+05 1.36e+03  -0.1 2.34e+00   1.3 7.28e-01 1.82e-01f  1
 161r 0.0000000e+00 5.02e+03 3.23e+02  -0.1 9.79e-01   1.7 4.09e-01 1.72e-01h  1
 162r 0.0000000e+00 1.40e+05 3.25e+03  -0.1 4.27e+00   1.2 5.19e-01 1.44e-01f  1
 163r 0.0000000e+00 1.81e+02 3.92e+02  -0.1 9.40e-01   1.6 7.16e-02 1.75e-01f  1
 164r 0.0000000e+00 1.77e+02 4.06e+02  -0.1 6.96e+00   1.2 1.11e-01 3.00e-02f  1
 165r 0.0000000e+00 1.65e+05 1.85e+03  -0.1 6.31e-01   1.6 1.00e+00 7.83e-01f  1
 166r 0.0000000e+00 1.52e+05 1.95e+03  -0.1 1.42e+00   2.0 1.56e-01 6.77e-02h  1
 167r 0.0000000e+00 1.45e+05 1.84e+03  -0.1 1.87e+00   1.5 8.15e-01 6.71e-02F  1
 168r 0.0000000e+00 1.41e+03 1.06e+03  -0.1 9.49e-01   2.0 7.40e-01 6.71e-01H  1
 169r 0.0000000e+00 7.35e+02 5.12e+02  -0.1 1.14e+00   1.5 1.00e+00 5.13e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 170r 0.0000000e+00 1.80e+02 4.02e+02  -0.1 5.20e-01   1.9 1.00e+00 9.06e-01f  1
 171r 0.0000000e+00 1.48e+05 5.23e+03  -0.1 9.68e-01   2.3 2.08e-01 8.46e-01f  1
 172r 0.0000000e+00 3.34e+02 9.30e+02  -0.1 3.08e+00   1.9 7.19e-02 2.57e-01f  1
 173r 0.0000000e+00 1.35e+02 6.09e+02  -0.1 1.56e+00   2.3 1.00e+00 4.33e-01f  1
 174r 0.0000000e+00 1.23e+02 1.33e+03  -0.1 3.63e-01   2.7 3.05e-01 4.52e-02f  1
 175r 0.0000000e+00 1.45e+05 8.81e+02  -0.1 9.54e-01   2.2 6.13e-02 1.93e-01f  1
 176r 0.0000000e+00 2.94e+03 1.25e+03  -0.1 7.72e-01   2.7 8.57e-02 2.41e-01h  1
 177r 0.0000000e+00 1.26e+03 5.92e+02  -0.1 2.47e-01   3.1 6.70e-01 5.35e-01f  1
 178r 0.0000000e+00 5.72e+02 3.05e+02  -0.1 7.35e-01   2.6 5.14e-01 4.86e-01f  1
 179r 0.0000000e+00 5.30e+02 6.34e+03  -0.1 1.06e+00   2.1 1.00e+00 5.88e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 180r 0.0000000e+00 1.07e+04 2.17e+04  -0.1 1.40e+00   1.7 6.79e-01 3.11e-01f  1
 181r 0.0000000e+00 1.04e+04 2.12e+04  -0.1 2.86e+01   1.2 4.93e-02 2.43e-02f  1
 182r 0.0000000e+00 9.43e+03 2.02e+04  -0.1 4.58e+00   1.6 9.41e-02 6.03e-02f  1
 183r 0.0000000e+00 9.41e+03 2.02e+04  -0.1 9.50e+01   1.1 2.62e-03 4.86e-04h  1
 184r 0.0000000e+00 5.11e+03 3.99e+04  -0.1 7.76e+00   1.5 3.41e-02 7.73e-02f  1
 185r 0.0000000e+00 1.68e+03 2.69e+03  -0.1 2.23e+00   2.0 8.88e-02 1.69e-01h  1
 186r 0.0000000e+00 3.47e+03 4.96e+03  -0.1 1.93e+00   1.5 4.58e-01 6.54e-02f  1
 187r 0.0000000e+00 3.55e+03 5.00e+03  -0.1 1.37e+02   1.9 4.43e-04 3.32e-04f  1
 188r 0.0000000e+00 3.95e+03 5.05e+03  -0.1 3.69e+00   2.3 1.48e-02 1.01e-02h  1
 189r 0.0000000e+00 3.75e+03 5.89e+03  -0.1 9.95e-01   1.9 1.04e-01 3.90e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 190r 0.0000000e+00 4.86e+01 2.05e+03  -0.1 1.91e+00   1.4 1.06e-01 1.47e-01f  1
 191r 0.0000000e+00 1.53e+05 1.80e+03  -0.1 9.65e-01   1.8 2.44e-01 1.14e-01f  1
 192r 0.0000000e+00 7.11e+02 1.66e+03  -0.1 3.59e+00   1.3 1.08e-01 3.69e-01f  1
 193r 0.0000000e+00 6.92e+02 1.60e+03  -0.1 2.09e+00   1.8 2.38e-01 3.88e-02f  1
 194r 0.0000000e+00 1.72e+05 1.39e+03  -0.1 6.61e-01   2.2 4.29e-01 1.38e-01f  1
 195r 0.0000000e+00 1.62e+05 1.32e+03  -0.1 1.70e+00   1.7 1.76e-02 5.10e-02f  1
 196r 0.0000000e+00 1.18e+03 1.35e+03  -0.1 7.79e-01   2.1 2.46e-01 7.20e-02f  1
 197r 0.0000000e+00 1.73e+05 1.10e+03  -0.1 2.12e+00   1.7 6.31e-01 1.98e-01f  1
 198r 0.0000000e+00 1.60e+05 1.34e+03  -0.1 1.34e+00   2.1 6.35e-02 6.16e-02f  1
 199r 0.0000000e+00 1.55e+05 1.42e+03  -0.1 1.17e+01   1.6 2.72e-01 2.52e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 200r 0.0000000e+00 6.64e+01 1.67e+03  -0.1 8.94e-01   2.0 1.07e-01 4.84e-01f  1
 201r 0.0000000e+00 8.82e+01 1.37e+03  -0.1 1.46e+00   2.5 1.66e-01 1.80e-01f  1
 202r 0.0000000e+00 1.53e+05 9.35e+03  -0.1 4.55e+00   2.0 2.28e-01 1.18e-01f  1
 203r 0.0000000e+00 7.54e+02 1.65e+03  -0.1 1.28e+00   2.4 1.39e-02 1.99e-01f  1
 204r 0.0000000e+00 6.29e+02 1.42e+03  -0.1 1.34e+00   2.8 6.97e-02 1.46e-01f  1
 205r 0.0000000e+00 6.03e+02 1.39e+03  -0.1 1.53e+00   2.4 2.68e-01 3.67e-02f  1
 206r 0.0000000e+00 4.76e+02 1.20e+03  -0.1 6.05e-01   2.8 1.63e-01 1.82e-01f  1
 207r 0.0000000e+00 1.53e+05 1.25e+04  -0.1 1.69e+00   2.3 2.80e-01 1.50e-01f  1
 208r 0.0000000e+00 1.45e+02 1.15e+03  -0.1 1.35e+01   1.8 4.92e-02 2.91e-02f  1
 209r 0.0000000e+00 5.21e+03 1.27e+04  -0.1 6.02e-01   2.3 7.49e-01 3.75e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 210r 0.0000000e+00 3.85e+03 1.19e+04  -0.1 2.08e+00   1.8 2.17e-01 8.88e-02f  1
 211r 0.0000000e+00 2.26e+03 2.98e+03  -0.1 1.58e+00   2.2 2.65e-02 2.95e-01h  1
 212r 0.0000000e+00 2.10e+03 2.76e+03  -0.1 3.18e+00   1.7 7.57e-01 7.10e-02f  1
 213r 0.0000000e+00 8.94e+03 1.62e+04  -0.1 1.45e+00   2.2 2.80e-01 2.47e-01f  1
 214r 0.0000000e+00 1.33e+03 2.28e+03  -0.1 1.05e+00   2.6 2.51e-02 3.48e-02h  1
 215r 0.0000000e+00 9.84e+03 5.77e+03  -0.1 1.16e+00   2.1 5.21e-01 3.87e-02f  1
 216r 0.0000000e+00 1.01e+03 2.59e+03  -0.1 9.06e-01   2.5 1.14e-01 1.05e-01h  1
 217r 0.0000000e+00 1.04e+04 7.53e+03  -0.1 1.45e+00   2.1 4.84e-01 3.63e-01f  1
 218r 0.0000000e+00 1.02e+04 1.04e+04  -0.1 1.71e+00   2.5 1.19e-02 8.13e-02h  1
 219r 0.0000000e+00 9.36e+02 2.52e+03  -0.1 9.54e-01   2.9 7.63e-02 1.03e-01h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 220r 0.0000000e+00 8.86e+02 2.37e+03  -0.1 3.58e-01   3.3 2.82e-01 5.77e-02f  1
 221r 0.0000000e+00 6.86e+02 1.76e+03  -0.1 3.20e-01   3.8 1.52e-01 2.38e-01f  1
 222r 0.0000000e+00 6.30e+02 2.22e+03  -0.1 8.55e-01   3.3 2.70e-01 8.73e-02f  1
 223r 0.0000000e+00 5.11e+02 1.34e+03  -0.1 2.49e-01   3.7 3.50e-02 2.04e-01f  1
 224r 0.0000000e+00 5.02e+02 2.02e+03  -0.1 8.40e-01   3.2 3.48e-01 1.91e-02f  1
 225r 0.0000000e+00 4.67e+02 3.99e+03  -0.1 1.01e+00   3.7 3.14e-02 7.21e-02f  1
 226r 0.0000000e+00 4.23e+02 3.51e+03  -0.1 4.89e-01   3.2 1.63e-01 1.06e-01f  1
 227r 0.0000000e+00 3.93e+02 3.59e+03  -0.1 2.54e-01   3.6 1.35e-01 8.16e-02f  1
 228r 0.0000000e+00 2.97e+02 1.10e+03  -0.1 3.06e-01   3.1 2.62e-01 2.76e-01f  1
 229r 0.0000000e+00 2.77e+02 2.43e+03  -0.1 8.69e-01   3.6 1.19e-01 7.88e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 230r 0.0000000e+00 1.95e+02 3.20e+03  -0.1 3.40e-01   3.1 1.05e-01 3.56e-01f  1

 231r 0.0000000e+00 1.88e+02 3.75e+03  -0.1 1.65e+00   2.6 3.90e-01 4.81e-02f  1
 232r 0.0000000e+00 1.67e+02 3.13e+03  -0.1 4.14e-01   3.0 2.87e-01 1.59e-01f  1
 233r 0.0000000e+00 1.56e+02 2.95e+03  -0.1 1.14e+00   2.6 2.33e-01 8.79e-02f  1
 234r 0.0000000e+00 1.64e+05 1.42e+04  -0.1 8.76e+00   2.1 2.28e-02 4.78e-02f  1
 235r 0.0000000e+00 5.07e+02 2.65e+03  -0.1 1.60e+00   2.5 6.21e-02 6.02e-02h  1
 236r 0.0000000e+00 1.61e+04 2.58e+04  -0.1 1.83e+00   2.0 2.29e-01 9.06e-02f  1
 237r 0.0000000e+00 1.56e+04 2.51e+04  -0.1 1.86e+00   2.4 3.39e-02 2.74e-02h  1
 238r 0.0000000e+00 1.53e+04 2.47e+04  -0.1 8.76e+00   2.0 9.07e-02 1.44e-02f  1
 239r 0.0000000e+00 1.40e+04 2.30e+04  -0.1 2.54e+00   2.4 7.75e-02 8.13e-02h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 240r 0.0000000e+00 1.27e+04 2.18e+04  -0.1 3.15e+00   1.9 1.20e-01 7.64e-02h  1
 241r 0.0000000e+00 8.98e+02 2.27e+03  -0.1 1.89e+00   2.3 1.31e-01 1.77e-01h  1
 242r 0.0000000e+00 8.95e+02 2.26e+03  -0.1 8.56e+01   1.9 2.99e-03 3.69e-03f  1
 243r 0.0000000e+00 1.69e+04 1.40e+03  -0.1 9.61e-01   2.3 8.97e-02 5.38e-02f  1
 244r 0.0000000e+00 1.69e+04 1.32e+03  -0.1 1.33e+00   1.8 7.50e-02 3.09e-02h  1
 245r 0.0000000e+00 1.68e+04 1.18e+03  -0.1 8.58e-01   2.2 1.13e-01 2.84e-02h  1
 246r 0.0000000e+00 7.56e+02 2.03e+03  -0.1 2.67e+00   1.8 3.90e-03 3.96e-02h  1
 247r 0.0000000e+00 1.67e+04 4.00e+03  -0.1 1.26e+00   2.2 3.33e-01 1.66e-01f  1
 248r 0.0000000e+00 1.56e+04 3.65e+03  -0.1 2.68e+00   1.7 3.19e-02 6.23e-02h  1
 249r 0.0000000e+00 1.42e+04 2.58e+03  -0.1 1.96e+00   2.1 2.87e-02 1.18e-01h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 250r 0.0000000e+00 2.44e+02 2.00e+03  -0.1 2.75e+00   1.7 2.61e-02 1.05e-01f  1
 251r 0.0000000e+00 2.62e+04 6.68e+03  -0.1 9.60e-01   2.1 1.41e-01 2.63e-01f  1
 252r 0.0000000e+00 1.65e+05 1.42e+03  -0.1 1.57e+00   2.5 5.03e-03 1.04e-01h  1
 253r 0.0000000e+00 1.39e+04 3.33e+03  -0.1 3.37e+00   2.0 6.16e-02 2.64e-02f  1
 254r 0.0000000e+00 3.01e+03 2.06e+03  -0.1 8.35e+00   1.6 2.00e-02 5.52e-02h  1
 255r 0.0000000e+00 2.04e+04 6.70e+03  -0.1 5.00e-01   2.0 3.25e-02 3.29e-02F  1
 256r 0.0000000e+00 2.03e+04 6.68e+03  -0.1 4.31e+01   1.5 8.83e-03 4.14e-03f  1
 257r 0.0000000e+00 1.49e+05 6.69e+03  -0.1 1.60e+00   1.9 9.57e-02 7.53e-02h  1
 258r 0.0000000e+00 1.73e+05 3.42e+03  -0.1 7.28e-01   2.4 2.19e-01 8.33e-02f  1
 259r 0.0000000e+00 2.71e+03 1.94e+03  -0.1 8.76e-01   1.9 3.08e-02 6.87e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 260r 0.0000000e+00 3.67e+04 4.22e+03  -0.1 8.70e+00   1.4 4.96e-02 7.31e-02f  1
 261r 0.0000000e+00 3.56e+04 4.03e+03  -0.1 1.55e+00   1.8 1.41e-01 3.01e-02h  1
 262r 0.0000000e+00 1.91e+03 2.11e+03  -0.1 2.54e+00   1.4 1.91e-01 1.74e-01h  1
 263r 0.0000000e+00 1.78e+04 2.58e+03  -0.1 2.29e+00   1.8 5.03e-01 1.69e-02f  1
 264r 0.0000000e+00 2.80e+03 2.30e+03  -0.1 1.33e+00   2.2 4.66e-02 3.70e-01h  1
 265r 0.0000000e+00 2.45e+03 2.08e+03  -0.1 1.33e+00   1.7 2.00e-01 9.57e-02f  2
 266r 0.0000000e+00 3.04e+04 7.08e+03  -0.1 1.44e+00   1.3 8.86e-02 4.75e-02F  1
 267r 0.0000000e+00 2.94e+04 6.81e+03  -0.1 2.47e+00   1.7 1.76e-02 3.53e-02f  1
 268r 0.0000000e+00 2.83e+04 6.58e+03  -0.1 3.46e+00   1.2 3.58e-02 3.28e-02f  1
 269r 0.0000000e+00 2.59e+04 5.92e+03  -0.1 3.59e+00   1.6 3.68e-02 7.92e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 270r 0.0000000e+00 2.51e+04 5.38e+03  -0.1 5.07e+00   1.2 1.01e-01 1.00e-01f  1
 271r 0.0000000e+00 2.38e+04 5.06e+03  -0.1 3.02e+00   1.6 2.68e-01 5.16e-02h  1
 272r 0.0000000e+00 1.82e+04 3.25e+03  -0.1 2.91e+00   1.1 3.58e-01 2.25e-01h  1
 273r 0.0000000e+00 1.57e+04 2.77e+03  -0.1 1.15e+00   1.5 1.41e-02 1.38e-01H  1
 274r 0.0000000e+00 1.33e+04 2.29e+03  -0.1 1.04e+01   1.1 9.63e-02 1.28e-01f  1
 275r 0.0000000e+00 1.31e+04 2.01e+03  -0.1 6.91e-01   1.5 4.51e-01 1.71e-01H  1
 276r 0.0000000e+00 1.29e+04 1.99e+03  -0.1 1.72e+00   1.0 1.38e-01 8.80e-03h  1
 277r 0.0000000e+00 9.73e+02 1.73e+03  -0.1 2.04e+00   1.4 4.23e-01 1.79e-01h  2
 278r 0.0000000e+00 2.22e+04 1.52e+03  -0.1 3.05e+00   0.9 3.25e-01 2.36e-02f  1
 279r 0.0000000e+00 1.91e+03 2.31e+03  -0.1 1.11e+00   1.4 1.00e+00 1.00e+00F  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 280r 0.0000000e+00 2.01e+04 1.96e+03  -0.1 1.72e+00   1.8 3.01e-01 1.99e-01f  1
 281r 0.0000000e+00 1.43e+04 2.78e+03  -0.1 5.62e+00   1.3 4.27e-02 1.70e-01h  1
 282r 0.0000000e+00 1.42e+04 2.76e+03  -0.1 1.95e+00   1.8 1.79e-01 5.90e-03h  1
 283r 0.0000000e+00 1.10e+04 2.44e+03  -0.1 2.43e+00   1.3 2.87e-01 1.03e-01h  1
 284r 0.0000000e+00 1.48e+03 2.33e+03  -0.1 1.74e+00   1.7 8.59e-02 2.78e-01h  1
 285r 0.0000000e+00 2.61e+04 2.42e+03  -0.1 3.92e+00   1.2 2.09e-01 3.35e-02f  1
 286r 0.0000000e+00 2.58e+04 2.39e+03  -0.1 5.67e+00   0.7 1.76e-01 1.22e-02h  1
 287r 0.0000000e+00 1.49e+04 1.39e+03  -0.1 3.27e+00   1.2 1.51e-01 3.78e-01h  1
 288r 0.0000000e+00 1.39e+04 6.34e+02  -0.1 6.41e-01   1.6 1.54e-01 3.12e-01H  1
 289r 0.0000000e+00 1.31e+04 5.68e+02  -0.1 1.16e+00   2.0 6.73e-02 5.11e-02h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 290r 0.0000000e+00 9.26e+03 4.02e+02  -0.1 1.69e+00   1.5 1.79e-01 2.45e-01h  1
 291r 0.0000000e+00 8.86e+03 5.69e+02  -0.1 5.90e-01   2.0 1.46e-01 1.80e-01H  1
 292r 0.0000000e+00 8.49e+03 9.38e+02  -0.1 5.57e-01   2.4 2.00e-01 3.11e-02h  1
 293r 0.0000000e+00 7.11e+03 1.22e+03  -0.1 6.66e-01   1.9 1.87e-01 8.31e-02h  1
 294r 0.0000000e+00 6.30e+03 1.08e+03  -0.1 2.18e+01   1.4 2.15e-04 4.70e-03h  2
 295r 0.0000000e+00 6.12e+03 1.07e+03  -0.1 9.15e+00   1.9 1.78e-02 4.18e-03H  1
 296r 0.0000000e+00 6.08e+03 1.25e+03  -0.1 9.95e-01   2.3 1.83e-02 4.08e-02F  1
 297r 0.0000000e+00 5.82e+03 1.32e+03  -0.1 6.73e-01   1.8 5.95e-02 2.38e-02h  1
 298r 0.0000000e+00 5.74e+03 1.25e+03  -0.1 7.47e-01   2.2 1.89e-01 1.32e-02F  1
 299r 0.0000000e+00 1.28e+04 1.57e+03  -0.1 1.10e+00   1.8 1.82e-02 5.81e-02F  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 300r 0.0000000e+00 1.26e+04 1.69e+03  -0.1 6.88e-01   2.2 8.69e-02 7.17e-02F  1
 301r 0.0000000e+00 1.04e+04 3.04e+03  -0.1 7.80e-01   1.7 7.74e-02 9.79e-02h  1
 302r 0.0000000e+00 1.04e+04 3.03e+03  -0.1 7.06e-01   2.1 4.75e-02 2.01e-02F  1
 303r 0.0000000e+00 9.55e+03 4.14e+03  -0.1 8.64e-01   1.7 3.19e-02 3.22e-02h  1
 304r 0.0000000e+00 9.49e+03 4.21e+03  -0.1 7.98e-01   2.1 1.57e-02 1.76e-02F  1
 305r 0.0000000e+00 9.12e+03 5.28e+03  -0.1 3.35e+00   1.6 7.44e-03 9.32e-03h  1
 306r 0.0000000e+00 7.53e+03 9.33e+03  -0.1 1.01e+00   2.0 2.61e-02 1.23e-01F  1
 307r 0.0000000e+00 1.53e+05 3.25e+03  -0.1 8.05e-01   2.5 2.84e-02 4.01e-02f  1
 308r 0.0000000e+00 3.64e+02 3.14e+03  -0.1 2.62e+00   2.0 3.97e-02 3.34e-02h  1
 309r 0.0000000e+00 1.55e+05 3.08e+03  -0.1 1.85e+00   1.5 5.92e-02 1.97e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 310r 0.0000000e+00 9.54e+01 2.69e+03  -0.1 7.01e+00   1.0 3.09e-02 1.26e-01f  1
 311r 0.0000000e+00 5.60e+03 9.28e+03  -0.1 2.50e+00   1.5 1.56e-01 5.63e-02f  1
 312r 0.0000000e+00 3.23e+03 1.15e+04  -0.1 1.75e+00   1.9 1.55e-01 1.38e-01h  1
 313r 0.0000000e+00 5.69e+03 1.17e+04  -0.1 1.45e+00   1.4 1.22e-02 1.65e-02H  1
 314r 0.0000000e+00 5.43e+03 1.17e+04  -0.1 1.15e+00   1.8 1.54e-01 3.47e-02f  4
 315r 0.0000000e+00 5.25e+03 1.20e+04  -0.1 1.77e+00   1.4 3.91e-02 2.20e-02f  4
 316r 0.0000000e+00 5.09e+03 1.23e+04  -0.1 1.09e+00   1.8 2.50e-01 3.90e-02H  1
 317r 0.0000000e+00 4.87e+03 3.92e+03  -0.1 2.19e+00   1.3 3.21e-01 3.02e-01F  1
 318r 0.0000000e+00 1.53e+05 2.87e+03  -0.1 1.72e+00   1.7 1.78e-01 3.95e-02h  1
 319r 0.0000000e+00 1.50e+05 2.81e+03  -0.1 9.12e+00   1.3 4.70e-02 2.30e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 320r 0.0000000e+00 1.45e+05 2.72e+03  -0.1 4.75e+00   0.8 6.86e-02 3.05e-02f  1
 321r 0.0000000e+00 1.89e+05 3.10e+03  -0.1 2.12e+00   1.2 2.96e-01 1.29e-01f  1
 322r 0.0000000e+00 4.72e+03 3.34e+03  -0.1 7.28e+00   0.7 1.74e-01 3.75e-01h  1
 323r 0.0000000e+00 4.48e+03 3.16e+03  -0.1 2.86e+00   1.2 2.47e-01 5.33e-02f  1
 324r 0.0000000e+00 1.59e+05 1.20e+03  -0.1 4.91e+00   0.7 8.14e-02 6.50e-02f  1
 325r 0.0000000e+00 1.41e+05 6.24e+02  -0.1 2.27e+00   1.1 1.71e-01 8.99e-02h  1
 326r 0.0000000e+00 4.93e+03 3.33e+03  -0.1 2.49e+01   0.6 8.70e-04 2.83e-02f  1
 327r 0.0000000e+00 2.39e+04 9.66e+03  -0.1 4.56e+00   1.1 2.35e-01 5.19e-02f  1
 328r 0.0000000e+00 2.04e+04 7.64e+03  -0.1 4.70e+00   0.6 1.55e-01 1.84e-01h  1
 329r 0.0000000e+00 2.00e+04 7.49e+03  -0.1 1.78e+01   0.1 5.47e-02 1.97e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 330r 0.0000000e+00 1.87e+04 6.97e+03  -0.1 4.83e+00   0.5 1.04e-01 6.53e-02f  1
 331r 0.0000000e+00 1.52e+04 5.88e+03  -0.1 1.11e+01   0.0 5.11e-02 1.72e-01f  1
 332r 0.0000000e+00 1.02e+04 5.40e+03  -0.1 5.07e+00   0.5 3.94e-02 1.75e-01f  1
 333r 0.0000000e+00 3.76e+03 1.93e+03  -0.1 1.89e+00   0.9 5.10e-01 6.17e-01f  1
 334r 0.0000000e+00 8.77e+02 9.75e+02  -0.1 7.24e-01   1.3 7.22e-01 1.00e+00f  1
 335r 0.0000000e+00 3.40e+03 5.70e+02  -0.1 4.16e-01   1.7 4.06e-01 9.92e-01f  1
 336r 0.0000000e+00 6.22e+03 8.37e+02  -0.1 1.01e+00   2.2 1.35e-01 3.04e-01f  1
 337r 0.0000000e+00 5.66e+03 5.87e+02  -0.1 1.76e-01   2.6 3.96e-01 9.32e-02f  1
 338r 0.0000000e+00 5.21e+03 3.71e+02  -0.1 4.41e-01   2.1 2.36e-01 3.02e-01f  1
 339r 0.0000000e+00 6.08e+03 5.07e+02  -0.1 1.61e+00   1.6 1.23e-01 1.79e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 340r 0.0000000e+00 4.82e+03 8.17e+02  -0.1 2.72e-01   2.1 1.00e+00 2.11e-01f  1
 341r 0.0000000e+00 3.34e+03 5.43e+02  -0.1 5.39e-01   1.6 2.38e-01 3.42e-01f  1
 342r 0.0000000e+00 3.29e+03 5.37e+02  -0.1 5.69e+01   1.1 5.17e-03 5.50e-03f  1
 343r 0.0000000e+00 2.66e+03 9.91e+02  -0.1 3.66e-01   1.5 8.32e-01 2.00e-01f  1
 344r 0.0000000e+00 2.26e+03 8.35e+02  -0.1 9.46e-01   1.1 5.42e-01 1.46e-01f  1
 345r 0.0000000e+00 5.96e+02 1.90e+02  -0.1 3.35e-01   1.5 1.00e+00 7.93e-01f  1
 346r 0.0000000e+00 1.78e+03 1.28e+02  -0.1 9.70e-01   1.0 1.00e+00 7.02e-01f  1
 347r 0.0000000e+00 1.74e+03 2.52e+02  -0.1 3.07e+00   0.5 1.00e+00 5.11e-01f  1
 348r 0.0000000e+00 4.12e+03 5.17e+02  -0.1 6.35e+00   0.1 1.00e+00 3.20e-01f  1
 349r 0.0000000e+00 8.17e+03 5.36e+02  -0.1 1.28e+01  -0.4 4.57e-01 1.71e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 350r 0.0000000e+00 2.54e+04 6.40e+02  -0.1 3.18e+01  -0.9 3.63e-01 1.68e-01f  1
 351r 0.0000000e+00 2.47e+04 6.02e+02  -0.1 1.47e+01  -0.5 5.00e-01 2.01e-01f  1
 352r 0.0000000e+00 2.23e+04 4.38e+02  -0.1 3.25e+01  -0.9 3.98e-01 1.02e-01f  1
 353r 0.0000000e+00 1.41e+04 6.96e+02  -0.1 8.14e+01  -1.4 7.66e-01 2.15e-01f  1
 354r 0.0000000e+00 1.24e+04 1.13e+03  -0.1 2.57e+03    -  1.64e-01 5.81e-02f  1
 355r 0.0000000e+00 1.72e+04 7.59e+02  -0.1 2.18e+03    -  1.02e-01 2.06e-01f  1
 356r 0.0000000e+00 1.90e+04 6.29e+02  -0.1 1.38e+02  -1.9 1.00e+00 2.95e-01f  1
 357r 0.0000000e+00 7.17e+04 3.44e+02  -0.1 1.35e+03    -  4.55e-01 4.54e-01f  1
 358r 0.0000000e+00 6.12e+04 2.70e+02  -0.1 6.36e+02    -  2.18e-01 2.13e-01f  1
 359r 0.0000000e+00 4.42e+04 5.96e+02  -0.1 5.93e+02    -  5.31e-01 2.43e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 360r 0.0000000e+00 3.38e+04 6.02e+02  -0.1 3.72e+02    -  4.50e-01 1.99e-01f  1
 361r 0.0000000e+00 2.89e+04 5.75e+02  -0.1 3.40e+02    -  1.00e+00 1.70e-01f  1
 362r 0.0000000e+00 1.63e+04 4.23e+02  -0.1 2.88e+02    -  1.00e+00 4.33e-01f  1
 363r 0.0000000e+00 9.67e+02 8.45e+00  -0.1 1.64e+02    -  1.00e+00 1.00e+00f  1
 364r 0.0000000e+00 4.91e+02 8.35e+01  -0.8 9.59e+01    -  1.00e+00 6.86e-01f  1
 365r 0.0000000e+00 2.62e+03 6.05e+01  -0.8 3.55e+02    -  1.00e+00 7.08e-01f  1
 366r 0.0000000e+00 1.84e+02 2.12e-01  -0.8 8.68e+01    -  1.00e+00 1.00e+00f  1
 367r 0.0000000e+00 8.69e+01 2.70e+01  -3.3 1.20e+02    -  8.85e-01 7.82e-01f  1
 368r 0.0000000e+00 6.15e+02 1.60e+02  -3.3 7.33e+03    -  7.78e-01 4.63e-01f  1
 369r 0.0000000e+00 4.95e+02 3.69e+02  -3.3 1.36e+03    -  1.00e+00 2.28e-01f  1

iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
 370r 0.0000000e+00 3.30e+02 4.42e+02  -3.3 4.60e+03    -  9.48e-01 4.13e-01f  1
 371r 0.0000000e+00 3.07e+02 8.60e+02  -3.3 4.69e+03    -  1.00e+00 7.02e-02f  1
 372r 0.0000000e+00 1.58e+02 4.74e+02  -3.3 4.94e+03    -  1.00e+00 4.89e-01f  1
 373r 0.0000000e+00 5.21e+01 1.44e+02  -3.3 9.75e+02    -  1.00e+00 6.71e-01f  1
 374r 0.0000000e+00 1.43e+00 4.93e+00  -3.3 2.49e+02    -  1.00e+00 9.73e-01f  1
 375r 0.0000000e+00 5.04e-04 7.41e-05  -3.3 8.74e+00    -  1.00e+00 1.00e+00h  1
 376r 0.0000000e+00 2.05e-03 1.77e-01  -7.5 1.38e+02    -  1.00e+00 9.90e-01f  1
 377r 0.0000000e+00 1.13e-03 3.01e+02  -7.5 4.86e+00    -  1.00e+00 4.50e-01f  1
 378r 0.0000000e+00 2.84e-04 1.07e+02  -7.5 2.37e+00    -  9.87e-01 7.48e-01f  1
 379  0.0000000e+00 8.61e-09 1.10e+05  -1.0 2.92e-01    -  9.90e-01 1.00e+00h  1

Number of Iterations....: 379

                                   (scaled)                 (unscaled)
Objective...............:   0.0000000000000000e+00    0.0000000000000000e+00
Dual infeasibility......:   0.0000000000000000e+00    0.0000000000000000e+00
Constraint violation....:   4.8871011935219455e-12    8.6147338151931763e-09
Complementarity.........:   0.0000000000000000e+00    0.0000000000000000e+00
Overall NLP error.......:   4.8871011935219455e-12    8.6147338151931763e-09


Number of objective function evaluations             = 523
Number of objective gradient evaluations             = 5
Number of equality constraint evaluations            = 524
Number of inequality constraint evaluations          = 0
Number of equality constraint Jacobian evaluations   = 382
Number of inequality constraint Jacobian evaluations = 0
Number of Lagrangian Hessian evaluations             = 379
Total CPU secs in IPOPT (w/o function evaluations)   =      6.121
Total CPU secs in NLP function evaluations           =   1697.792

EXIT: Optimal Solution Found.
  • To my inexpert eyes, it looks like there's a lot more iterations (with the r suffix) in my run, whereas the version in the repo has 17 iterations (without the r suffix)
  • Also, I noticed that the Ipopt version is different (3.13.2 for my run, 3.12.13 for the version in the repo). Could this be related to the difference in behaviors?

@lbianchi-lbl
Copy link
Contributor Author

@bpaul4 @agarciadiego Since as I understand you have an environment where this notebook runs in a reasonable time, could you try running idaes environment-info in that environment and post here the output?

@adowling2
Copy link
Contributor

adowling2 commented Dec 21, 2021

@lbianchi-lbl Yes, 'r' means Ipopt is struggling. It stands for restoration phase, which is essentially "last hope" mode before Ipopt gives up.

Yes, the difference in Ipopt version would explain it. Next step is to look up what changed in the Ipopt version. What Ipopt version is included in IDAES get extensions?

@lbianchi-lbl
Copy link
Contributor Author

@adowling2, thanks for the clarification. According to the Solvers section of the output of idaes environment-info, the Ipopt version currently being installed is 3.13.2 (which matches what one sees in the notebook's relevant output cells, when running from a fresh installation):

  Solvers
      bonmin: 1.8.8.0
      cbc: 2.10.4.0
      couenne: 0.5.8.0
      dot_sens: 1.0.0.0
      ipopt: 3.13.2.0
      ipopt_l1: 3.13.3.0
      ipopt_sens: 3.13.2.0
      k_aug: 0.1.0.0

Maybe @eslickj will have more information on when the ipopt version was updated in idaes-ext?

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 21, 2021

@lbianchi-lbl, here is my environment info:

IDAES
Version: 1.13.0.dev0
Git Hash: 2e0757f5a4a6d77e48ef9e2e953f20aa8aa97565
Binary Directory: C:\Users\bpaul\AppData\Local\idaes\bin
Data Directory: C:\Users\bpaul\AppData\Local\idaes
Global Config: C:\Users\bpaul\AppData\Local\idaes\idaes.conf

Pyomo
Version: 6.1.3a0

Python
Version: 3.8.5 (default, Sep 3 2020, 21:29:08) [MSC v.1916 64 bit (AMD64)]
Executable: C:\Users\bpaul\Miniconda3\python.exe

OS
Platform: Windows
Release: 10
Version: 10.0.19041

Dependencies
backports.shutil_get_terminal_size: 1.0.0
bunch: 1.0.1
click: 7.1.2
colorama: 0.4.4
flask: 2.0.1
flask-cors: 3.0.10
jupyter: 1.0.0
lxml: 4.6.3
matplotlib: 3.4.2
nbconvert: 6.1.0
nbformat: 5.1.3
networkx: 2.5.1
numpy: 1.21.4
pandas: 1.3.0
pint: 0.17
psutil: 5.8.0
pytest: 6.2.4
python-slugify: 5.0.2
pywin32: 225
pyyaml: 5.4.1
rbfopt: 4.2.2
requests: 2.24.0
scipy: 1.7.0
sympy: 1.8
tinydb: 4.5.0

Extras
seaborn: Not Installed

Solvers
bonmin: 1.8.8.0
cbc: 2.10.4.0
couenne: 0.5.8.0
dot_sens: 1.0.0.0
ipopt: 3.13.2.0
ipopt_l1: 3.13.3.0
ipopt_sens: 3.13.2.0
k_aug: 0.1.0.0

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 21, 2021

Here is the IPOPT output for the initial solve (post-initialization). I scaled some variables as follows to get the build.py -t test to pass without a timeout error:

# Set scaling for model components
def set_scaling_factors(m):
    for unit in ['H101', 'R101', 'H102', 'F101']:
        if unit == 'F101':
            stream_list = ['inlet', 'vap_outlet', 'liq_outlet']
        else:
            stream_list = ['inlet', 'outlet']
        for stream in stream_list:
            block = getattr( getattr(m.fs, unit), stream )
            iscale.set_scaling_factor( getattr(block, 'flow_mol')[0], 1e2)
            iscale.set_scaling_factor( getattr(block, 'temperature')[0], 1e2)
            iscale.set_scaling_factor( getattr(block, 'pressure')[0], 1e6)
    iscale.calculate_scaling_factors(m)

Solver output:

Ipopt 3.13.2: 

******************************************************************************
This program contains Ipopt, a library for large-scale nonlinear optimization.
 Ipopt is released as open source code under the Eclipse Public License (EPL).
         For more information visit http://projects.coin-or.org/Ipopt

This version of Ipopt was compiled from source code available at
    https://github.com/IDAES/Ipopt as part of the Institute for the Design of
    Advanced Energy Systems Process Systems Engineering Framework (IDAES PSE
    Framework) Copyright (c) 2018-2019. See https://github.com/IDAES/idaes-pse.

This version of Ipopt was compiled using HSL, a collection of Fortran codes
    for large-scale scientific computation.  All technical papers, sales and
    publicity material resulting from use of the HSL codes within IPOPT must
    contain the following acknowledgement:
        HSL, a collection of Fortran codes for large-scale scientific
        computation. See http://www.hsl.rl.ac.uk.
******************************************************************************

This is Ipopt version 3.13.2, running with linear solver ma27.

Number of nonzeros in equality constraint Jacobian...:     4334
Number of nonzeros in inequality constraint Jacobian.:        0
Number of nonzeros in Lagrangian Hessian.............:     2692

Total number of variables............................:      551
                     variables with only lower bounds:      303
                variables with lower and upper bounds:      194
                     variables with only upper bounds:       44
Total number of equality constraints.................:      551
Total number of inequality constraints...............:        0
        inequality constraints with only lower bounds:        0
   inequality constraints with lower and upper bounds:        0
        inequality constraints with only upper bounds:        0

iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
   0  0.0000000e+00 5.61e+04 1.00e+00  -1.0 0.00e+00    -  0.00e+00 0.00e+00   0
   1  0.0000000e+00 5.61e+04 7.10e+01  -1.0 1.94e+07    -  1.11e-03 1.53e-05h  1
   2r 0.0000000e+00 5.61e+04 9.99e+02   2.7 0.00e+00    -  0.00e+00 7.66e-08R  2
   3r 0.0000000e+00 5.76e+04 9.95e+02   2.7 5.57e+05    -  1.50e-02 1.33e-03f  1
   4r 0.0000000e+00 5.66e+04 9.84e+02   2.7 1.23e+04    -  1.04e-02 1.15e-02f  1
   5r 0.0000000e+00 5.61e+04 1.32e+03   2.7 6.13e+03    -  2.15e-02 1.38e-02f  1
   6r 0.0000000e+00 5.63e+04 1.32e+03   2.7 2.49e+04    -  5.85e-04 7.54e-04f  1
   7r 0.0000000e+00 5.75e+04 9.68e+03   2.7 5.57e+03    -  7.97e-02 2.92e-02f  1
   8r 0.0000000e+00 5.75e+04 7.59e+04   2.7 8.14e+03    -  2.51e-01 6.20e-02f  1
   9r 0.0000000e+00 5.50e+04 5.41e+04   2.7 4.91e+03    -  7.65e-04 7.38e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  10r 0.0000000e+00 5.31e+04 5.41e+04   2.7 1.54e+03   0.0 9.03e-02 4.28e-02f  1
  11r 0.0000000e+00 5.06e+04 6.35e+04   2.7 7.40e+03    -  2.84e-01 5.82e-02f  1
  12r 0.0000000e+00 4.10e+04 6.05e+04   2.7 1.59e+03    -  8.00e-01 3.51e-01f  1
  13r 0.0000000e+00 2.84e+04 1.72e+04   2.7 5.49e+02    -  9.91e-01 7.53e-01f  1
  14r 0.0000000e+00 2.27e+04 2.63e+04   2.0 3.92e+02    -  3.39e-01 2.15e-01f  1
  15r 0.0000000e+00 1.32e+04 1.85e+04   2.0 4.32e+00   2.2 7.97e-01 5.45e-01f  1
  16r 0.0000000e+00 1.03e+04 1.27e+04   2.0 3.66e+02    -  3.41e-01 2.83e-01f  1
  17r 0.0000000e+00 1.15e+04 1.42e+04   2.0 1.99e+02    -  8.15e-01 5.36e-01f  1
  18r 0.0000000e+00 1.15e+04 4.57e+04   2.0 1.93e+02    -  9.73e-02 2.95e-01f  1
  19r 0.0000000e+00 9.15e+03 1.57e+04   2.0 1.26e+00   2.7 5.72e-01 7.70e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  20r 0.0000000e+00 7.97e+03 2.68e+04   2.0 3.10e+00   2.2 1.00e+00 3.28e-01f  1
  21r 0.0000000e+00 3.69e+03 4.84e+02   2.0 6.81e+01    -  1.00e+00 1.00e+00f  1
  22r 0.0000000e+00 4.60e+03 3.74e+02   0.6 1.10e+02    -  7.66e-01 7.84e-01f  1
  23r 0.0000000e+00 3.20e+03 4.68e+03   0.6 3.43e+02    -  4.71e-01 3.63e-01f  1
  24r 0.0000000e+00 9.68e+02 6.07e+03   0.6 5.20e-01   1.7 8.85e-01 7.78e-01f  1
  25r 0.0000000e+00 7.21e+02 1.03e+03   0.6 4.94e-01   1.2 7.22e-01 7.96e-01f  1
  26r 0.0000000e+00 7.21e+02 3.56e+03   0.6 2.25e+03    -  8.90e-03 8.08e-03f  2
  27r 0.0000000e+00 4.87e+02 2.33e+04   0.6 3.39e+00   2.6 2.20e-01 3.11e-01f  1
  28r 0.0000000e+00 4.06e+02 4.82e+04   0.6 2.33e+00   3.9 4.48e-02 8.82e-02h  1
  29r 0.0000000e+00 3.50e+02 5.16e+04   0.6 2.09e+00   3.4 1.10e-01 9.92e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  30r 0.0000000e+00 3.38e+02 5.00e+04   0.6 2.28e+00   2.9 1.11e-01 3.24e-02f  1
  31r 0.0000000e+00 2.89e+02 4.88e+04   0.6 3.46e+00   2.5 1.43e-01 1.27e-01h  1
  32r 0.0000000e+00 2.86e+02 4.85e+04   0.6 1.92e+00   2.0 2.78e-01 9.71e-03h  1
  33r 0.0000000e+00 2.12e+02 3.76e+04   0.6 2.16e+00   2.4 2.68e-01 2.37e-01h  1
  34r 0.0000000e+00 1.69e+02 3.03e+04   0.6 1.70e+00   1.9 1.00e+00 2.13e-01f  1
  35r 0.0000000e+00 8.50e+01 1.68e+04   0.6 1.45e+00   2.4 9.65e-01 4.80e-01f  1
  36r 0.0000000e+00 7.13e+01 5.15e+04   0.6 9.53e-01   1.9 1.00e+00 1.85e-01f  1
  37r 0.0000000e+00 4.96e+01 2.56e+04   0.6 9.32e-01   2.3 4.46e-01 3.96e-01f  1
  38r 0.0000000e+00 3.88e+01 7.39e+03   0.6 3.99e-01   1.8 1.00e+00 8.03e-01f  1
  39r 0.0000000e+00 3.70e+01 1.68e+03   0.6 1.47e+00   1.3 6.76e-01 5.29e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  40r 0.0000000e+00 4.25e+01 4.00e+01   0.6 6.26e-01   1.8 1.00e+00 1.00e+00f  1
  41r 0.0000000e+00 3.58e+01 9.36e+02  -0.8 2.88e+00   1.3 2.23e-01 1.13e-01f  1
  42r 0.0000000e+00 9.20e+01 2.86e+03  -0.8 3.51e-01   1.7 9.02e-01 5.41e-01f  1
  43r 0.0000000e+00 6.92e+02 1.39e+03  -0.8 6.21e-01   1.2 8.45e-01 5.90e-01f  1
  44r 0.0000000e+00 7.43e+02 9.93e+02  -0.8 1.90e+00   0.8 6.70e-01 3.17e-01f  1
  45r 0.0000000e+00 6.63e+02 8.84e+02  -0.8 5.89e+00   0.3 1.86e-02 1.06e-01f  1
  46r 0.0000000e+00 5.87e+02 7.91e+02  -0.8 2.00e+01  -0.2 3.13e-01 1.14e-01f  1
  47r 0.0000000e+00 1.42e+03 7.37e+02  -0.8 7.09e+01  -0.7 2.52e-01 7.40e-02f  1
  48r 0.0000000e+00 3.21e+03 7.24e+02  -0.8 3.68e+02  -1.1 1.23e-02 1.84e-02f  1
  49r 0.0000000e+00 3.05e+03 8.78e+02  -0.8 5.16e+01  -0.7 2.96e-01 6.50e-02f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  50r 0.0000000e+00 2.97e+03 8.23e+02  -0.8 1.87e+02  -1.2 5.70e-04 1.52e-02f  1
  51r 0.0000000e+00 2.74e+03 8.98e+02  -0.8 3.09e+03    -  5.29e-02 2.59e-02f  1
  52r 0.0000000e+00 2.71e+03 1.25e+03  -0.8 3.18e+03    -  1.34e-01 1.54e-02f  1
  53r 0.0000000e+00 2.69e+03 1.14e+03  -0.8 3.10e+03    -  5.93e-03 3.14e-02f  1
  54r 0.0000000e+00 2.48e+03 1.13e+03  -0.8 2.81e+03    -  1.50e-01 1.05e-01f  1
  55r 0.0000000e+00 2.47e+03 1.24e+03  -0.8 2.08e+03    -  4.99e-02 6.72e-04f  1
  56r 0.0000000e+00 2.70e+03 1.55e+03  -0.8 1.86e+03    -  2.18e-01 3.61e-02f  1
  57r 0.0000000e+00 3.01e+03 2.08e+03  -0.8 7.24e+02    -  1.00e+00 9.29e-02f  1
  58r 0.0000000e+00 5.48e+03 1.32e+03  -0.8 1.19e+03    -  1.00e+00 2.24e-01f  1
  59r 0.0000000e+00 6.79e+03 7.39e+02  -0.8 8.37e+02    -  9.80e-01 4.87e-01f  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  60r 0.0000000e+00 8.08e+03 8.26e+02  -0.8 1.20e+03    -  3.55e-01 1.50e-01f  1
  61r 0.0000000e+00 6.42e+03 1.28e+03  -0.8 7.65e+02    -  1.00e+00 2.08e-01f  1
  62r 0.0000000e+00 6.07e+02 9.55e+01  -0.8 5.29e+02    -  1.00e+00 9.24e-01f  1
  63r 0.0000000e+00 5.92e+00 5.11e-01  -0.8 2.01e+02    -  1.00e+00 1.00e+00h  1
  64r 0.0000000e+00 7.29e+00 1.29e+02  -2.2 1.80e+02    -  9.99e-01 6.60e-01f  1
  65r 0.0000000e+00 5.64e+02 3.24e+02  -2.2 1.23e+03    -  1.00e+00 6.10e-01f  1
  66r 0.0000000e+00 3.95e+02 2.92e+02  -2.2 9.94e+02    -  1.00e+00 3.94e-01f  1
  67r 0.0000000e+00 1.12e+02 2.81e+02  -2.2 1.51e+03    -  9.91e-01 7.16e-01f  1
  68r 0.0000000e+00 5.51e+00 2.55e+01  -2.2 5.42e+02    -  1.00e+00 9.60e-01f  1
  69r 0.0000000e+00 2.06e-01 1.88e-03  -2.2 1.14e+02    -  1.00e+00 1.00e+00h  1
iter    objective    inf_pr   inf_du lg(mu)  ||d||  lg(rg) alpha_du alpha_pr  ls
  70r 0.0000000e+00 7.70e-02 1.68e+02  -5.0 3.53e+02    -  8.44e-01 9.34e-01f  1
  71r 0.0000000e+00 7.67e-02 3.08e+04  -5.0 4.97e+04    -  9.57e-01 9.66e-03f  1
  72r 0.0000000e+00 4.58e-02 2.91e+04  -5.0 4.60e+02    -  1.00e+00 3.96e-01f  1
  73r 0.0000000e+00 5.41e-04 5.02e+02  -5.0 1.23e+02    -  1.00e+00 9.85e-01f  1
  74r 0.0000000e+00 2.67e-04 3.97e-04  -5.0 2.28e+00    -  1.00e+00 1.00e+00h  1
  75r 0.0000000e+00 3.41e-05 1.86e+02  -7.5 1.55e+00    -  1.00e+00 8.18e-01f  1

Number of Iterations....: 75

                                   (scaled)                 (unscaled)
Objective...............:   0.0000000000000000e+00    0.0000000000000000e+00
Dual infeasibility......:   0.0000000000000000e+00    0.0000000000000000e+00
Constraint violation....:   1.7379362458833627e-09    3.4096243325620890e-05
Complementarity.........:   0.0000000000000000e+00    0.0000000000000000e+00
Overall NLP error.......:   1.7379362458833627e-09    3.4096243325620890e-05


Number of objective function evaluations             = 80
Number of objective gradient evaluations             = 4
Number of equality constraint evaluations            = 80
Number of inequality constraint evaluations          = 0
Number of equality constraint Jacobian evaluations   = 77
Number of inequality constraint Jacobian evaluations = 0
Number of Lagrangian Hessian evaluations             = 75
Total CPU secs in IPOPT (w/o function evaluations)   =      7.869
Total CPU secs in NLP function evaluations           =    555.174

EXIT: Optimal Solution Found.

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 21, 2021

Looking at a much older version, it appears that the number of variables has jumped significantly - 551 variables and 550-700 CPU seconds now compared to 346 variables and 50 CPU seconds in this version which only took 7 iterations to solve with no restoration: https://github.com/agarciadiego/examples-pse/blob/internship/src/Examples/Advanced/CustomProperties/Hydrocarbon_Processing_example.ipynb

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 21, 2021

@agarciadiego and I investigated the issue, and the notebook ran as expected on his machine: IPOPT 3.13.2, 346 variables, 7 iterations, ~ 40 total CPU seconds. I will test re-generating the initialization file, if the timeout still occurs then the issue is probably due to a recent code or dependency update from a commit in mid-December when the tests started failing.

@lbianchi-lbl
Copy link
Contributor Author

@bpaul4 Thanks for the update and the detailed analysis.

I haven't thought about the initialization file (I assume you're talking about the HI_init.json.gz being generated or read in Cell 9 of the notebook) but I agree with you that this is definitely something worth investigating.

@agarciadiego would it be possible to upload the initialization file that's being used in your 7-iterations runs?

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 21, 2021

Generating a new HI_init.json.gz and then restarting/running the notebook immensely improved the solver runtime, less than 90 CPU seconds. We should probably make a note to regenerate any initialization files or packages anytime we change solver versions to avoid future issues.

I have saved the old .gz file using IPOPT 3.12 and a new one using IPOPT 3.13 with the scaling I implemented above. Currently, I'm running another version using IPOPT 3.13 without the scaling to see if we can leave the notebook itself alone. I will share all three files, and eventually can push our preferred .gz/notebook versions to #80.

@lbianchi-lbl
Copy link
Contributor Author

lbianchi-lbl commented Dec 21, 2021

@bpaul4 thanks a lot for checking that. That looks like a step in the right direction (again, from my limited expertise on this topic).

I tried something similar in #82, namely deleting the HI_init.json.gz file, committing, and pushing, so that the notebook is run in the CI jobs without that file, but it seems that it's still not enough to eliminate the errors: instead of the timeout we now have a solver failure. I tried re-running on the same commit, but I'm not too hopeful that it will change things.

EDIT I've just read your message more carefully, and I got your point about generating a new file. Yes, if you could, check how it behaves in these three cases and let us know how that goes.

@andrewlee94
Copy link
Member

@bpaul4 @lbianchi-lbl Based on the comments above, I suspect I know what happened.

We added some intermediate log_variables to the generic properties framework since the last release which would explain the additional variables you are seeing. Consequently, if you are initializing by loading an old json file, these variables would not be getting good initial values which would likely explain the solver issues we are seeing and why they can be fixed by initializing the model from scratch and creating a new json file.

To confirm, I would start by loading the old json file and check the model for log_variables - you will likely see that they all have default values. You could further confirm by calculating the correct values for these and manually setting them before calling the solver, which should should near-immediate convergence. If this is the case, then the correct solution is to just update the json file.

However, this then leads to the question of why we didn't notice this earlier and how we can make sure that we identify issues like these as soon as they occur (so that we know for sure which commit to idaes-pse caused the issue).

@bpaul4
Copy link
Contributor

bpaul4 commented Dec 21, 2021

I tested the notebook for 4 cases, and agree with your assessment @andrewlee94 . The test runs below I'm calling CI are the commands that the CI jobs run, while the build process is the test workflow recommended by our documentation. I noticed that the build.yml and build-ci.yml tests are not run the same way or with the same timeout limit.

  1. Load old initialization that used IPOPT 3.12, solve the original notebook with IPOPT 3.13; takes 650 CPU seconds to run and throws runtime error in both CI and build test runs (this is the "base case" error we have been seeing)

  2. Load old initialization that used IPOPT 3.12 and run with some variable scaling; takes 550 CPU seconds to run and only throws runtime error on CI runs (passes during build process)

  3. Train a new initialization file using IPOPT 3.13 on the original notebook; initialization ended up being infeasible and the solver does not find a solution

  4. Train a new initialization file using IPOPT 3.13 and run with some variable scaling; takes 30 CPU seconds to run and both build/CI runs pass on local machine

If this sufficiently addresses the error, I can push the updated json/notebook from case 4 to #80 and close this issue.

@lbianchi-lbl
Copy link
Contributor Author

lbianchi-lbl commented Dec 21, 2021

@bpaul4 that's great, thank you so much! If I understand correctly, case 3 is what I've been trying with the most recent commit on #82; if this is the case, then I can also confirm this behavior.

I'd say that the solution you're proposing sounds optimal, especially if you think this can be done quickly. If so, then please go ahead and add that fix to #80 (assuming the rest of the PR is ready to merge), so we can include this in the final 1.12.0 release of the IDAES examples.

@andrewlee94: thanks for the clarification. If, as I understand, this problem manifested itself only through a longer runtime, then I can see how that would be difficult to catch: the only check that's even indirectly measuring the runtime is the build timeout, but this is not a good test since it would be triggered if the slowdown caused the runtime to be greater than the threshold, but not otherwise. Ideally, we'd have a more systematic way of measuring performance (I tried a simple solution in #64) and analyze that data to detect performance regressions.

@adowling2
Copy link
Contributor

adowling2 commented Dec 22, 2021

This makes so much sense.

Is there a clean way to check the number of Ipopt iterations on some of these notebooks? Perhaps add another type of test that runs nightly. The downside is this would need to get updated every time we update Ipopt, etc.

@lbianchi-lbl
Copy link
Contributor Author

@adowling2 I agree that exposing the solver information to the notebook testing pipeline would be a better way to detect this type of issues than relying on the total runtime. Does the object returned by solver.solve() store this information? Alternatively, is there already some utility function to parse the Ipopt output to a Python object and/or machine-readable format?

@adowling2
Copy link
Contributor

@carldlaird @eslickj @jsiirola Here is a quick summary of this thread:

  • Some of the thermodynamic models were updated with extra intermediate variables during the past 1 month (?).
  • Some of the notebooks load saved initial points to keep the automated tests reasonable.
  • The saved initial points did not include the new intermediate variables in the thermodynamic models. As a result, the notebooks started timing out in the automated tests. (The new intermediate variables were not initialized.)
  • It took a few weeks to track down the root cause. This was complicated by the fact that the tests ran fine locally, but not in CI.

Now that you are up to speed, a few questions for you to weigh in on:

  • What are your thoughts on checking the number of Ipopt iterations in the notebooks that load initial points from a file? This would have helped us catch the issue faster.
  • Can you point us to any preferred ways to get the numbers of iterations from Ipopt?
  • Any suggestions on better ways to make this easier to debug in the future?

@carldlaird
Copy link

@adowling2

  • There is a way to get the iterations from an Ipopt solve. I wrote a script to do this, and I think Dan added this to IDAES. Let's add @dangunter.
  • If these initialization files are needed for the test, I think we should have a discussion about whether or not it makes sense to fail the test if some variables are missing. I suspect the json loader can give us this information. I realize this might make for many more testing problems as people change models, but it still might be the best thing to do.

@adowling2
Copy link
Contributor

@carldlaird +1 on your idea to check the json file (initial point) for missing variables.

@ksbeattie ksbeattie added the Priority:Normal Normal Priority Issue or PR label Jan 6, 2022
@adowling2
Copy link
Contributor

Moved two ideas to improve tested from this discussion to #85 and #86.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Priority:Normal Normal Priority Issue or PR
Projects
None yet
Development

No branches or pull requests

7 participants