Skip to content

Commit ec2ace7

Browse files
boekerboeker
authored
Merge pull request #36955 from vespa-engine/boeker/ann-time-stats-in-query-setup-stats
Collect time-related ANN stats in QuerySetupStats
2 parents 7cb9741 + f413ecb commit ec2ace7

4 files changed

Lines changed: 100 additions & 9 deletions

File tree

‎searchlib/src/tests/attribute/tensorattribute/tensorattribute_test.cpp‎

Lines changed: 60 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@
3232
#include <vespa/vespalib/data/fileheader.h>
3333
#include <vespa/vespalib/gtest/gtest.h>
3434
#include <vespa/vespalib/net/http/state_explorer.h>
35+
#include <vespa/vespalib/util/fake_deadline.h>
3536
#include <vespa/vespalib/util/mmap_file_allocator_factory.h>
3637
#include <vespa/vespalib/util/threadstackexecutor.h>
3738

@@ -300,6 +301,10 @@ class MockNearestNeighborIndex : public NearestNeighborIndex {
300301
std::vector<Neighbor> find_top_k(Stats& stats, uint32_t k, const search::tensor::BoundDistanceFunction& df,
301302
uint32_t explore_k, double exploration_slack, bool prefetch_tensors,
302303
const vespalib::Deadline& doom, double distance_threshold) const override {
304+
std::this_thread::sleep_for(1ms); // Make sure that test does not fail because it ran too fast
305+
if (doom.is_missed()) {
306+
return {};
307+
}
303308
stats.count_computed_distance();
304309
stats.count_visited_node();
305310
stats.count_visited_node();
@@ -308,7 +313,6 @@ class MockNearestNeighborIndex : public NearestNeighborIndex {
308313
(void)explore_k;
309314
(void)exploration_slack;
310315
(void)prefetch_tensors;
311-
(void)doom;
312316
(void)distance_threshold;
313317
return {};
314318
}
@@ -318,6 +322,10 @@ class MockNearestNeighborIndex : public NearestNeighborIndex {
318322
uint32_t explore_k, double exploration_slack, bool prefetch_tensors,
319323
const vespalib::Deadline& doom,
320324
double distance_threshold) const override {
325+
std::this_thread::sleep_for(1ms); // Make sure that test does not fail because it ran too fast
326+
if (doom.is_missed()) {
327+
return {};
328+
}
321329
stats.count_computed_distance();
322330
stats.count_visited_node();
323331
stats.count_visited_node();
@@ -330,7 +338,6 @@ class MockNearestNeighborIndex : public NearestNeighborIndex {
330338
(void)filter;
331339
(void)low_hit_ratio;
332340
(void)exploration;
333-
(void)doom;
334341
(void)distance_threshold;
335342
return {};
336343
}
@@ -1538,6 +1545,9 @@ TEST(TensorAttributeTest, NN_blueprint_collects_stats) {
15381545
}
15391546
EXPECT_EQ(1, f.stats().approximate_nns_distances_computed());
15401547
EXPECT_EQ(2, f.stats().approximate_nns_nodes_visited());
1548+
EXPECT_GT(f.stats().approximate_nns_time_used(), vespalib::duration::zero());
1549+
EXPECT_EQ(0, f.stats().approximate_nns_timeouts_hit());
1550+
vespalib::duration last_approximate_nns_time_used = f.stats().approximate_nns_time_used();
15411551

15421552
// With filter active
15431553
{
@@ -1558,6 +1568,46 @@ TEST(TensorAttributeTest, NN_blueprint_collects_stats) {
15581568
}
15591569
EXPECT_EQ(2, f.stats().approximate_nns_distances_computed());
15601570
EXPECT_EQ(4, f.stats().approximate_nns_nodes_visited());
1571+
EXPECT_GT(f.stats().approximate_nns_time_used(), last_approximate_nns_time_used);
1572+
EXPECT_EQ(0, f.stats().approximate_nns_timeouts_hit());
1573+
last_approximate_nns_time_used = f.stats().approximate_nns_time_used();
1574+
1575+
// Using up time budget (but not hitting timeout)
1576+
{
1577+
auto bp = f.make_blueprint(true);
1578+
auto inactive_filter = GlobalFilter::create();
1579+
EXPECT_FALSE(bp->pending_index_search());
1580+
bp->set_global_filter(*inactive_filter, 0.6);
1581+
EXPECT_TRUE(bp->pending_index_search());
1582+
vespalib::FakeDeadline fake_deadline(-1s, vespalib::Deadline::Type::BUDGET);
1583+
bp->perform_index_search(fake_deadline.get_deadline(), f.stats());
1584+
EXPECT_FALSE(bp->pending_index_search());
1585+
}
1586+
EXPECT_EQ(2, f.stats().approximate_nns_distances_computed());
1587+
EXPECT_EQ(4, f.stats().approximate_nns_nodes_visited());
1588+
EXPECT_GT(f.stats().approximate_nns_time_used(), last_approximate_nns_time_used);
1589+
EXPECT_EQ(0, f.stats().approximate_nns_timeouts_hit());
1590+
last_approximate_nns_time_used = f.stats().approximate_nns_time_used();
1591+
1592+
// Hitting timeout
1593+
{
1594+
auto bp = f.make_blueprint(true);
1595+
auto inactive_filter = GlobalFilter::create();
1596+
EXPECT_FALSE(bp->pending_index_search());
1597+
bp->set_global_filter(*inactive_filter, 0.6);
1598+
EXPECT_TRUE(bp->pending_index_search());
1599+
vespalib::FakeDeadline fake_deadline(-1s, vespalib::Deadline::Type::TIMEOUT);
1600+
bp->perform_index_search(fake_deadline.get_deadline(), f.stats());
1601+
EXPECT_FALSE(bp->pending_index_search());
1602+
}
1603+
EXPECT_EQ(2, f.stats().approximate_nns_distances_computed());
1604+
EXPECT_EQ(4, f.stats().approximate_nns_nodes_visited());
1605+
EXPECT_GT(f.stats().approximate_nns_time_used(), last_approximate_nns_time_used);
1606+
EXPECT_EQ(1, f.stats().approximate_nns_timeouts_hit());
1607+
size_t last_approximate_nns_distances_computed = f.stats().approximate_nns_distances_computed();
1608+
size_t last_approximate_nns_nodes_visited = f.stats().approximate_nns_nodes_visited();
1609+
last_approximate_nns_time_used = f.stats().approximate_nns_time_used();
1610+
size_t last_approximate_nns_timeouts_hit = f.stats().approximate_nns_timeouts_hit();
15611611

15621612
// Hitting fallback
15631613
{
@@ -1570,8 +1620,10 @@ TEST(TensorAttributeTest, NN_blueprint_collects_stats) {
15701620
bp->set_global_filter(*strong_filter, 0.6);
15711621
EXPECT_FALSE(bp->pending_index_search());
15721622
}
1573-
EXPECT_EQ(2, f.stats().approximate_nns_distances_computed());
1574-
EXPECT_EQ(4, f.stats().approximate_nns_nodes_visited());
1623+
EXPECT_EQ(last_approximate_nns_distances_computed, f.stats().approximate_nns_distances_computed());
1624+
EXPECT_EQ(last_approximate_nns_nodes_visited, f.stats().approximate_nns_nodes_visited());
1625+
EXPECT_EQ(last_approximate_nns_time_used, f.stats().approximate_nns_time_used());
1626+
EXPECT_EQ(last_approximate_nns_timeouts_hit, f.stats().approximate_nns_timeouts_hit());
15751627

15761628
// Using exact search in the first place
15771629
{
@@ -1581,8 +1633,10 @@ TEST(TensorAttributeTest, NN_blueprint_collects_stats) {
15811633
bp->set_global_filter(*inactive_filter, 0.6);
15821634
EXPECT_FALSE(bp->pending_index_search());
15831635
}
1584-
EXPECT_EQ(2, f.stats().approximate_nns_distances_computed());
1585-
EXPECT_EQ(4, f.stats().approximate_nns_nodes_visited());
1636+
EXPECT_EQ(last_approximate_nns_distances_computed, f.stats().approximate_nns_distances_computed());
1637+
EXPECT_EQ(last_approximate_nns_nodes_visited, f.stats().approximate_nns_nodes_visited());
1638+
EXPECT_EQ(last_approximate_nns_time_used, f.stats().approximate_nns_time_used());
1639+
EXPECT_EQ(last_approximate_nns_timeouts_hit, f.stats().approximate_nns_timeouts_hit());
15861640
}
15871641

15881642
auto test_values = ::testing::Values(1u, 2u);

‎searchlib/src/tests/queryeval/queryeval_test.cpp‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -893,6 +893,24 @@ TEST(QueryEvalTest, test_setup_stats) {
893893
EXPECT_EQ(2u, stats.approximate_nns_nodes_visited());
894894
stats.add_to_approximate_nns_nodes_visited(2u);
895895
EXPECT_EQ(4u, stats.approximate_nns_nodes_visited());
896+
897+
EXPECT_EQ(vespalib::duration::zero(), stats.approximate_nns_time_used());
898+
stats.add_to_approximate_nns_time_used(vespalib::duration(1234));
899+
EXPECT_EQ(vespalib::duration(1234), stats.approximate_nns_time_used());
900+
stats.add_to_approximate_nns_time_used(vespalib::duration(766));
901+
EXPECT_EQ(vespalib::duration(2000), stats.approximate_nns_time_used());
902+
903+
EXPECT_EQ(0u, stats.approximate_nns_timeouts_hit());
904+
stats.add_to_approximate_nns_timeouts_hit(1u);
905+
EXPECT_EQ(1u, stats.approximate_nns_timeouts_hit());
906+
stats.add_to_approximate_nns_timeouts_hit(2u);
907+
EXPECT_EQ(3u, stats.approximate_nns_timeouts_hit());
908+
909+
// Make sure all stats are unchanged
910+
EXPECT_EQ(2u, stats.approximate_nns_distances_computed());
911+
EXPECT_EQ(4u, stats.approximate_nns_nodes_visited());
912+
EXPECT_EQ(vespalib::duration(2000), stats.approximate_nns_time_used());
913+
EXPECT_EQ(3u, stats.approximate_nns_timeouts_hit());
896914
}
897915

898916
GTEST_MAIN_RUN_ALL_TESTS()

‎searchlib/src/vespa/searchlib/queryeval/nearest_neighbor_blueprint.cpp‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,9 @@ NearestNeighborBlueprint::AnnStats::AnnStats()
6262
void NearestNeighborBlueprint::AnnStats::flush(search::queryeval::QuerySetupStats& setup_stats) const {
6363
setup_stats.add_to_approximate_nns_distances_computed(index_stats.distances_computed());
6464
setup_stats.add_to_approximate_nns_nodes_visited(index_stats.nodes_visited());
65+
66+
setup_stats.add_to_approximate_nns_time_used(time_used);
67+
setup_stats.add_to_approximate_nns_timeouts_hit(timeout_hit);
6568
}
6669

6770
void NearestNeighborBlueprint::AnnStats::visit(vespalib::ObjectVisitor& visitor) const {

‎searchlib/src/vespa/searchlib/queryeval/queryeval_stats.h‎

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@
22

33
#pragma once
44

5+
#include <vespa/vespalib/util/time.h>
6+
57
#include <atomic>
68
#include <memory>
79

@@ -13,11 +15,17 @@ namespace search::queryeval {
1315
**/
1416
class QuerySetupStats {
1517
private:
16-
size_t _approximate_nns_distances_computed;
17-
size_t _approximate_nns_nodes_visited;
18+
size_t _approximate_nns_distances_computed;
19+
size_t _approximate_nns_nodes_visited;
20+
vespalib::duration _approximate_nns_time_used;
21+
size_t _approximate_nns_timeouts_hit;
1822

1923
public:
20-
QuerySetupStats() noexcept : _approximate_nns_distances_computed(0), _approximate_nns_nodes_visited(0) {}
24+
QuerySetupStats() noexcept
25+
: _approximate_nns_distances_computed(0),
26+
_approximate_nns_nodes_visited(0),
27+
_approximate_nns_time_used(vespalib::duration::zero()),
28+
_approximate_nns_timeouts_hit(0) {}
2129

2230
size_t approximate_nns_distances_computed() const noexcept { return _approximate_nns_distances_computed; }
2331
void add_to_approximate_nns_distances_computed(size_t value) noexcept {
@@ -26,6 +34,14 @@ class QuerySetupStats {
2634

2735
size_t approximate_nns_nodes_visited() const noexcept { return _approximate_nns_nodes_visited; }
2836
void add_to_approximate_nns_nodes_visited(size_t value) noexcept { _approximate_nns_nodes_visited += value; }
37+
38+
vespalib::duration approximate_nns_time_used() const noexcept { return _approximate_nns_time_used; }
39+
void add_to_approximate_nns_time_used(vespalib::duration ann_time) noexcept {
40+
_approximate_nns_time_used += ann_time;
41+
}
42+
43+
size_t approximate_nns_timeouts_hit() const noexcept { return _approximate_nns_timeouts_hit; }
44+
void add_to_approximate_nns_timeouts_hit(size_t value) noexcept { _approximate_nns_timeouts_hit += value; }
2945
};
3046

3147
/**

0 commit comments

Comments
 (0)