Add per-operation timing to segment_current_trips using ect.Timer

[TeachMeTW]

• Wrapped each significant operation within the segment_current_trips function with ect.Timer context managers.
• Named each timer using the pattern ecwp.PipelineStages.TRIP_SEGMENTATION.name + "/operation" for consistent identification.
• After each timed block, recorded the elapsed time by calling esds.store_pipeline_time with the appropriate parameters.
• Ensured that only timing-related code was added without altering existing logic, error handling, or formatting.

This enhancement enables granular performance monitoring of the trip segmentation process, allowing for better identification of potential bottlenecks and optimization opportunities.

[TeachMeTW]

@shankari Please review;

• added a timer to the "ad-hoc" pipeline step ✅
• add timers to parts of the trip segmentation, with suffixes ✅
• tested with a user intake, updates show when querying ✅

[shankari]

@TeachMeTW Thank you for the clean PR!

I don't think that the trip segmentations stats are fine-grained enough.
Did you look at the logs/stats from the "tested with a user intake, updates show when querying"?
My expectation is that the create_places_and_trips timer will account for the bulk of the overall time for the step (e.g. if the step takes 100ms, create_places_and_trips will account for 95ms). And you don't have any timers within create_places_and_trips, so you won't know where we are spending the time, and what we should try to optimize.
Further, I don't think we need timers for simple if/then statements - e.g. the below

        elif len(segmentation_points) == 0:
            with ect.Timer(ecwp.PipelineStages.TRIP_SEGMENTATION.name + "/early_return_no_segmentation") as timer_early_return_no_segmentation:
                # no new segments, no need to keep looking at these again
                logging.debug("len(segmentation_points) == 0, early return")
                epq.mark_segmentation_done(user_id, None)
            esds.store_pipeline_time(
                user_id,
                ecwp.PipelineStages.TRIP_SEGMENTATION.name + "/early_return_no_segmentation",
                time.time(),
                timer_early_return_no_segmentation.elapsed
            )

There are literally two statements within the timer in the code snippet above - a log statement and a mark_segmentation_done, neither of which are expected to be heavyweight.

I would:

1. look at the logs from running the single user intake,
2. correlate that to the trip segmentation codebase, and
3. add timers for the sections of code (within create_places_and_trips) that are taking the most time.

as a nice-to-have, can you also split commit into two:

• easy: one for adding instrumentation to the _get_and_store_range?
• more complex: one for adding instrumentation to trip_segmentation?

You can even create two PRs so I can merge the easy one while reviewing the more complex one.
Feel free to close this PR and create two new ones if that makes it easier!

[shankari]

@TeachMeTW is there an ETA for addressing my comments?
I see that you have split the commit, but I still don't see the "easy: one for adding instrumentation to the _get_and_store_range?" PR and you haven't addressed my comment around "I don't think that the trip segmentations stats are fine-grained enough." in this PR.

In particular, "easy: one for adding instrumentation to the _get_and_store_range?" is the main change that we want to get into production soon.

[TeachMeTW]

@TeachMeTW is there an ETA for addressing my comments? I see that you have split the commit, but I still don't see the "easy: one for adding instrumentation to the _get_and_store_range?" PR and you haven't addressed my comment around "I don't think that the trip segmentations stats are fine-grained enough." in this PR.

In particular, "easy: one for adding instrumentation to the _get_and_store_range?" is the main change that we want to get into production soon.

It is almost finished but I need to test it; is there a uuid in ca_ebike that has trips that are segmentable? How do I search for that? The tests I've done stops at:

    if len(loc_df) == 0:
        # no new segments, no need to keep looking at these again
        logging.debug("len(loc_df) == 0, early return")
        epq.mark_segmentation_done(user_id, None)
        return
        

because there are no new segments hence I cannot see if the fine grained timers are being called.

[shankari]

you can reset the pipeline using bin/reset_pipeline.py

[TeachMeTW]

@shankari I have added more timings, specifically for create_places_and_trips

[TeachMeTW]

@shankari ready for feedback; is this in depth timers enough; I also only noticed 3 things that take the most times; filter methods, create_places_and_trips, single/multi filter

[shankari]

@TeachMeTW no, this doesn't actually address my comments.

And you don't have any timers within create_places_and_trips, so you won't know where we are spending the time, and what we should try to optimize.

I miswrote; I would actually expect most of the time to be in segment_into_trips. I think that is what you found as well.

From #990 (comment)

I also only noticed 3 things that take the most times; filter methods, create_places_and_trips, single/multi filter

what are those times?

I would expect to see fine-grained instrumentation in segment_into_trips as well.

Note also that this has broken several tests.

As I said earlier, it looks like this will take some time to implement, so please move
#990 (comment)
to a separate PR

[TeachMeTW]

@shankari Addressed comments

[shankari]

@TeachMeTW tests are still failing

#990 (review)

Note also that this has broken several tests.

I am not going to review unless the tests are passing.

[shankari]

@JGreenlee since this is no longer the weekend, can you review this before it comes to me?

[TeachMeTW]

@JGreenlee Please review, tests are passing

[JGreenlee]

This looks pretty clean! We should be able to assess bottlenecks in segmentation; I think this will allow for even more granular instrumentation than I had in mind.

[TeachMeTW]

@shankari @JGreenlee and I discovered a confusing behavior with the filters. I tested with both an ios and android user -- but the main issue stems from the fact that both only use the distance filter, while the time filter is left unused. What are your thoughts? We are both stumped in regards to this. @JGreenlee can add more to this thread if I have not covered everything.

[shankari]

I tested with both an ios and android user -- but the main issue stems from the fact that both only use the distance filter, while the time filter is left unused.

I would like to see proof of this. Please use <details> to avoid a wall of text and strip out any identifying information before posting

[JGreenlee]

There is no bug. We were testing against 2 iOS users when we thought it was 1 Android and 1 iOS user.
I was correct that the reason @TeachMeTW wasn't seeing the time filter be used is because he was testing a user on one platform and needed to test the other platform. However, I mixed it up and thought android -> distance and ios -> time, when it is actually the opposite.
After choosing an Android user, @TeachMeTW was indeed able to see readings from the time filter.

[TeachMeTW]

@JGreenlee Please review the two changes. I do not believe the failing ubuntu test has anything to do with the changes I made.

[JGreenlee]

Noted that tests are passing but workflow fails due to e-mission/e-mission-docs#1097

[TeachMeTW]

@JGreenlee please re review

[JGreenlee]

I think this is fine to merge.
Some of these Timer blocks might still be overkill, but it's not easy to tell without digging into every function called. We can always remove some later after assessing on prod and seeing what is and isn't a bottleneck.
At this stage, better too granular than not granular enough

[shankari]

I agree with @JGreenlee that more fine-grained is better than less, but I also want to point out that there is a cost to storing a lot of stats in terms of database usage. This is particularly true for the pipeline stats which are generated ~ every hour, as opposed to the admin dashboard stats, which are only generated when the admin user logs in to the dashboard.

I can deploy this to staging, but we should use the staging results to strip out the bottom 89-90% of stats before we move to production (even the limited 3 environment production). We can add them back if we resolve all the issues with the top 10-20% of readings!

In particular, I do not anticipate that any of the stats below 👇 will be relevant. They are literally just creating python objects.

[shankari]

creating a python object

[shankari]

simple database query

[shankari]

created python object

[shankari]

created python object