Log some study definition stats and timings

[rebkwok]

Log some study definition stats and execution timings:

• study definition variable count
• count of variables using codelists
  • for each of these, size of the codelist
• output column count
• table query count
• joins count
• index dates - count, min, max
• measures count
• timing:
  • each executed query
  • full generate_cohort for each index date, and all index dates
  • writing cohort to file
  • generate_measures, for each input file

see #777

[rebkwok]

From the suggestions in the issue, the one that I haven't implemented is the suggestion to log

min and max dates from here

Min/max dates can be dynamic and involve other queries, not just dates, so I'm deferring figuring out how to deal with those until Seb's back and I can ask him

[bloodearnest]

This is wonderful. It will really help figuring stuff out.

Have left a scatter shot of minor questions and comments.

[bloodearnest]

Mild nit: I think the "cohortextractor" prefix is a possibly redundant, I'd probably prefer just "stats"

[bloodearnest]

I'm not very familiar with structlog or cohortextractor logging, but will this result in all stats being logged when running a cohortextractor job in with opensafely run?

I think we only want to enable this logging in production, as with dummy data its a) not very useful and b) noisy

Could we possibly disable this when running against the expectations backend? And also maybe enabled environment variable for testing/debugging?

[bloodearnest]

Hmm, I just realised most of the logging will only happen in prod anyway, as it's in the tpp/emis bits. But some would still happen in local running too, so probably still worth checking if it's noisy or confusing.

[rebkwok]

Mild nit: I think the "cohortextractor" prefix is a possibly redundant, I'd probably prefer just "stats"

The prefix was Dave's suggestion, but I'm sure he's not commited to it :). I think we want something unique for greppableness - "stats" might be too likely to turn up in places other than the stats log name

[bloodearnest]

Fair point.

[rebkwok]

Hmm, I just realised most of the logging will only happen in prod anyway, as it's in the tpp/emis bits. But some would still happen in local running too, so probably still worth checking if it's noisy or confusing.

Yes, all the particularly noisy things (SQL logging) will only happen on prod. I ran the SRO measures study locally to see what it produces, and I think it's ok - this is the log for the main cohort generation:
generate_study_population.log

It has all the codelist variables and sizes, which could possibly be useful in a local run, and it has the timing for the overall generate_cohort for each index date, which isn't particularly useful in a local run, but it's not that much noise

[rebkwok]

@bloodearnest I think this is ready for another review now - thanks for all the suggestions!

[bloodearnest]

This is fab. ONWARDS!