Update time-logging and debugging messages

[shorvath-noaa]

We need to update our time-logging and debugging messages for the BMI implementation of V4. For example, this is under main_v04() in main.py to initialize time-logging:

showtiming = log_parameters.get("showtiming", None)
if showtiming:
    task_times = {}
    task_times['forcing_time'] = 0
    task_times['route_time'] = 0
    task_times['output_time'] = 0
    main_start_time = time.time()

Each of these task times are updated throughout main.py as tasks are run. The final step of main_v04() is to print out total times:

if showtiming:
  task_times['total_time'] = time.time() - main_start_time

LOG.debug("process complete in %s seconds." % (time.time() - main_start_time))

if showtiming:
  print('************ TIMING SUMMARY ************')
  print('----------------------------------------')
  print(
      'Network graph construction: {} secs, {} %'\
      .format(
          round(task_times['network_creation_time'],2),
          round(task_times['network_creation_time']/task_times['total_time'] * 100,2)
      )
  )
  print(
      'Forcing array construction: {} secs, {} %'\
      .format(
          round(task_times['forcing_time'],2),
          round(task_times['forcing_time']/task_times['total_time'] * 100,2)
      )
  ) 
  print(
      'Routing computations: {} secs, {} %'\
      .format(
          round(task_times['route_time'],2),
          round(task_times['route_time']/task_times['total_time'] * 100,2)
      )
  ) 
  print(
      'Output writing: {} secs, {} %'\
      .format(
          round(task_times['output_time'],2),
          round(task_times['output_time']/task_times['total_time'] * 100,2)
      )
  )
  print('----------------------------------------')
  print(
      'Total execution time: {} secs'\
      .format(
          round(task_times['network_creation_time'],2) +
          round(task_times['forcing_time'],2) +
          round(task_times['route_time'],2) +
          round(task_times['output_time'],2)
      )
  )

Current behavior

Time logging is done in main.py, so when we run t-route through BMI functions we are not keeping track of timing.

Expected behavior

Time logging and optional print out of times when running t-route through BMI functions. I'm thinking this can go in troute_model.py, but it doesn't have to.

Steps to replicate behavior (include URLs)

1.

Screenshots

[shorvath-noaa]

@AminTorabi-NOAA