Add individual command logging for index/constraint application step

[AetherUnbound]

Description

As part of the investigation around the API response time jumping dramatically during a data refresh, we identified that the index & constraint application step specifically was causing the API degradation. I suspect that there may be a single index/constraint application that is causing the slowness, rather than the entire set of ALTERs. In order to test this hypothesis, we need accurate logging for when each step is run.

Specifically, these two query executions should be split up into the individual alters, and each one should be logged when it is run:

openverse-api/ingestion_server/ingestion_server/ingest.py

Line 352 in 5435e0e

downstream_cur.execute(";\n".join(create_indices))

openverse-api/ingestion_server/ingestion_server/ingest.py

Line 359 in 5435e0e

downstream_cur.execute(remap_constraints)

Additional context

Similar logging was added for the go-live step in #415

Implementation

• 🙋 I would be interested in implementing this feature.

[sarayourfriend]

Specifically, these two query executions should be split up into the individual alters, and each one should be logged when it is run:

Please log when it is run and when it finishes, maybe even log the delta if possible just so it's nice and easy to diagnose if there's an issue there 🙂

[AetherUnbound]

Ah, they're run immediately after each other, so I was thinking the logs in CloudWatch would end up looking something like this:

2022-05-27 05:23:00,000 INFO ingest.py:356 - ALTER <column> ADD INDEX <foo>
2022-05-27 05:23:10,000 INFO ingest.py:356 - ALTER <column> ADD INDEX <bar>
2022-05-27 05:23:20,000 INFO ingest.py:356 - ALTER <column> ADD INDEX <baz>
2022-05-27 05:23:30,000 INFO ingest.py:356 - ALTER <column> ADD CONSTRAINT <zip>

Do you think that'd be sufficient? That would give us the exact indications of when each one starts, and since these are run serially the end can be assumed to just before the next line starts.

[sarayourfriend]

I guess for all except the last one?

[AetherUnbound]

These are the only steps run after before another log line appears:

openverse-api/ingestion_server/ingestion_server/ingest.py

Lines 353 to 356 in 5435e0e

	_update_progress(progress, 70.0)
	# Step 7: Recreate constraints from the original table
	log.info("Done creating indices! Remapping constraints...")

_update_progress just sets a value:

openverse-api/ingestion_server/ingestion_server/ingest.py

Lines 247 to 249 in 5435e0e

	def _update_progress(progress, new_value):
	if progress:
	progress.value = new_value

I feel like that gives us a good enough time bounding. If anything though, I can swap the log line and the _update_progress one.