edgedb
Response time issue
I am connecting to EdgeDB-SERVER in a GCP VM, using FASTAPI, code is given below API code file and edgedb.toml are already in the same directory.
conn = edgedb.create_async_client()
app = FastAPI()
@app.get("/add_data")
async def adddata (data : dict):
logging.info(f"-----------TIME --------------- {datetime.now()}")
st = datetime.now()
var = await ( conn.query_json(INSERT QUERY)
logging.info("Query exec time: {}".format(datetime.now()-st))
return eval(var)
@app.get("/get_single_data/{img_id}")
async def get_single_data(img_id:str):
logging.info(f"-----------TIME st --------------- {datetime.now()}")
st = datetime.now()
var = await ( conn.query_json(SELECT query)
logging.info("Query exec time: {}".format(datetime.now()-st))
return eval(var)
I am sending 20 requests using async + aiohttp.clientSession from different VM. All requests are entered to api_function asynchronously but fetching from DB happens sequentially and the query exec time keeps on increasing.
while sending requests to /add_data, requests are going to FASTAPI concurrently
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.887357
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.888552
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.889711
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.890296
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.890883
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.891310
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.891754
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.892140
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.892500
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.892883
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.893255
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.893613
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.894031
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.894564
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.895049
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.895480
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.895916
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.896332
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.896777
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.897791
INFO:root:-----------TIME --------------- 2022-01-25 07:47:48.898413
INFO:root:Query exec time: 0:00:00.011458
INFO: 10.56.3.98:57708 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.011933
INFO: 10.56.3.98:57736 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.013192
INFO: 10.56.3.98:57734 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.018139
INFO: 10.56.3.98:57712 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.020113
INFO: 10.56.3.98:57716 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.023454
INFO: 10.56.3.98:57718 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.017702
INFO: 10.56.3.98:57742 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.020796
INFO: 10.56.3.98:57714 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.022909
INFO: 10.56.3.98:57722 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.017524
INFO: 10.56.3.98:57744 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.018848
INFO: 10.56.3.98:57732 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.025497
INFO: 10.56.3.98:57724 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.022834
INFO: 10.56.3.98:57710 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.024485
INFO: 10.56.3.98:57720 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.020375
INFO: 10.56.3.98:57740 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.021983
INFO: 10.56.3.98:57738 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.025868
INFO: 10.56.3.98:57726 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.024466
INFO: 10.56.3.98:57728 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.025383
INFO: 10.56.3.98:57730 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.021126
INFO: 10.56.3.98:57746 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.022242
while sending requests to /get_single_data, requests are entering to API concurrently...
INFO:root:-----time st -------------2022-01-25 07:48:44.223958
INFO:root:-----time st -------------2022-01-25 07:48:44.225382
INFO:root:-----time st -------------2022-01-25 07:48:44.225925
INFO:root:-----time st -------------2022-01-25 07:48:44.226363
INFO:root:-----time st -------------2022-01-25 07:48:44.226710
INFO:root:-----time st -------------2022-01-25 07:48:44.227059
INFO:root:-----time st -------------2022-01-25 07:48:44.227408
INFO:root:-----time st -------------2022-01-25 07:48:44.227738
INFO:root:-----time st -------------2022-01-25 07:48:44.228052
INFO:root:-----time st -------------2022-01-25 07:48:44.228346
INFO:root:-----time st -------------2022-01-25 07:48:44.228631
INFO:root:-----time st -------------2022-01-25 07:48:44.228911
INFO:root:-----time st -------------2022-01-25 07:48:44.230125
INFO:root:-----time st -------------2022-01-25 07:48:44.230465
INFO:root:-----time st -------------2022-01-25 07:48:44.230788
INFO:root:-----time st -------------2022-01-25 07:48:44.231142
INFO:root:-----time st -------------2022-01-25 07:48:44.231471
INFO:root:-----time st -------------2022-01-25 07:48:44.231831
INFO:root:-----time st -------------2022-01-25 07:48:44.232150
INFO:root:-----time st -------------2022-01-25 07:48:44.232625
INFO:root:-----time st -------------2022-01-25 07:48:44.233109
INFO:root:Query exec time: 0:00:00.043368
INFO: 10.56.3.98:58302 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.082232
INFO: 10.56.3.98:58292 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.115055
INFO: 10.56.3.98:58298 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.148064
INFO: 10.56.3.98:58300 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.209334
INFO: 10.56.3.98:58306 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.238325
INFO: 10.56.3.98:58288 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.262985
INFO: 10.56.3.98:58296 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.292190
INFO: 10.56.3.98:58286 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.324947
INFO: 10.56.3.98:58284 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.347185
INFO: 10.56.3.98:58290 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.372092
INFO: 10.56.3.98:58294 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.400004
INFO: 10.56.3.98:58308 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.422483
INFO: 10.56.3.98:58318 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.450572
INFO: 10.56.3.98:58310 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.480537
INFO: 10.56.3.98:58320 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.506605
INFO: 10.56.3.98:58312 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.532549
INFO: 10.56.3.98:58322 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.564470
INFO: 10.56.3.98:58324 - "GET /get_single_data/rear_1632383205 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.594593
INFO: 10.56.3.98:58316 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.628099
INFO: 10.56.3.98:58304 - "GET /get_single_data/front_1632382854 HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.658299
INFO: 10.56.3.98:58314 - "GET /get_single_data/hood_1632382967 HTTP/1.1" 200 OK
The main thing which I worried about is the Query exec time: 0:00:00.658299, it's increasing continuously and I am not able to understand when I send the requests, again and again, Query exec time is increasing. At the initial stage, the Query exec time was roughly 2-3 ms for a single request using postman. in \add_data response >> Query_exec_time is not increasing sequentially
INFO:root:Query exec time: 0:00:00.025868
INFO: 10.56.3.98:57726 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.024466
INFO: 10.56.3.98:57728 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.025383
INFO: 10.56.3.98:57730 - "POST /add_data HTTP/1.1" 200 OK
INFO:root:Query exec time: 0:00:00.021126
But in the case of \get_single_data , its increasing sequentially and too large, which I am not able to understand While sending requests, I was expecting that 20 requests will go concurrently, (which is happening) and Query_exec_time should be roughly 2-3 ms for each request. (Correct me here if I am wrong). Need help here
@fantix
An increasing query time within a group of concurrent requests usually means you have some shared resources that serialized your requests. If another group of requests (/add_data) doesn't have the same symptom, it likely means the shared resource is not in edgedb-python itself. In this case, looking at the SELECT query of /get_single_data would be helpful, probably with the server debug logging on.
Another hint for testing this kind of timing issues is that, you probably want to pre-heat both the client and the server before running the actual test. Because both the edgedb-python client and the EdgeDB server has a connection pool, sending a bunch of requests concurrently and waiting for a few seconds would allow the pool to be ready for the test. Also, manually send a few requests separately to see the query time without a heavy load.
By the way, I think 0:00:00.025868 is 25 ms, instead of 2 ms.
Code
async def get_single_data_from_img_id(img_id:str):
st = datetime.now()
var = await ( conn.query_json("SELECT region_damage {image_id, output_version, raw_panel_name_from_id, clean_panel_name_from_id, aggregated_results, thresholds} \
FILTER .image_id = <str>$image_id" , image_id=img_id))
logging.info("Query exec time: {}".format(datetime.now()-st))
return json.loads(var)
aggregated results & thresholds are JSON. Sending a few requests separately gives a rough time of 3-4 ms. Query exec time: 0:00:00.003508 in case of add_data, in case of get_single_data, it's around 2-3 ms 0:00:00.002528 which suddenly jumps to ~25-30 ms while sending requests asynchronously.
So I was expecting every query_exec_time ~ 3-4 ms while sending 20 requests asynchronously.
How to check for shared resources serializing my requests. ( CPU usage roughly remains at 5-10 %, MEM ~ 4G/15.6G )
Also, need info on server debug logging and connection pool. https://lu.ma/edgedb Registered :+1: )
How to check for shared resources serializing my requests.
Hmm, this query doesn't seems to be holding any lock that may cause the issue. At this moment I have no clue but trying to reproduce locally first.
Also, need info on server debug logging and connection pool.
Depending on the way you start your server, you could either set the server command option --log-level to debug, or use the environment variable EDGEDB_SERVER_LOG_LEVEL. There're also a bunch of debug options that can be enabled through environment variables, but it's usually too verbose unless you're really trying to debug the EdgeDB server itself.
https://lu.ma/edgedb Registered 👍 )
Welcome to the party!