Only show DEBUG messages if verbosity > 1

[rjgildea]

Following 0e4ec1d, this allows for getting the normal log output plus the timing information only. Previously, you could only get the normal output only, or the DEBUG messages plus timing. Since some DEBUG messages potentially involve some expensive calculations, timing output may not be representative of normal runtime.

[graeme-winter]

Works for me 🙂

[Anthchirp]

Not against it. However I'm also not sure if it makes sense to have -v basically make no change in the output beyond what you could also get with

command | while IFS= read -r line; do printf '[%s] %s\n' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done

or similar

I also don't know if it is useful from a user's point of view to just get timing information. What would be the use case for that?

In any case I note that dials commands' --help output does not suggest you can use -v multiple times

[rjgildea]

@Anthchirp as pointed out above, the current implementation as of 0e4ec1d means that you can only get timing information in combination with debug output, which may not be an accurate reflection of the true timing information (without debug output). If timing information isn't useful, why did was it added in the first place (#1057)? I probably would have preferred to add an additional -t command line flag, but this would have necessitated changing every call to dials.util.log.config - this PR is less invasive.

[Anthchirp]

Well, timing with regular output wasn't so useful, which is why we removed it. I think the current state (timing with -v, no timing without -v) is fine - even if the timings change between -v and not -v. But I'm not invested in this either way.

[rjgildea]

With the current state, timing information is definitely not useful, as it only reflects the timing of the debug mode, which may bare little relation with the actual timings. If the consensus is that timing information is not useful, then perhaps the timing information introduced in #1057 should be removed entirely, but then that will effectively re-open #932 - although perhaps 0e4ec1d already does that as the user now only gets by default the inconsistent timing information that #932 complained about.

[Anthchirp]

The timings in the "debug mode" will accurately describe the timings of the run in "debug mode". In my opinion it is a separate issue if we are doing wildly different things when running with -v compared to running without. I certainly would be surprised by a significant behavioural change when supplying a verbosity parameter.

[dagewa]

It happens here in refinement

dials/algorithms/refinement/refiner.py

Lines 1024 to 1028 in 0a33e73

	# These involve calculation, so skip them when output is quiet
	if logger.getEffectiveLevel() < logging.ERROR:
	self.print_step_table()
	self.print_out_of_sample_rmsd_table()
	self.print_exp_rmsd_table()

The amount of time it takes to run these calculations is minimal, but there is no point at all to run them if the results are not going to be displayed.

[dagewa]

I like it. I don't think there is a reason to introduce a new option like -t. Adding timing is exactly an increase in verbosity. Adding debug is an additional increase in verbosity. I can't think of a situation where you want the debug info, but absolutely must not have the timing. I can however see how timing would be useful, without seeing all the debug crud.

[dagewa]

It happens here in refinement

dials/algorithms/refinement/refiner.py

Lines 1024 to 1028 in 0a33e73

	# These involve calculation, so skip them when output is quiet
	if logger.getEffectiveLevel() < logging.ERROR:
	self.print_step_table()
	self.print_out_of_sample_rmsd_table()
	self.print_exp_rmsd_table()

The amount of time it takes to run these calculations is minimal, but there is no point at all to run them if the results are not going to be displayed.

Actually this just avoids calculation when refiner is truly quiet. I don't think there is a difference in calculation between info and debug any more in refiner

[Anthchirp]

I like it. Adding timing is exactly an increase in verbosity.

👍 In that case I suggest amending the command line help text to indicate -v can be used multiple times

and fixing the failing test before merging 🙂

[rjgildea]

I like it. Adding timing is exactly an increase in verbosity.

👍 In that case I suggest amending the command line help text to indicate -v can be used multiple times

and fixing the failing test before merging 🙂

Done and done 👍