Added time prints of VQE to the log

[yaelbh]

Summary

We encapsulate circuit executions and operator evaluations with time measurements, then print to the log.

Details and comments

Can consider the following alternative to this approach: the functions of execution (in Terra) and operator evaluation measure their run time, i.e., the run time is measured inside the function. Then they either print to the log by themselves or return the run time in a variable. In the second case (return in a variable), either the caller prints the run time to the log, or the user in a callback function has the freedom to process the run time in anyway, including printing it to the log. This requires adding a parameter to the callback function.

[woodsp-ibm]

The eval printing is done at info level (formerly done at debug) so users could see progress of the variation under the default logging settings. Otherwise vqe can seem to be 'stuck' from an external viewpoint (this was before we had the callback, and yes nowadays one can use that but its extra effort as such). Also the log can be easily piped to file for later use etc.
Adding the other timing log there for the execution outside the for loop will double the lines printed in general by default. Normally we do one set of parameters - there would only be more if one uses grouped evals which is not on by default. Grouping was intended to allow more to be parallelized by in practice with many ccts anyway with paulis it often made little to no difference in practice.
So here is what I am thinking - take the time from that first execution and add it as a 2nd time value in the original log line, that way we will only have one log output and the time would be properly representative by default. If one turned on eval group and had more than one parameter set you would then need to know this 2nd value is 'shared' so to speak across different parameter sets but I do not think that this is that bad. I would rather have this than twice as many log lines by default.

[yaelbh]

I agree with most, but am not happy with the solution for the rare case where there is more than one set of parameters. I suggest to check if this is the case, and if yes, then either do print the extra line of execution, or not to print times at all.

[woodsp-ibm]

As suggested that line would always contain the first circuit execution time but for multiple param sets it would be the same value (thats what I meant by shared). If you were trying to see the overall time in that case you would have to account for that.
It can be more complicated. You could save the first time, then save an array of times in the loop, and at the end log (at DEBUG level) the 'Circuit execution' time and the array of times (one for each parameter set - normally only one unless grouping). You could also include a sum total there too.

[yaelbh]

I've fixed something in the spirit of this discussion, hope it's OK.

[woodsp-ibm]

The change is fine by me, timing will be there by default. Using grouped evals will not produce it - arguably these just run in parallel so individual timing of any eval should be the same and if you wanted to see it you would have to temporarily turn off grouping.