Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(search): FT.PROFILE #1787

Merged
merged 2 commits into from
Sep 3, 2023
Merged

Conversation

dranikpg
Copy link
Contributor

@dranikpg dranikpg commented Sep 2, 2023

Adds FT.PROFILE commands that runs the search query with profiling to see a detailed execution plan with timings. Does not comply with RS's FtProfile.

Example output for a simple query. First, it prints general results, then the detailed execution plan for each shard

image

@dranikpg dranikpg changed the title feat(search): Profiling feat(search): FT.PROFILE Sep 2, 2023
@dranikpg dranikpg force-pushed the search-profile branch 2 times, most recently from 4683e17 to 1c53e74 Compare September 2, 2023 10:29
Signed-off-by: Vladislav Oleshko <vlad@dragonflydb.io>
@dranikpg dranikpg marked this pull request as ready for review September 2, 2023 12:03
@dranikpg
Copy link
Contributor Author

dranikpg commented Sep 2, 2023

I know we can compute more helpful metrics, but for now I'd like to output just the raw data

Everything (like non-leaf node overhead) can be calculated on top of that

chakaz
chakaz previously approved these changes Sep 3, 2023
Copy link
Collaborator

@chakaz chakaz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice!

struct AlgorithmProfile {
struct ProfileEvent {
std::string descr;
size_t micros; // time event took in microseconds
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Consider using absl::Duration or the std equivalent

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was using absl::Now() first and its not monotonic. I actually detected it just by checking the results visually 😆 So I switched to chrono's steady clock.

I think the micros is fine. I don't see what the benefit is of using a scaringly long chrono type is if I just count the number of microseconds at the end

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What do you mean by non-monotonic? It represents a moment in time, regardless of timezones, and should never go back / forward in time
https://github.com/abseil/abseil-cpp/blob/fc44fa053cc91193d2bb60fb9356bcecb301242e/absl/time/time.h#L751-L752

Generally, I dislike having the units as a convention instead of part of the type, as it's error prone. Your call as always.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

absl::Now queries the system clock which is not monotonic, that's why I switched to chrono (and converting chrono timepoint to asbl duration isn't that nice as well)

abseil/abseil-cpp#172 (comment)

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it can go back in time since it uses a real clock. It's better using steady/monotonic clocks when measuring latency.
+1 to @dranikpg preference to simplicity over standard. if to count microseconds I need to write:
std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - start).count()
then maybe it's the standard committee that should do a better job.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I didn't think of the case of the system changing time (I did think of daylight saving time changes, but that should be OK with absl::Now).
Anyway, I would use std::chrono::microseconds but I realize I'm in the minority. I saw so many bugs caused by bad unit conversions, some costlier than others. Sure, the type is verbose, but there are std typedefs to assist, and we can create one ourselves.
And.. in any case we need to write the long statement above (since absl::Now() is non monotonic), it's just a matter of storing a raw integer type vs a type-safe one
Having written that, @dranikpg you decide :)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We're not sending spaceships to Mars, we're debugging profiling queries 😆

Its has nothing to do with dates. The system clock is non monotonic on a microsecond level and jumps around a little. Because its implemented by some low level device / caches values / corrects itself 🤷🏻‍♂️

Copy link
Contributor

@kostasrim kostasrim Sep 4, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We're not sending spaceships to Mars, we're debugging profiling queries 😆

Not yet. SpaceFly on the way to Mars 🚀

src/core/search/search.h Outdated Show resolved Hide resolved
src/core/search/search.cc Outdated Show resolved Hide resolved
Signed-off-by: Vladislav Oleshko <vlad@dragonflydb.io>
@dranikpg dranikpg merged commit 5af6169 into dragonflydb:main Sep 3, 2023
7 checks passed
@dranikpg dranikpg deleted the search-profile branch September 15, 2023 06:37
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants