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

Instrumentalize code to measure latency and QPS (and save results) #2266

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

cadurosar
Copy link
Collaborator

Here’s a pull request to add instrumentation to anserini and try to make latency/qps measuring standardized and a part of the retrieval. It basically stores the retrieval latencies and then computes average, median and p99 latency and stores in a file. Note that these are “best effort” latencies as you get the result before it is pretreated by Lucene in order to make it readable, but they are not exactly the server latency (imagine a server running Lucene and you are outside of it, it would be the latency including packet traffic but not result parsing).

Testing with arguana based on: https://github.com/cadurosar/anserini/blob/instrumentalize/docs/regressions/regressions-beir-v1.0.0-arguana-splade-distil-cocodenser-medium.md:

Without instrumentation:

2023-11-21 12:17:47,728 INFO  [main] search.SearchCollection (SearchCollection.java:1047) - Index: indexes/lucene-index.beir-v1.0.0-arguana-splade_distil_cocodenser_medium
2023-11-21 12:17:48,262 INFO  [main] search.SearchCollection (SearchCollection.java:1051) - Fields: []
2023-11-21 12:17:50,213 INFO  [main] search.SearchCollection (SearchCollection.java:1323) - runtag: Anserini
2023-11-21 12:17:50,217 INFO  [main] search.SearchCollection (SearchCollection.java:1329) - ============ Launching Search Threads ============
2023-11-21 12:17:53,109 INFO  [pool-3-thread-7] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 100 queries processed
2023-11-21 12:17:54,193 INFO  [pool-3-thread-7] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 200 queries processed
2023-11-21 12:17:55,097 INFO  [pool-3-thread-2] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 300 queries processed
2023-11-21 12:17:56,318 INFO  [pool-3-thread-6] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 400 queries processed
2023-11-21 12:17:57,709 INFO  [pool-3-thread-6] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 500 queries processed
2023-11-21 12:17:58,788 INFO  [pool-3-thread-3] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 600 queries processed
2023-11-21 12:18:00,063 INFO  [pool-3-thread-8] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 700 queries processed
2023-11-21 12:18:01,347 INFO  [pool-3-thread-1] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 800 queries processed
2023-11-21 12:18:02,586 INFO  [pool-3-thread-6] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 900 queries processed
2023-11-21 12:18:03,885 INFO  [pool-3-thread-2] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1000 queries processed
2023-11-21 12:18:05,262 INFO  [pool-3-thread-2] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1100 queries processed
2023-11-21 12:18:06,397 INFO  [pool-3-thread-1] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1200 queries processed
2023-11-21 12:18:07,443 INFO  [pool-3-thread-5] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1300 queries processed
2023-11-21 12:18:08,493 INFO  [pool-3-thread-7] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1400 queries processed
2023-11-21 12:18:08,620 INFO  [pool-2-thread-1] search.SearchCollection$SearcherThread (SearchCollection.java:977) - ranker: impact(), reranker: default: 1406 queries processed in 00:00:18 = ~76.68 q/s
2023-11-21 12:18:09,583 INFO  [main] search.SearchCollection (SearchCollection.java:1535) - Total run time: 00:00:21

Only information on QPS, need to read logs to get it.

With instrumentation:

2023-11-21 12:27:03,280 INFO  [main] search.SearchCollection (SearchCollection.java:1043) - Index: indexes/lucene-index.beir-v1.0.0-arguana-splade_distil_cocodenser_medium
2023-11-21 12:27:03,800 INFO  [main] search.SearchCollection (SearchCollection.java:1047) - Fields: []
2023-11-21 12:27:05,715 INFO  [main] search.SearchCollection (SearchCollection.java:1319) - runtag: Anserini
2023-11-21 12:27:05,718 INFO  [main] search.SearchCollection (SearchCollection.java:1325) - ============ Launching Search Threads ============
2023-11-21 12:27:08,950 INFO  [pool-3-thread-4] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 100 queries processed
2023-11-21 12:27:09,867 INFO  [pool-3-thread-8] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 200 queries processed
2023-11-21 12:27:10,796 INFO  [pool-3-thread-2] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 300 queries processed
2023-11-21 12:27:11,951 INFO  [pool-3-thread-1] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 400 queries processed
2023-11-21 12:27:13,233 INFO  [pool-3-thread-7] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 500 queries processed
2023-11-21 12:27:14,243 INFO  [pool-3-thread-7] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 600 queries processed
2023-11-21 12:27:15,190 INFO  [pool-3-thread-4] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 700 queries processed
2023-11-21 12:27:16,183 INFO  [pool-3-thread-5] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 800 queries processed
2023-11-21 12:27:17,108 INFO  [pool-3-thread-1] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 900 queries processed
2023-11-21 12:27:18,212 INFO  [pool-3-thread-3] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1000 queries processed
2023-11-21 12:27:19,366 INFO  [pool-3-thread-2] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1100 queries processed
2023-11-21 12:27:20,358 INFO  [pool-3-thread-6] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1200 queries processed
2023-11-21 12:27:21,376 INFO  [pool-3-thread-3] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1300 queries processed
2023-11-21 12:27:22,371 INFO  [pool-3-thread-3] search.SearchCollection$SearcherThread (SearchCollection.java:930) - ranker: impact(), reranker: default: 1400 queries processed
2023-11-21 12:27:22,518 INFO  [pool-2-thread-1] search.SearchCollection$SearcherThread (SearchCollection.java:962) - ranker: impact(), reranker: default: 1406 queries processed in 00:00:16 = ~84.16 q/s with average latency: 87.45 ms with median latency: 71.00 ms and p99 latency: 369.00 ms
2023-11-21 12:27:23,757 INFO  [main] search.SearchCollection (SearchCollection.java:1531) - Total run time: 00:00:20

Has latency information and creates a file which is the run name + _Efficiency. On this example "runs/run.beir-v1.0.0-arguana-splade_distil_cocodenser_medium.splade_distil_cocodenser_medium.topics.beir-v1.0.0-arguana.test.splade_distil_cocodenser_medium.txt_Efficiency"

QPS: 84.1613791452173
Mean latency: 87.4452347083926
Median latency: 71.0
P99 latency: 369.0

This is just a first version, tell me what you think @lintool @ArthurChen189

Copy link

codecov bot commented Nov 21, 2023

Codecov Report

Attention: 44 lines in your changes are missing coverage. Please review.

Comparison is base (6369184) 61.67% compared to head (079f060) 61.45%.
Report is 1 commits behind head on master.

Files Patch % Lines
...main/java/io/anserini/search/SearchCollection.java 12.00% 42 Missing and 2 partials ⚠️
Additional details and impacted files
@@             Coverage Diff              @@
##             master    #2266      +/-   ##
============================================
- Coverage     61.67%   61.45%   -0.23%     
  Complexity     1244     1244              
============================================
  Files           196      196              
  Lines         11554    11601      +47     
  Branches       1490     1494       +4     
============================================
+ Hits           7126     7129       +3     
- Misses         3889     3931      +42     
- Partials        539      541       +2     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@ArthurChen189
Copy link
Member

Hi @cadurosar, thanks for the PR, this is very neat.

@@ -231,6 +283,10 @@ public static class Args {
@Option(name = "-arbitraryScoreTieBreak", usage = "Break score ties arbitrarily (not recommended)")
public boolean arbitraryScoreTieBreak = false;

@Option(name = "-instrumentalize", usage = "Add instrumentation to better report latency and QPS")
public boolean instrumentalize = false;

Copy link
Member

Choose a reason for hiding this comment

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

Suggested change

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.

2 participants