How to gather timing information on every step of a pipeline?

[graue70]

(This separates the two questions from #7425.)

I want to store how long each component in my pipeline took.

This kind of timing information would obviously best be gathered in Language.__call__(). As I do it, I get the timing information only for my custom components. I don't see a way to hook into the loop.

1. Is my only choice to wrap the spaCy components in custom components like this?

def __call__(self, doc: Doc) -> Doc:
    start_time = time.time()
    doc = self.wrapped_component(doc)
    doc._.timing[self.wrapped_component.name] = time.time() - start_time
    return doc

2. Would adding the possibility to record timing for all steps of a pipeline be a welcome addition to the spaCy code? Something like this for Language.__call__():

def __call__(self, text, timing=False):
    # ...
    for name, proc in self.pipeline():
        start_time = time.time()
        doc = proc(doc)
        if timing:
            doc.timing[name] = time.time() - start_time
    # ...
    return doc

I guess my questions boil down to: 'Is timing information the only use case for global extension attributes not related to a specific component?' If so, it might make sense to include it in Language.__call__(). If not, it might make sense to give the user the option to add initialization code to a pipeline.

[graue70]

(The original answer from @ines can be found at #7425 (comment).)

Is my only choice to wrap the spaCy components in custom components like this?

An alternative option would be to insert an instance of a simple timing logging component in between all existing component (e.g. on after_pipeline_creation). This works well for debugging purposes, but it's maybe not that pretty because you end up with a bunch of extra components.

I agree that it's not nice to need twice as many components just to get timing information.

Would adding the possibility to record timing for all steps of a pipeline be a welcome addition to the spaCy code?

Just making it about timing is too specific and not really customisable enough – but I do see the general appeal of being able to hook into Language.__call__ before/after a pipeline component is applied. The problem is that conceptually, this would actually end up being quite similar to the "components between components" setup, only much less explicit. The callback would have to receive the Doc object, but it shouldn't be modifying it – otherwise, the result would be very confusing and the callback would essentially just be a hidden pipeline component.

If you don't want the hook to modify the Doc object, how would the hook help me in gathering timing information? Where would it be stored if not in e.g. doc._.timing?

I guess it's meta information about the pipeline process and not about the document/text itself. At the moment, my component modifies the Doc twice, once with actual text related information and once with the meta timing information.

Maybe there should be hidden meta components which aren't shown by default? Maybe there should be a different namespace doc.meta.timing for meta information?

I get that doing this only for timing is very specific and not flexible, but I currently can't think of other meta information that could be gathered during the pipeline process (hence my suggestion). Can you?