Open daverigby opened 4 months ago
jonathanzxu
commented
4 months ago Can't reproduce, but error seems to have something to do with running queries in a gevent child process (e.g. Locust User) (see https://groups.google.com/a/lists.datastax.com/g/python-driver-user/c/XVicwbCxtiM). How frequently does this happen? @brickj
daverigby
commented
3 months ago I just got a reproduction of this.
vsb --database=pinecone --workload=mnist-test --pinecone_api_key=XXXXOuput:
2024-08-06T11:36:09 INFO Vector Search Bench: Starting experiment with backend='pinecone', workload='mnist-test', users=1, requests_per_sec=unlimited
2024-08-06T11:36:09 INFO Writing benchmark results to 'reports/pinecone/2024-08-06T11:36:09'
2024-08-06T11:36:09 INFO Starting Setup phase
/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/google_crc32c/__init__.py:29: RuntimeWarning: As the c extension couldn't be imported, `google-crc32c` is using a pure python implementation that is significantly slower. If
possible, please configure a c build environment and compile the extension
warnings.warn(_SLOW_CRC32C_WARNING, RuntimeWarning)
2024-08-06T11:36:23 INFO Workload 'mnist-test' initialized record_count=600 dimensions=784 metric=DistanceMetric.Euclidean
2024-08-06T11:36:23 INFO PineconeDB: Specified index 'vsb-mnist-test' was not found, or the specified API key cannot access it. Creating new index 'vsb-mnist-test'.
✔ Setup complete 1/1 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:20 00:00
✔ Dataset download complete 3/3 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:03 00:00
2024-08-06T11:36:29 INFO Completed Setup phase, took 20.50s
2024-08-06T11:36:31 INFO Starting Populate phase
✔ Populate complete 600/600 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:04 00:00
Records/sec: 147.5
2024-08-06T11:36:35 INFO Completed Populate phase, took 4.09s
2024-08-06T11:36:37 INFO Starting Finalize phase
✔ Finalize complete 1/? ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 0:00:00
✔ Finalize population 600/600 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:00 00:00
2024-08-06T11:36:37 INFO Completed Finalize phase, took 0.15s
2024-08-06T11:36:39 INFO Starting Run phase
✔ Run complete 20/20 ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 100% 0:00:02 00:00
Current metrics (last 10s): 0.0 op/s | latency: p50=100ms, p95=110.0ms | recall: p50=1.00, p5=1.00
2024-08-06T11:36:41 INFO Completed Run phase, took 2.14s
Operation Summary
Operation Requests Failures Requests/sec Failures/sec
───────────────────────────────────────────────────────────
Populate 2 0(0%) 0 0.0
Search 20 0(0%) 1 0.0
Metrics Summary
Operation Metric Min 0.1% 1% 5% 10% 25% 50% 75% 90% 95% 99% 99.9% 99.99% Max Mean
──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
Populate Latency (ms) 311 310 310 310 310 310 3100 3100 3100 3100 3100 3100 3100 3083 1697
Search Latency (ms) 99 99 99 100 100 100 100 100 130 140 140 140 140 142 105
Search Recall 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 1.00 2024-08-06T11:36:42 INFO Saved stats to 'reports/pinecone/2024-08-06T11:36:09/stats.json'
Traceback (most recent call last):
File "/opt/homebrew/Cellar/python@3.12/3.12.4/Frameworks/Python.framework/Versions/3.12/lib/python3.12/weakref.py", line 666, in _exitfunc
f()
File "/opt/homebrew/Cellar/python@3.12/3.12.4/Frameworks/Python.framework/Versions/3.12/lib/python3.12/weakref.py", line 590, in call
return info.func(*info.args, **(info.kwargs or {}))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/urllib3/connectionpool.py", line 1180, in _close_pool_connections
conn.close()
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/urllib3/connection.py", line 275, in close
super().close()
File "/opt/homebrew/Cellar/python@3.12/3.12.4/Frameworks/Python.framework/Versions/3.12/lib/python3.12/http/client.py", line 1020, in close
sock.close() # close it manually... there may be other refs
^^^^^^^^^^^^
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/gevent/_socket3.py", line 331, in close
self._real_close()
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/gevent/ssl.py", line 717, in _real_close
socket._real_close(self)
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/gevent/_socket3.py", line 324, in _real_close
self._detach_socket('closed')
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/gevent/_socket3.py", line 315, in _detach_socket
self._drop_events_and_close(closefd=(reason == 'closed'))
File "/Users/dave/repos/pinecone-io/VSB/.venv/lib/python3.12/site-packages/gevent/_socketcommon.py", line 466, in _drop_events_and_close
hub.cancel_waits_close_and_then(
File "src/gevent/_hub_primitives.py", line 75, in gevent._gevent_c_hub_primitives.WaitOperationsGreenlet.cancel_waits_close_and_then
File "src/gevent/libev/corecext.pyx", line 1059, in gevent.libev.corecext.watcher.close
File "src/gevent/libev/corecext.pyx", line 1015, in gevent.libev.corecext.watcher.stop
File "src/gevent/libev/corecext.pyx", line 280, in gevent.libev.corecext._check_loop
ValueError: operation on destroyed loop
However, running the exact same command again _didn't_ fail, so this is an intermittent issue.
Is this a new bug?
Current Behavior
When running vsb workload mnist-test against pinecone on macOS using python3.12, an exception was thrown at the end of the run (after summary stats were printed).
Expected Behavior
A clean shutdown occurs
Steps To Reproduce
Relevant log output